void
crm_enable_blackbox(int nsig)
{
if (blackbox_file_prefix == NULL) {
pid_t pid = getpid();
blackbox_file_prefix = malloc(NAME_MAX);
snprintf(blackbox_file_prefix, NAME_MAX, "%s/%s-%d", CRM_BLACKBOX_DIR, crm_system_name,
pid);
}
if (qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_STATE_GET, 0) != QB_LOG_STATE_ENABLED) {
qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_SIZE, 5 * 1024 * 1024); /* Any size change drops existing entries */
qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_ENABLED, QB_TRUE); /* Setting the size seems to disable it */
crm_notice("Initiated blackbox recorder: %s", blackbox_file_prefix);
/* Save to disk on abnormal termination */
crm_signal(SIGSEGV, crm_trigger_blackbox);
crm_signal(SIGABRT, crm_trigger_blackbox);
crm_signal(SIGILL, crm_trigger_blackbox);
crm_signal(SIGBUS, crm_trigger_blackbox);
crm_update_callsites();
blackbox_trigger = qb_log_custom_open(blackbox_logger, NULL, NULL, NULL);
qb_log_ctl(blackbox_trigger, QB_LOG_CONF_ENABLED, QB_TRUE);
crm_trace("Trigger: %d is %d %d", blackbox_trigger,
qb_log_ctl(blackbox_trigger, QB_LOG_CONF_STATE_GET, 0), QB_LOG_STATE_ENABLED);
crm_update_callsites();
}
}
END_TEST
#ifdef HAVE_PTHREAD_SETSCHEDPARAM
START_TEST(test_threaded_logging_bad_sched_params)
{
int32_t t;
int32_t rc;
qb_log_init("test", LOG_USER, LOG_EMERG);
qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_ENABLED, QB_FALSE);
t = qb_log_custom_open(_test_logger, NULL, NULL, NULL);
rc = qb_log_filter_ctl(t, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FILE, "*", LOG_INFO);
ck_assert_int_eq(rc, 0);
qb_log_format_set(t, "%b");
rc = qb_log_ctl(t, QB_LOG_CONF_ENABLED, QB_TRUE);
ck_assert_int_eq(rc, 0);
rc = qb_log_ctl(t, QB_LOG_CONF_THREADED, QB_TRUE);
ck_assert_int_eq(rc, 0);
#if defined(SCHED_RR)
#define QB_SCHED SCHED_RR
#elif defined(SCHED_FIFO)
#define QB_SCHED SCHED_FIFO
#else
#define QB_SCHED (-1)
#endif
rc = qb_log_thread_priority_set(QB_SCHED, -1);
ck_assert_int_eq(rc, 0);
rc = qb_log_thread_start();
ck_assert_int_ne(rc, 0);
qb_log_fini();
}
END_TEST
#endif
START_TEST(test_extended_information)
{
int32_t t;
int32_t rc;
int extended;
qb_log_init("test", LOG_USER, LOG_DEBUG);
qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_ENABLED, QB_FALSE);
t = qb_log_custom_open(_test_logger, NULL, NULL, NULL);
_ck_assert_int(t, >, QB_LOG_STDOUT);
qb_log_format_set(t, "%b");
rc = qb_log_filter_fn_set(NULL);
ck_assert_int_eq(rc, 0);
rc = qb_log_filter_ctl(t, QB_LOG_FILTER_CLEAR_ALL, QB_LOG_FILTER_FILE,
"*", LOG_TRACE);
ck_assert_int_eq(rc, 0);
rc = qb_log_filter_ctl(t, QB_LOG_FILTER_CLEAR_ALL, QB_LOG_FILTER_FORMAT,
"*", LOG_TRACE);
ck_assert_int_eq(rc, 0);
rc = qb_log_filter_ctl(t, QB_LOG_FILTER_ADD, QB_LOG_FILTER_FORMAT,
"*", LOG_TRACE);
ck_assert_int_eq(rc, 0);
rc = qb_log_ctl(t, QB_LOG_CONF_ENABLED, QB_TRUE);
ck_assert_int_eq(rc, 0);
for (extended = QB_FALSE; extended <= QB_TRUE; ++extended) {
rc = qb_log_ctl(t, QB_LOG_CONF_EXTENDED, extended);
ck_assert_int_eq(rc, 0);
num_msgs = 0;
memset(test_buf, 0, sizeof(test_buf));
qb_log(LOG_ERR, "message with no extended information");
ck_assert_str_eq(test_buf, "message with no extended information");
memset(test_buf, 0, sizeof(test_buf));
qb_log(LOG_ERR, "message with empty extended information "QB_XS);
ck_assert_str_eq(test_buf, "message with empty extended information ");
memset(test_buf, 0, sizeof(test_buf));
qb_log(LOG_ERR, QB_XS" message with only extended information");
ck_assert_str_eq(test_buf, extended?
"| message with only extended information" : "");
memset(test_buf, 0, sizeof(test_buf));
qb_log(LOG_ERR, "message with extended information "QB_XS" (namely this)");
ck_assert_str_eq(test_buf, extended?
"message with extended information | (namely this)"
: "message with extended information ");
ck_assert_int_eq(num_msgs, (extended? 4 : 3));
}
qb_log_fini();
}
END_TEST
START_TEST(test_threaded_logging)
{
int32_t t;
int32_t rc;
qb_log_init("test", LOG_USER, LOG_EMERG);
qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_ENABLED, QB_FALSE);
t = qb_log_custom_open(_test_logger, NULL, NULL, NULL);
rc = qb_log_filter_ctl(t, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FILE, "*", LOG_INFO);
ck_assert_int_eq(rc, 0);
qb_log_format_set(t, "%b");
rc = qb_log_ctl(t, QB_LOG_CONF_ENABLED, QB_TRUE);
ck_assert_int_eq(rc, 0);
rc = qb_log_ctl(t, QB_LOG_CONF_THREADED, QB_TRUE);
ck_assert_int_eq(rc, 0);
qb_log_thread_start();
memset(test_buf, 0, sizeof(test_buf));
test_priority = 0;
num_msgs = 0;
qb_log(LOG_INFO, "Yoda how old are you? - %d", __LINE__);
qb_log(LOG_INFO, "Yoda how old are you? - %d", __LINE__);
qb_log(LOG_INFO, "Yoda how old are you? - %d", __LINE__);
qb_log(LOG_INFO, "Yoda how old are you? - %d", __LINE__);
qb_log(LOG_INFO, "Yoda how old are you? - %d", __LINE__);
qb_log(LOG_INFO, "Yoda how old are you? - %d", __LINE__);
qb_log(LOG_INFO, "Yoda how old are you? - %d", __LINE__);
qb_log(LOG_INFO, "Yoda how old are you? - %d", __LINE__);
qb_log(LOG_INFO, "Yoda how old are you? - %d", __LINE__);
qb_log(LOG_INFO, "Yoda how old are you? - %d", __LINE__);
qb_log_fini();
ck_assert_int_eq(num_msgs, 10);
}
END_TEST
START_TEST(test_log_enable)
{
int32_t t;
int32_t state;
qb_log_init("test", LOG_USER, LOG_DEBUG);
state = qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_STATE_GET, 0);
ck_assert_int_eq(state, QB_LOG_STATE_ENABLED);
state = qb_log_ctl(QB_LOG_STDERR, QB_LOG_CONF_STATE_GET, 0);
ck_assert_int_eq(state, QB_LOG_STATE_DISABLED);
state = qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_STATE_GET, 0);
ck_assert_int_eq(state, QB_LOG_STATE_DISABLED);
qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_ENABLED, QB_FALSE);
state = qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_STATE_GET, 0);
ck_assert_int_eq(state, QB_LOG_STATE_DISABLED);
t = qb_log_custom_open(_test_logger, NULL, NULL, NULL);
qb_log_ctl(t, QB_LOG_CONF_ENABLED, QB_TRUE);
qb_log_filter_ctl(t, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FILE, "*", LOG_DEBUG);
qb_log_format_set(t, "%b");
qb_log(LOG_DEBUG, "Hello");
ck_assert_str_eq(test_buf, "Hello");
num_msgs = 0;
qb_log_ctl(t, QB_LOG_CONF_ENABLED, QB_FALSE);
qb_log(LOG_DEBUG, "Goodbye");
ck_assert_int_eq(num_msgs, 0);
qb_log_ctl(t, QB_LOG_CONF_ENABLED, QB_TRUE);
qb_log(LOG_DEBUG, "Hello again");
ck_assert_int_eq(num_msgs, 1);
ck_assert_str_eq(test_buf, "Hello again");
}
void
crm_enable_blackbox(int nsig)
{
if (blackbox_file_prefix == NULL) {
pid_t pid = getpid();
blackbox_file_prefix = malloc(NAME_MAX);
snprintf(blackbox_file_prefix, NAME_MAX, "%s/%s-%d", CRM_BLACKBOX_DIR, crm_system_name,
pid);
}
if (qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_STATE_GET, 0) != QB_LOG_STATE_ENABLED) {
qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_SIZE, 5 * 1024 * 1024); /* Any size change drops existing entries */
qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_ENABLED, QB_TRUE); /* Setting the size seems to disable it */
crm_notice("Initiated blackbox recorder: %s", blackbox_file_prefix);
crm_signal(SIGSEGV, crm_trigger_blackbox);
crm_update_callsites();
/* Original meanings from signal(7)
*
* Signal Value Action Comment
* SIGTRAP 5 Core Trace/breakpoint trap
*
* Our usage is as similar as possible
*/
mainloop_add_signal(SIGTRAP, crm_trigger_blackbox);
blackbox_trigger = qb_log_custom_open(blackbox_logger, NULL, NULL, NULL);
qb_log_ctl(blackbox_trigger, QB_LOG_CONF_ENABLED, QB_TRUE);
crm_info("Trigger: %d is %d %d", blackbox_trigger,
qb_log_ctl(blackbox_trigger, QB_LOG_CONF_STATE_GET, 0), QB_LOG_STATE_ENABLED);
crm_update_callsites();
}
}
int32_t
main(int32_t argc, char *argv[])
{
const char *options = "vhteobdf:";
int32_t opt;
int32_t tracer;
int32_t do_stderr = QB_FALSE;
int32_t do_stdout = QB_FALSE;
int32_t do_dump_blackbox = QB_FALSE;
char *logfile = NULL;
int32_t log_fd = -1;
while ((opt = getopt(argc, argv, options)) != -1) {
switch (opt) {
case 'd':
do_dump_blackbox = QB_TRUE;
break;
case 't':
do_threaded = QB_TRUE;
break;
case 'e':
do_stderr = QB_TRUE;
break;
case 'o':
do_stdout = QB_TRUE;
break;
case 'b':
do_blackbox = QB_TRUE;
break;
case 'f':
logfile = optarg;
break;
case 'v':
_log_priority++;
break;
case 'h':
default:
show_usage(argv[0]);
exit(0);
break;
}
}
if (do_dump_blackbox) {
qb_log_blackbox_print_from_file("simple-log.fdata");
exit(0);
}
signal(SIGSEGV, sigsegv_handler);
qb_log_init("simple-log", LOG_USER, LOG_INFO);
qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_THREADED, do_threaded);
qb_log_tags_stringify_fn_set(my_tags_stringify);
if (do_stderr) {
qb_log_filter_fn_set(m_filter);
qb_log_format_set(QB_LOG_STDERR, "[%p] %4g: %f:%l %b");
qb_log_ctl(QB_LOG_STDERR, QB_LOG_CONF_ENABLED, QB_TRUE);
tracer = qb_log_custom_open(trace_logger, NULL, NULL, NULL);
qb_log_ctl(tracer, QB_LOG_CONF_ENABLED, QB_TRUE);
qb_log_format_set(tracer, "%4g: %n() %b");
qb_log_filter_ctl2(tracer, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FILE, __FILE__,
LOG_TRACE, 200);
}
if (do_stdout) {
qb_log_filter_ctl2(QB_LOG_STDOUT, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FILE, __FILE__,
LOG_ALERT, QB_MIN(LOG_DEBUG, _log_priority));
qb_log_format_set(QB_LOG_STDOUT, "[%p] %4g: %f:%l %b");
qb_log_ctl(QB_LOG_STDOUT, QB_LOG_CONF_ENABLED, QB_TRUE);
}
if (do_blackbox) {
qb_log_filter_ctl(QB_LOG_BLACKBOX, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FILE, "*", LOG_DEBUG);
qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_SIZE, 4096);
qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_THREADED, QB_FALSE);
qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_ENABLED, QB_TRUE);
}
if (logfile) {
log_fd = qb_log_file_open(logfile);
qb_log_filter_ctl(log_fd, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FILE, __FILE__, _log_priority);
qb_log_format_set(log_fd, "[%N] %t %n() [%p] %b");
qb_log_ctl(log_fd, QB_LOG_CONF_THREADED, do_threaded);
qb_log_ctl(log_fd, QB_LOG_CONF_ENABLED, QB_TRUE);
}
if (do_threaded) {
qb_log_thread_start();
}
qb_log(LOG_DEBUG, "hello");
qb_log(LOG_INFO, "this is an info");
qb_log(LOG_NOTICE, "hello - notice?");
func_one();
func_two();
qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_ENABLED, QB_FALSE);
qb_log(LOG_WARNING, "no syslog");
qb_log(LOG_ERR, "no syslog");
#if 0
// test blackbox
logfile = NULL;
logfile[5] = 'a';
#endif
if (do_blackbox) {
qb_log_blackbox_write_to_file("simple-log.fdata");
qb_log_blackbox_print_from_file("simple-log.fdata");
qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_ENABLED, QB_FALSE);
}
qb_log_fini();
return 0;
}
END_TEST
START_TEST(test_log_basic)
{
int32_t t;
int32_t rc;
qb_log_init("test", LOG_USER, LOG_EMERG);
qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_ENABLED, QB_FALSE);
t = qb_log_custom_open(_test_logger, NULL, NULL, NULL);
rc = qb_log_filter_ctl(t, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FORMAT, "Angus", LOG_WARNING);
ck_assert_int_eq(rc, 0);
qb_log_format_set(t, "%b");
rc = qb_log_ctl(t, QB_LOG_CONF_ENABLED, QB_TRUE);
ck_assert_int_eq(rc, 0);
/* captures last log */
memset(test_buf, 0, sizeof(test_buf));
test_priority = 0;
num_msgs = 0;
/*
* test filtering by format
*/
qb_log(LOG_INFO, "Hello Angus, how are you?");
qb_log(LOG_WARNING, "Hello Steven, how are you?");
qb_log(LOG_ERR, "Hello Andrew, how are you?");
qb_log(LOG_ERR, "Hello Angus, how are you?");
qb_log(LOG_EMERG, "Hello Anna, how are you?");
ck_assert_int_eq(test_priority, LOG_ERR);
ck_assert_int_eq(num_msgs, 1);
ck_assert_str_eq(test_buf, "Hello Angus, how are you?");
/*
* test filtering by file regex
*/
qb_log_filter_ctl(t, QB_LOG_FILTER_CLEAR_ALL,
QB_LOG_FILTER_FORMAT, "*", LOG_TRACE);
qb_log_filter_ctl(t, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FILE_REGEX, "^fakefile*", LOG_DEBUG);
num_msgs = 0;
qb_log_from_external_source(__func__, "fakefile_logging", "%s bla", LOG_INFO,
56, 0, "filename/lineno");
qb_log_from_external_source(__func__, "do_not_log_fakefile_logging", "%s bla", LOG_INFO,
56, 0, "filename/lineno");
ck_assert_int_eq(num_msgs, 1);
/*
* test filtering by format regex
*/
qb_log_filter_ctl(t, QB_LOG_FILTER_CLEAR_ALL,
QB_LOG_FILTER_FORMAT, "*", LOG_TRACE);
qb_log_filter_ctl(t, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FORMAT_REGEX, "^one", LOG_WARNING);
num_msgs = 0;
qb_log(LOG_INFO, "one two three");
qb_log(LOG_ERR, "testing one two three");
qb_log(LOG_WARNING, "one two three");
qb_log(LOG_ERR, "one two three");
qb_log(LOG_EMERG, "one two three");
ck_assert_int_eq(num_msgs, 3);
/*
* test filtering by function and regex
*/
qb_log_filter_ctl(t, QB_LOG_FILTER_CLEAR_ALL,
QB_LOG_FILTER_FILE, "*", LOG_TRACE);
qb_log_filter_ctl(t, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FUNCTION_REGEX, "^log_.*please", LOG_WARNING);
num_msgs = 0;
qb_log(LOG_ERR, "try if you: log_it_please()");
log_it_please();
ck_assert_int_eq(num_msgs, 3);
qb_log_filter_ctl(t, QB_LOG_FILTER_REMOVE,
QB_LOG_FILTER_FUNCTION_REGEX, "log_it_please", LOG_WARNING);
/*
* test filtering by function
*/
qb_log_filter_ctl(t, QB_LOG_FILTER_CLEAR_ALL,
QB_LOG_FILTER_FILE, "*", LOG_TRACE);
qb_log_filter_ctl(t, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FUNCTION, "log_it_please", LOG_WARNING);
num_msgs = 0;
qb_log(LOG_ERR, "try if you: log_it_please()");
log_it_please();
ck_assert_int_eq(num_msgs, 3);
qb_log_filter_ctl(t, QB_LOG_FILTER_REMOVE,
QB_LOG_FILTER_FUNCTION, "log_it_please", LOG_WARNING);
qb_log_filter_ctl(t, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FUNCTION, __func__, LOG_DEBUG);
num_msgs = 0;
log_it_please();
ck_assert_int_eq(num_msgs, 0);
qb_log(LOG_DEBUG, "try if you: log_it_please()");
ck_assert_int_eq(num_msgs, 1);
qb_log_filter_ctl(t, QB_LOG_FILTER_CLEAR_ALL,
QB_LOG_FILTER_FILE, "*", LOG_TRACE);
qb_log_filter_ctl(t, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FUNCTION,
"log_also,log_and_this_too",
LOG_DEBUG);
num_msgs = 0;
log_also();
log_and_this_too();
ck_assert_int_eq(num_msgs, 2);
qb_log_filter_ctl(t, QB_LOG_FILTER_CLEAR_ALL,
QB_LOG_FILTER_FILE, "*", LOG_TRACE);
qb_log_filter_ctl(t, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FILE, "fakefile.c,"__FILE__",otherfakefile", LOG_DEBUG);
/*
* make sure we can pass in a null filename or function name.
*/
qb_log_from_external_source(__func__, NULL, "%s", LOG_INFO,
__LINE__, 0, "null filename");
qb_log_from_external_source(NULL, __FILE__, "%s", LOG_INFO,
__LINE__, 0, "null function");
/* check same file/lineno logs with different formats work
*/
num_msgs = 0;
qb_log_from_external_source(__func__, __FILE__, "%s bla", LOG_INFO,
56, 0, "filename/lineno");
ck_assert_int_eq(num_msgs, 1);
ck_assert_str_eq(test_buf, "filename/lineno bla");
num_msgs = 0;
qb_log_from_external_source(__func__, __FILE__, "%s", LOG_INFO,
56, 0, "same filename/lineno");
ck_assert_int_eq(num_msgs, 1);
ck_assert_str_eq(test_buf, "same filename/lineno");
/* check filtering works on same file/lineno but different
* log level.
*/
qb_log_filter_ctl(t, QB_LOG_FILTER_CLEAR_ALL,
QB_LOG_FILTER_FILE, "*", LOG_TRACE);
qb_log_filter_ctl(t, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FILE, __FILE__, LOG_INFO);
num_msgs = 0;
qb_log_from_external_source(__func__, __FILE__,
"same filename/lineno, this level %d",
LOG_INFO, 56, 0, LOG_INFO);
ck_assert_int_eq(num_msgs, 1);
ck_assert_str_eq(test_buf, "same filename/lineno, this level 6");
num_msgs = 0;
qb_log_from_external_source(__func__, __FILE__,
"same filename/lineno, this level %d",
LOG_DEBUG, 56, 0, LOG_DEBUG);
ck_assert_int_eq(num_msgs, 0);
}