diff --git a/lib/log_blackbox.c b/lib/log_blackbox.c
index 3e30504..8519a48 100644
--- a/lib/log_blackbox.c
+++ b/lib/log_blackbox.c
@@ -1,384 +1,384 @@
/*
* Copyright (C) 2011 Red Hat, Inc.
*
* All rights reserved.
*
* Author: Angus Salkeld <asalkeld@redhat.com>
*
* libqb is free software: you can redistribute it and/or modify
* it under the terms of the GNU Lesser General Public License as published by
* the Free Software Foundation, either version 2.1 of the License, or
* (at your option) any later version.
*
* libqb is distributed in the hope that it will be useful,
* but WITHOUT ANY WARRANTY; without even the implied warranty of
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
* GNU Lesser General Public License for more details.
*
* You should have received a copy of the GNU Lesser General Public License
* along with libqb. If not, see <http://www.gnu.org/licenses/>.
*/
#include "os_base.h"
#include <qb/qbrb.h>
#include "util_int.h"
#include "log_int.h"
#include "ringbuffer_int.h"
#define BB_MIN_ENTRY_SIZE (4 * sizeof(uint32_t) +\
sizeof(uint8_t) +\
2 * sizeof(char) + sizeof(time_t))
static void
_blackbox_reload(int32_t target)
{
struct qb_log_target *t = qb_log_target_get(target);
if (t->instance == NULL) {
return;
}
qb_rb_close(t->instance);
t->instance = qb_rb_open(t->filename, t->size,
QB_RB_FLAG_CREATE | QB_RB_FLAG_OVERWRITE, 0);
}
/* <u32> file lineno
* <u32> tags
* <u8> priority
* <u32> function name length
* <string> function name
* <u32> buffer length
* <string> buffer
*/
static void
_blackbox_vlogger(int32_t target,
struct qb_log_callsite *cs, struct timespec *timestamp, va_list ap)
{
size_t max_size;
size_t actual_size;
uint32_t fn_size;
char *chunk;
char *msg_len_pt;
uint32_t msg_len;
struct qb_log_target *t = qb_log_target_get(target);
if (t->instance == NULL) {
return;
}
fn_size = strlen(cs->function) + 1;
actual_size = 4 * sizeof(uint32_t) + sizeof(uint8_t) + fn_size + sizeof(struct timespec);
max_size = actual_size + t->max_line_length;
chunk = qb_rb_chunk_alloc(t->instance, max_size);
if (chunk == NULL) {
/* something bad has happened. abort blackbox logging */
qb_util_perror(LOG_ERR, "Blackbox allocation error, aborting blackbox log %s", t->filename);
qb_rb_close(qb_rb_lastref_and_ret(
(struct qb_ringbuffer_s **) &t->instance
));
return;
}
/* line number */
memcpy(chunk, &cs->lineno, sizeof(uint32_t));
chunk += sizeof(uint32_t);
/* tags */
memcpy(chunk, &cs->tags, sizeof(uint32_t));
chunk += sizeof(uint32_t);
/* log level/priority */
memcpy(chunk, &cs->priority, sizeof(uint8_t));
chunk += sizeof(uint8_t);
/* function name */
memcpy(chunk, &fn_size, sizeof(uint32_t));
chunk += sizeof(uint32_t);
memcpy(chunk, cs->function, fn_size);
chunk += fn_size;
/* timestamp */
memcpy(chunk, timestamp, sizeof(struct timespec));
chunk += sizeof(struct timespec);
/* log message length */
msg_len_pt = chunk;
chunk += sizeof(uint32_t);
/* log message */
- msg_len = qb_vsnprintf_serialize(chunk, max_size, cs->format, ap);
- if (msg_len >= max_size) {
+ msg_len = qb_vsnprintf_serialize(chunk, t->max_line_length, cs->format, ap);
+ if (msg_len >= t->max_line_length) {
chunk = msg_len_pt + sizeof(uint32_t); /* Reset */
/* Leave this at QB_LOG_MAX_LEN so as not to overflow the blackbox */
msg_len = qb_vsnprintf_serialize(chunk, QB_LOG_MAX_LEN,
"Log message too long to be stored in the blackbox. "\
"Maximum is QB_LOG_MAX_LEN" , ap);
}
actual_size += msg_len;
/* now that we know the length, write it
*/
memcpy(msg_len_pt, &msg_len, sizeof(uint32_t));
(void)qb_rb_chunk_commit(t->instance, actual_size);
}
static void
_blackbox_close(int32_t target)
{
struct qb_log_target *t = qb_log_target_get(target);
qb_rb_close(qb_rb_lastref_and_ret(
(struct qb_ringbuffer_s **) &t->instance
));
}
int32_t
qb_log_blackbox_open(struct qb_log_target *t)
{
if (t->size < 1024) {
return -EINVAL;
}
snprintf(t->filename, PATH_MAX, "%s-%d-blackbox", t->name, getpid());
t->instance = qb_rb_open(t->filename, t->size,
QB_RB_FLAG_CREATE | QB_RB_FLAG_OVERWRITE, 0);
if (t->instance == NULL) {
return -errno;
}
t->logger = NULL;
t->vlogger = _blackbox_vlogger;
t->reload = _blackbox_reload;
t->close = _blackbox_close;
return 0;
}
/*
* This is designed to look as much like the ringbuffer header
* as possible so that we can distinguish an old RB dump
* from a new one with this header.
*/
struct _blackbox_file_header {
uint32_t word_size;
uint32_t read_pt;
uint32_t write_pt;
uint32_t version;
uint32_t hash;
} __attribute__((packed));
/* Values we expect for a 'new' header */
#define QB_BLACKBOX_HEADER_WORDSIZE 0
#define QB_BLACKBOX_HEADER_READPT 0xCCBBCCBB
#define QB_BLACKBOX_HEADER_WRITEPT 0xBBCCBBCC
#define QB_BLACKBOX_HEADER_VERSION 2
#define QB_BLACKBOX_HEADER_HASH 0
ssize_t
qb_log_blackbox_write_to_file(const char *filename)
{
ssize_t written_size = 0;
struct qb_log_target *t;
struct _blackbox_file_header header;
int fd = open(filename, O_CREAT | O_RDWR, 0700);
if (fd < 0) {
return -errno;
}
/* Write header, so we know this is a 'new' format blackbox */
header.word_size = QB_BLACKBOX_HEADER_WORDSIZE;
header.read_pt = QB_BLACKBOX_HEADER_READPT;
header.write_pt = QB_BLACKBOX_HEADER_WRITEPT;
header.version = QB_BLACKBOX_HEADER_VERSION;
header.hash = QB_BLACKBOX_HEADER_HASH;
written_size = write(fd, &header, sizeof(header));
if (written_size < sizeof(header)) {
close(fd);
return written_size;
}
t = qb_log_target_get(QB_LOG_BLACKBOX);
if (t->instance) {
written_size += qb_rb_write_to_file(t->instance, fd);
} else {
written_size = -ENOENT;
}
close(fd);
return written_size;
}
int
qb_log_blackbox_print_from_file(const char *bb_filename)
{
qb_ringbuffer_t *instance;
ssize_t bytes_read;
int max_size = 2 * QB_LOG_MAX_LEN;
char *chunk;
int fd;
int err = 0;
int saved_errno;
struct _blackbox_file_header header;
int have_timespecs = 0;
char time_buf[64];
fd = open(bb_filename, 0);
if (fd < 0) {
saved_errno = errno;
qb_util_perror(LOG_ERR, "qb_log_blackbox_print_from_file");
return -saved_errno;
}
/* Read the header. If it looks like one of ours then
we know we have hi-res timestamps */
err = read(fd, &header, sizeof(header));
if (err < sizeof(header)) {
saved_errno = errno;
close(fd);
return -saved_errno;
}
if (header.word_size == QB_BLACKBOX_HEADER_WORDSIZE &&
header.read_pt == QB_BLACKBOX_HEADER_READPT &&
header.write_pt == QB_BLACKBOX_HEADER_WRITEPT &&
header.version == QB_BLACKBOX_HEADER_VERSION &&
header.hash == QB_BLACKBOX_HEADER_HASH) {
have_timespecs = 1;
} else {
(void)lseek(fd, 0, SEEK_SET);
}
instance = qb_rb_create_from_file(fd, 0);
close(fd);
if (instance == NULL) {
return -EIO;
}
chunk = malloc(max_size);
if (!chunk) {
goto cleanup;
}
do {
char *ptr;
uint32_t lineno;
uint32_t tags;
uint8_t priority;
uint32_t fn_size;
char *function;
uint32_t len;
struct timespec timestamp;
time_t time_sec;
uint32_t msg_len;
struct tm *tm;
char message[QB_LOG_MAX_LEN];
bytes_read = qb_rb_chunk_read(instance, chunk, max_size, 0);
if (bytes_read >= 0 && bytes_read < BB_MIN_ENTRY_SIZE) {
printf("ERROR Corrupt file: blackbox header too small.\n");
err = -1;
goto cleanup;
} else if (bytes_read < 0) {
errno = -bytes_read;
perror("ERROR: qb_rb_chunk_read failed");
err = -EIO;
goto cleanup;
}
ptr = chunk;
/* lineno */
memcpy(&lineno, ptr, sizeof(uint32_t));
ptr += sizeof(uint32_t);
/* tags */
memcpy(&tags, ptr, sizeof(uint32_t));
ptr += sizeof(uint32_t);
/* priority */
memcpy(&priority, ptr, sizeof(uint8_t));
ptr += sizeof(uint8_t);
/* function size & name */
memcpy(&fn_size, ptr, sizeof(uint32_t));
if ((fn_size + BB_MIN_ENTRY_SIZE) > bytes_read) {
#ifndef S_SPLINT_S
printf("ERROR Corrupt file: fn_size way too big %" PRIu32 "\n", fn_size);
err = -EIO;
#endif /* S_SPLINT_S */
goto cleanup;
}
if (fn_size <= 0) {
#ifndef S_SPLINT_S
printf("ERROR Corrupt file: fn_size negative %" PRIu32 "\n", fn_size);
err = -EIO;
#endif /* S_SPLINT_S */
goto cleanup;
}
ptr += sizeof(uint32_t);
function = ptr;
ptr += fn_size;
/* timestamp size & content */
if (have_timespecs) {
memcpy(×tamp, ptr, sizeof(struct timespec));
ptr += sizeof(struct timespec);
time_sec = timestamp.tv_sec;
} else {
memcpy(&time_sec, ptr, sizeof(time_t));
ptr += sizeof(time_t);
timestamp.tv_nsec = 0LL;
}
tm = localtime(&time_sec);
if (tm) {
int slen = strftime(time_buf,
sizeof(time_buf), "%b %d %T",
tm);
snprintf(time_buf+slen, sizeof(time_buf) - slen, ".%03llu", timestamp.tv_nsec/QB_TIME_NS_IN_MSEC);
} else {
snprintf(time_buf, sizeof(time_buf), "%ld",
(long int)time_sec);
}
/* message length */
memcpy(&msg_len, ptr, sizeof(uint32_t));
if (msg_len > QB_LOG_MAX_LEN || msg_len <= 0) {
#ifndef S_SPLINT_S
printf("ERROR Corrupt file: msg_len out of bounds %" PRIu32 "\n", msg_len);
err = -EIO;
#endif /* S_SPLINT_S */
goto cleanup;
}
ptr += sizeof(uint32_t);
/* message content */
len = qb_vsnprintf_deserialize(message, QB_LOG_MAX_LEN, ptr);
assert(len > 0);
message[len] = '\0';
len--;
while (len > 0 && (message[len] == '\n' || message[len] == '\0')) {
message[len] = '\0';
len--;
}
printf("%-7s %s %s(%u):%u: %s\n",
qb_log_priority2str(priority),
time_buf, function, lineno, tags, message);
} while (bytes_read > BB_MIN_ENTRY_SIZE);
cleanup:
qb_rb_close(instance);
free(chunk);
return err;
}
diff --git a/tests/check_log.c b/tests/check_log.c
index 039a4bb..e5abf40 100644
--- a/tests/check_log.c
+++ b/tests/check_log.c
@@ -1,1136 +1,1138 @@
/*
* Copyright (c) 2011-2015 Red Hat, Inc.
*
* All rights reserved.
*
* Author: Angus Salkeld <asalkeld@redhat.com>
*
* This file is part of libqb.
*
* libqb is free software: you can redistribute it and/or modify
* it under the terms of the GNU Lesser General Public License as published by
* the Free Software Foundation, either version 2.1 of the License, or
* (at your option) any later version.
*
* libqb is distributed in the hope that it will be useful,
* but WITHOUT ANY WARRANTY; without even the implied warranty of
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
* GNU Lesser General Public License for more details.
*
* You should have received a copy of the GNU Lesser General Public License
* along with libqb. If not, see <http://www.gnu.org/licenses/>.
*/
#include "os_base.h"
#include <pthread.h>
#include "check_common.h"
#include <qb/qbdefs.h>
#include <qb/qbutil.h>
#include <qb/qblog.h>
#ifdef USE_JOURNAL
#include <systemd/sd-journal.h>
#endif
#include "_syslog_override.h"
extern size_t qb_vsnprintf_serialize(char *serialize, size_t max_len, const char *fmt, va_list ap);
extern size_t qb_vsnprintf_deserialize(char *string, size_t strlen, const char *buf);
static void
format_this(char *out, const char *fmt, ...)
{
char buf[QB_LOG_MAX_LEN];
va_list ap;
va_start(ap, fmt);
qb_vsnprintf_serialize(buf, QB_LOG_MAX_LEN, fmt, ap);
qb_vsnprintf_deserialize(out, QB_LOG_MAX_LEN, buf);
va_end(ap);
}
static void
format_this_up_to(char *out, size_t max_len, const char *fmt, ...)
{
char buf[QB_LOG_MAX_LEN];
va_list ap;
va_start(ap, fmt);
qb_vsnprintf_serialize(buf, max_len, fmt, ap);
qb_vsnprintf_deserialize(out, QB_LOG_MAX_LEN, buf);
va_end(ap);
}
START_TEST(test_va_serialize)
{
char buf[QB_LOG_MAX_LEN];
char cmp_buf[QB_LOG_MAX_LEN];
format_this(buf, "one line");
ck_assert_str_eq(buf, "one line");
format_this(buf, "p1:%p, p2:%p", format_this, buf);
snprintf(cmp_buf, QB_LOG_MAX_LEN, "p1:%p, p2:%p", format_this, buf);
ck_assert_str_eq(buf, cmp_buf);
format_this(buf, "s1:%s, s2:%s", "Yes", "Never");
ck_assert_str_eq(buf, "s1:Yes, s2:Never");
format_this(buf, "s1:%s, s2:%s", "Yes", "Never");
ck_assert_str_eq(buf, "s1:Yes, s2:Never");
format_this(buf, "d1:%d, d2:%5i, d3:%04i", 23, 37, 84);
ck_assert_str_eq(buf, "d1:23, d2: 37, d3:0084");
format_this(buf, "f1:%.5f, f2:%.2f", 23.34109, 23.34109);
ck_assert_str_eq(buf, "f1:23.34109, f2:23.34");
format_this(buf, "%zd", (size_t)13140964);
ck_assert_str_eq(buf, "13140964");
format_this(buf, "%jd", (intmax_t)30627823);
ck_assert_str_eq(buf, "30627823");
format_this(buf, "%td", buf-cmp_buf);
snprintf(cmp_buf, QB_LOG_MAX_LEN, "%td", buf-cmp_buf);
ck_assert_str_eq(buf, cmp_buf);
format_this(buf, ":%s:", "Hello, world!");
ck_assert_str_eq(buf, ":Hello, world!:");
format_this(buf, ":%15s:", "Hello, world!");
ck_assert_str_eq(buf, ": Hello, world!:");
format_this(buf, ":%.10s:", "Hello, world!");
ck_assert_str_eq(buf, ":Hello, wor:");
format_this(buf, ":%-10s:", "Hello, world!");
ck_assert_str_eq(buf, ":Hello, world!:");
format_this(buf, ":%-15s:", "Hello, world!");
ck_assert_str_eq(buf, ":Hello, world! :");
format_this(buf, ":%.15s:", "Hello, world!");
ck_assert_str_eq(buf, ":Hello, world!:");
format_this(buf, ":%15.10s:", "Hello, world!");
ck_assert_str_eq(buf, ": Hello, wor:");
format_this(buf, ":%-15.10s:", "Hello, world!");
ck_assert_str_eq(buf, ":Hello, wor :");
format_this(buf, ":%*d:", 8, 96);
ck_assert_str_eq(buf, ": 96:");
format_this_up_to(buf, 11, "123456789____");
ck_assert_str_eq(buf, "123456789_");
format_this(buf, "Client %s.%.9s wants to fence (%s) '%s' with device '%s'",
"bla", "foooooooooooooooooo",
"action", "target", "hoop");
ck_assert_str_eq(buf,
"Client bla.foooooooo wants to fence (action) 'target' with device 'hoop'");
format_this(buf, "Node %s now has process list: %.32x (was %.32x)",
"18builder", 2, 0);
ck_assert_str_eq(buf, "Node 18builder now has process list: 00000000000000000000000000000002 (was 00000000000000000000000000000000)");
}
END_TEST
START_TEST(test_log_stupid_inputs)
{
int32_t rc;
/* shouldn't crash with out an init() */
qb_log_fini();
/* not init'ed */
rc = qb_log_filter_ctl(QB_LOG_SYSLOG, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FILE, "bla", LOG_TRACE);
ck_assert_int_eq(rc, -EINVAL);
rc = qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_SIZE, 2000);
ck_assert_int_eq(rc, -EINVAL);
qb_log(LOG_INFO, "not init'd");
qb_log_from_external_source(__func__, __FILE__, "%s", LOG_INFO,
__LINE__, 0, "also not init'd");
qb_log_init("test", LOG_USER, LOG_DEBUG);
/* non-opened log file */
rc = qb_log_filter_ctl(21, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FILE, "bla", LOG_TRACE);
ck_assert_int_eq(rc, -EBADF);
rc = qb_log_ctl(21, QB_LOG_CONF_PRIORITY_BUMP, -1);
ck_assert_int_eq(rc, -EBADF);
/* target < 0 or >= 32 */
rc = qb_log_filter_ctl(41, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FILE, "bla", LOG_TRACE);
ck_assert_int_eq(rc, -EBADF);
rc = qb_log_ctl(-1, QB_LOG_CONF_PRIORITY_BUMP, -1);
ck_assert_int_eq(rc, -EBADF);
/* crap values to filter_ctl() */
rc = qb_log_filter_ctl(QB_LOG_SYSLOG, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FILE, NULL, LOG_INFO);
ck_assert_int_eq(rc, -EINVAL);
rc = qb_log_filter_ctl(QB_LOG_SYSLOG, 56,
QB_LOG_FILTER_FILE, "boja", LOG_INFO);
ck_assert_int_eq(rc, -EINVAL);
/* crap values to ctl() */
rc = qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_SIZE, -2000);
ck_assert_int_eq(rc, -EINVAL);
rc = qb_log_ctl(QB_LOG_BLACKBOX, 67, 2000);
ck_assert_int_eq(rc, -EINVAL);
rc = qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_SIZE, 2000);
ck_assert_int_eq(rc, -ENOSYS);
}
END_TEST
static char test_buf[4097];
static uint8_t test_priority;
static int32_t num_msgs;
static size_t last_length;
/*
* to test that we get what we expect.
*/
static void
_test_logger(int32_t t,
struct qb_log_callsite *cs,
struct timespec *timestamp, const char *msg)
{
test_buf[0] = '\0';
qb_log_target_format(t, cs, timestamp, msg, test_buf);
test_priority = cs->priority;
num_msgs++;
}
static void
_test_length_logger(int32_t t,
struct qb_log_callsite *cs,
struct timespec *timestamp, const char *msg)
{
strcpy(test_buf, msg);
qb_log_target_format(t, cs, timestamp, msg, test_buf);
test_priority = cs->priority;
num_msgs++;
last_length = strlen(msg);
}
static void log_also(void)
{
qb_log(LOG_INFO, "yes please");
}
static void log_and_this_too(void)
{
qb_log(LOG_INFO, "this too please");
}
static void log_it_please(void)
{
qb_enter();
qb_log(LOG_TRACE, "A:%d B:%d C:%d", 1, 2, 3);
qb_log(LOG_DEBUG, "A:%d B:%d C:%d", 1, 2, 3);
errno = EEXIST;
qb_perror(LOG_WARNING, "bogus error");
errno = 0;
qb_log(LOG_INFO, "A:%d B:%d C:%d", 1, 2, 3);
qb_log(LOG_NOTICE, "A:%d B:%d C:%d", 1, 2, 3);
qb_log(LOG_WARNING, "A:%d B:%d C:%d", 1, 2, 3);
qb_log(LOG_ERR, "A:%d B:%d C:%d", 1, 2, 3);
qb_leave();
}
static int32_t _cust_t = -1;
static void
m_filter(struct qb_log_callsite *cs)
{
if ((cs->priority >= LOG_ALERT &&
cs->priority <= LOG_INFO) ||
cs->tags > 0) {
qb_bit_set(cs->targets, _cust_t);
} else {
qb_bit_clear(cs->targets, _cust_t);
}
}
START_TEST(test_log_filter_fn)
{
int32_t rc;
qb_log_init("test", LOG_USER, LOG_EMERG);
qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_ENABLED, QB_FALSE);
_cust_t = qb_log_custom_open(_test_logger, NULL, NULL, NULL);
_ck_assert_int(_cust_t, >, QB_LOG_BLACKBOX);
rc = qb_log_ctl(_cust_t, QB_LOG_CONF_ENABLED, QB_TRUE);
ck_assert_int_eq(rc, 0);
/*
* test the custom filter function.
* make sure qb_log, and qb_log_from_external_source are filtered.
*/
qb_log_filter_fn_set(m_filter);
num_msgs = 0;
qb_log(LOG_NOTICE, "qb_log_filter_fn_set good");
qb_log_from_external_source(__func__, __FILE__, "%s", LOG_INFO,
__LINE__, 0, "qb_log_filter_fn_set good");
qb_log(LOG_TRACE, "qb_log_filter_fn_set bad");
qb_log_from_external_source(__func__, __FILE__, "%s", LOG_DEBUG,
__LINE__, 44, "qb_log_filter_fn_set woot");
qb_log_from_external_source(__func__, __FILE__, "%s", LOG_DEBUG,
__LINE__, 0, "qb_log_filter_fn_set bad");
ck_assert_int_eq(num_msgs, 3);
}
END_TEST
START_TEST(test_file_logging)
{
struct stat st;
int rc, lf;
unlink("test1.log");
unlink("test2.log");
qb_log_init("test", LOG_USER, LOG_DEBUG);
lf = qb_log_file_open("test1.log");
rc = qb_log_filter_ctl(lf, QB_LOG_FILTER_ADD, QB_LOG_FILTER_FILE,
__FILE__, LOG_DEBUG);
ck_assert_int_eq(rc, 0);
rc = qb_log_ctl(lf, QB_LOG_CONF_ENABLED, QB_TRUE);
ck_assert_int_eq(rc, 0);
qb_log(LOG_INFO, "write to file 1");
qb_log(LOG_INFO, "write to file 1 again");
rc = stat("test1.log", &st);
ck_assert_int_eq(rc, 0);
ck_assert_int_ge(st.st_size, 32);
/* Test reopen with NULL arg */
rc = qb_log_file_reopen(lf, NULL);
ck_assert_int_eq(rc, 0);
qb_log(LOG_INFO, "write to file 1 and again");
qb_log(LOG_INFO, "write to file 1 yet again");
rc = stat("test1.log", &st);
ck_assert_int_eq(rc, 0);
ck_assert_int_ge(st.st_size, 64);
/* Test reopen with new file */
rc = qb_log_file_reopen(lf, "test2.log");
ck_assert_int_eq(rc, 0);
qb_log(LOG_INFO, "write to file 2");
qb_log(LOG_INFO, "write to file 2 again");
rc = stat("test2.log", &st);
ck_assert_int_eq(rc, 0);
ck_assert_int_ge(st.st_size, 32);
unlink("test1.log");
unlink("test2.log");
}
END_TEST
START_TEST(test_timestamps)
{
int32_t t;
int32_t rc;
int a,b,c,d;
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);
/* normal timestamp */
qb_log_format_set(t, "%t %b");
rc = qb_log_ctl(t, QB_LOG_CONF_ENABLED, QB_TRUE);
ck_assert_int_eq(rc, 0);
qb_log(LOG_INFO, "The time now is (see left)");
rc = sscanf(test_buf+7, "%d:%d:%d.%d", &a, &b, &c, &d);
ck_assert_int_eq(rc, 3);
/* millisecond timestamp */
qb_log_format_set(t, "%T %b");
qb_log(LOG_INFO, "The time now is precisely (see left)");
rc = sscanf(test_buf+7, "%d:%d:%d.%d", &a, &b, &c, &d);
ck_assert_int_eq(rc, 4);
}
END_TEST
START_TEST(test_line_length)
{
int32_t t;
int32_t rc;
int i;
char bigbuf[4097];
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_length_logger, NULL, NULL, NULL);
rc = qb_log_filter_ctl(t, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FORMAT, "*", LOG_WARNING);
ck_assert_int_eq(rc, 0);
qb_log_format_set(t, "[%p] %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_MAX_LINE_LEN, 32);
ck_assert_int_eq(rc, 0);
rc = qb_log_ctl(t, QB_LOG_CONF_ELLIPSIS, QB_TRUE);
ck_assert_int_eq(rc, 0);
/* captures last log */
memset(test_buf, 0, sizeof(test_buf));
test_priority = 0;
num_msgs = 0;
qb_log(LOG_ERR, "Short message");
qb_log(LOG_ERR, "This is a longer message 123456789012345678901234567890");
qb_log(LOG_ERR, "Long message with parameters %d %s", 1234, "Oh yes it is");
ck_assert_int_eq(num_msgs, 3);
ck_assert_int_eq(last_length, 31);
ck_assert_str_eq(test_buf+28, "...");
rc = qb_log_ctl(t, QB_LOG_CONF_ELLIPSIS, QB_FALSE);
ck_assert_int_eq(rc, 0);
qb_log(LOG_ERR, "Long message with parameters %d %s", 1234, "Oh yes it is");
ck_assert_str_ne(test_buf+28, "...");
/* Long lines */
num_msgs = 0;
rc = qb_log_ctl(t, QB_LOG_CONF_MAX_LINE_LEN, 4096);
ck_assert_int_eq(rc, 0);
for (i=0; i<4096; i++) {
bigbuf[i] = '0'+(i%10);
}
bigbuf[4096] = '\0';
qb_log(LOG_ERR, "%s", bigbuf);
ck_assert_int_eq(num_msgs, 1);
ck_assert_int_eq(last_length, 4095);
}
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);
}
END_TEST
static const char *_test_tags_stringify(uint32_t tags)
{
if (tags == 1) {
return "ONE";
} else if (tags == 8) {
return "ATE";
} else {
return "ANY";
}
}
START_TEST(test_log_format)
{
int32_t t;
/* following size/length related equation holds in the context of use:
strlen(cmp_str) = strlen(host_str) + X; X ~ 20 < sizeof(host_str) */
char host_str[256];
char cmp_str[2 * sizeof(host_str)];
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);
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, "%p %f %b");
qb_log(LOG_DEBUG, "Angus");
ck_assert_str_eq(test_buf, "debug check_log.c Angus");
qb_log(LOG_INFO, "Angus");
ck_assert_str_eq(test_buf, "info check_log.c Angus");
qb_log(LOG_NOTICE, "Angus");
ck_assert_str_eq(test_buf, "notice check_log.c Angus");
qb_log(LOG_WARNING, "Angus");
ck_assert_str_eq(test_buf, "warning check_log.c Angus");
qb_log(LOG_ERR, "Angus");
ck_assert_str_eq(test_buf, "error check_log.c Angus");
qb_log(LOG_CRIT, "Angus");
ck_assert_str_eq(test_buf, "crit check_log.c Angus");
qb_log(LOG_ALERT, "Angus");
ck_assert_str_eq(test_buf, "alert check_log.c Angus");
qb_log(LOG_EMERG, "Angus");
ck_assert_str_eq(test_buf, "emerg check_log.c Angus");
qb_log_tags_stringify_fn_set(_test_tags_stringify);
qb_log_format_set(t, "%g %b");
qb_logt(LOG_INFO, 0, "Angus");
ck_assert_str_eq(test_buf, "ANY Angus");
qb_logt(LOG_INFO, 1, "Angus");
ck_assert_str_eq(test_buf, "ONE Angus");
qb_logt(LOG_INFO, 5, "Angus");
ck_assert_str_eq(test_buf, "ANY Angus");
qb_logt(LOG_INFO, 8, "Angus");
ck_assert_str_eq(test_buf, "ATE Angus");
qb_log_format_set(t, "%-15f %b");
qb_log(LOG_WARNING, "Andrew");
ck_assert_str_eq(test_buf, " check_log.c Andrew");
qb_log_tags_stringify_fn_set(NULL);
gethostname(host_str, sizeof(host_str));
host_str[sizeof(host_str) - 1] = '\0';
qb_log_format_set(t, "%P %H %N %b");
qb_log(LOG_INFO, "Angus");
snprintf(cmp_str, sizeof(cmp_str), "%d %s test Angus", getpid(),
host_str);
ck_assert_str_eq(test_buf, cmp_str);
qb_log_format_set(t, "%3N %H %P %b");
qb_log(LOG_INFO, "Angus");
snprintf(cmp_str, sizeof(cmp_str), "tes %s %d Angus", host_str,
getpid());
ck_assert_str_eq(test_buf, cmp_str);
}
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");
}
END_TEST
#define ITERATIONS 100000
static void *thr_send_logs_2(void *ctx)
{
int32_t i;
printf("%s\n", __func__);
for (i = 0; i < ITERATIONS; i++) {
qb_log(LOG_INFO, "bla bla");
qb_log(LOG_INFO, "blue blue");
qb_log(LOG_INFO, "bra bra");
qb_log(LOG_INFO, "bro bro");
qb_log(LOG_INFO, "brown brown");
qb_log(LOG_INFO, "booo booo");
qb_log(LOG_INFO, "bogus bogus");
qb_log(LOG_INFO, "bungu bungu");
}
return (NULL);
}
static void *thr_send_logs_1(void *ctx)
{
int32_t i;
printf("%s\n", __func__);
for (i = 0; i < ITERATIONS; i++) {
qb_log_from_external_source(__func__, __FILE__, "%s", LOG_INFO,
__LINE__, 0, "foo soup");
qb_log_from_external_source(__func__, __FILE__, "%s", LOG_INFO,
__LINE__, 0, "fungus soup");
qb_log_from_external_source(__func__, __FILE__, "%s", LOG_INFO,
__LINE__, 0, "fruity soup");
qb_log_from_external_source(__func__, __FILE__, "%s", LOG_INFO,
__LINE__, 0, "free soup");
qb_log_from_external_source(__func__, __FILE__, "%s", LOG_INFO,
__LINE__, 0, "frot soup");
qb_log_from_external_source(__func__, __FILE__, "%s", LOG_INFO,
__LINE__, 0, "fresh soup");
qb_log_from_external_source(__func__, __FILE__, "%s", LOG_INFO,
__LINE__, 0, "fattening soup");
}
return (NULL);
}
#define THREADS 4
START_TEST(test_log_threads)
{
pthread_t threads[THREADS];
pthread_attr_t thread_attr[THREADS];
int32_t i;
int32_t rc;
int32_t lf;
void *retval;
qb_log_init("test", LOG_USER, LOG_DEBUG);
lf = qb_log_file_open("threads.log");
rc = qb_log_filter_ctl(lf, QB_LOG_FILTER_ADD, QB_LOG_FILTER_FILE,
__FILE__, LOG_DEBUG);
ck_assert_int_eq(rc, 0);
qb_log_format_set(lf, "[%p] [%l] %b");
rc = qb_log_ctl(lf, QB_LOG_CONF_ENABLED, QB_TRUE);
ck_assert_int_eq(rc, 0);
rc = qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_ENABLED, QB_FALSE);
ck_assert_int_eq(rc, 0);
for (i = 0; i < THREADS/2; i++) {
pthread_attr_init(&thread_attr[i]);
pthread_attr_setdetachstate(&thread_attr[i],
PTHREAD_CREATE_JOINABLE);
pthread_create(&threads[i], &thread_attr[i],
thr_send_logs_1, NULL);
}
for (i = THREADS/2; i < THREADS; i++) {
pthread_attr_init(&thread_attr[i]);
pthread_attr_setdetachstate(&thread_attr[i],
PTHREAD_CREATE_JOINABLE);
pthread_create(&threads[i], &thread_attr[i],
thr_send_logs_2, NULL);
}
for (i = 0; i < THREADS; i++) {
pthread_join(threads[i], &retval);
}
}
END_TEST
START_TEST(test_log_long_msg)
{
int lpc;
int rc;
int i, max = 1000;
char *buffer = calloc(1, max);
qb_log_init("test", LOG_USER, LOG_DEBUG);
rc = qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_ENABLED, QB_FALSE);
ck_assert_int_eq(rc, 0);
rc = qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_SIZE, 1024);
ck_assert_int_eq(rc, 0);
rc = qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_ENABLED, QB_TRUE);
ck_assert_int_eq(rc, 0);
rc = qb_log_filter_ctl(QB_LOG_BLACKBOX, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FILE, "*", LOG_TRACE);
ck_assert_int_eq(rc, 0);
for (lpc = 500; lpc < max; lpc++) {
lpc++;
for(i = 0; i < max; i++) {
buffer[i] = 'a' + (i % 10);
}
buffer[lpc%600] = 0;
qb_log(LOG_INFO, "Message %d %d - %s", lpc, lpc%600, buffer);
}
- qb_log_blackbox_write_to_file("blackbox.dump");
- qb_log_blackbox_print_from_file("blackbox.dump");
+ rc = qb_log_blackbox_write_to_file("blackbox.dump");
+ ck_assert_int_gt(rc, 0);
+ rc = qb_log_blackbox_print_from_file("blackbox.dump");
+ ck_assert_int_le(rc, 0);
unlink("blackbox.dump");
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
#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
static const char *tagtest_stringify_tag(uint32_t tag)
{
static char buf[32];
sprintf(buf, "%5" PRIu32, tag);
return buf;
}
START_TEST(test_zero_tags)
{
int32_t rc;
int32_t t;
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, "[%g] %b");
qb_log_tags_stringify_fn_set(tagtest_stringify_tag);
rc = qb_log_ctl(t, QB_LOG_CONF_ENABLED, QB_TRUE);
ck_assert_int_eq(rc, 0);
qb_log_filter_ctl(t, QB_LOG_FILTER_ADD,
QB_LOG_FILTER_FILE, "*", LOG_TRACE);
qb_log_from_external_source("function", "filename", "%s: %d", LOG_DEBUG, 356, 2, "testlog", 2);
ck_assert_str_eq(test_buf, "[ 2] testlog: 2");
qb_log_from_external_source("function", "filename", "%s: %d", LOG_DEBUG, 356, 0, "testlog", 0);
ck_assert_str_eq(test_buf, "[ 2] testlog: 0");
qb_log_fini();
}
END_TEST
#ifdef USE_JOURNAL
START_TEST(test_journal)
{
int rc;
const char *msg;
size_t len;
pid_t log_pid;
sd_journal *jnl;
int count = 0;
const char *msgid="f77379a8490b408bbe5f6940505a777b";
qb_log_init("check_log", LOG_USER, LOG_DEBUG);
qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_ENABLED, QB_TRUE);
rc = qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_USE_JOURNAL, 1);
ck_assert_int_eq(rc, 0);
qb_log2(msgid, LOG_ERR, "Test message 1 from libqb");
qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_ENABLED, QB_TRUE);
rc = qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_USE_JOURNAL, 1);
ck_assert_int_eq(rc, -EINVAL);
sleep(1);
/* Check it reached the journal */
rc = sd_journal_open(&jnl, 0);
ck_assert_int_eq(rc, 0);
rc = sd_journal_seek_tail(jnl);
ck_assert_int_eq(rc, 0);
SD_JOURNAL_FOREACH_BACKWARDS(jnl) {
rc = sd_journal_get_data(jnl, "_PID", (const void **)&msg, &len);
ck_assert_int_eq(rc, 0);
sscanf(msg, "_PID=%d", &log_pid);
fprintf(stderr, "PID message = '%s' - pid = %d (pid=%d, parent=%d)\n", msg, log_pid, getpid(), getppid());
if (log_pid == getpid()) {
rc = sd_journal_get_data(jnl, "MESSAGE", (const void **)&msg, &len);
ck_assert_int_eq(rc, 0);
rc = sd_journal_get_data(jnl, "MESSAGE_ID", (const void **)&msg, &len);
ck_assert_int_eq(rc, 0);
ck_assert_str_eq(msg+11, msgid);
break;
}
if (++count > 20) {
break;
}
}
sd_journal_close(jnl);
ck_assert_int_lt(count, 20);
}
END_TEST
#else
START_TEST(test_syslog)
{
int rc;
qb_log_init("flip", LOG_USER, LOG_INFO);
qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_ENABLED, QB_TRUE);
qb_log(LOG_ERR, "first as flip");
ck_assert_int_eq(_syslog_opened, 1);
ck_assert_str_eq(_syslog_ident, "flip");
qb_log_ctl2(QB_LOG_SYSLOG, QB_LOG_CONF_IDENT, QB_LOG_CTL2_S("flop"));
qb_log(LOG_ERR, "second as flop");
ck_assert_str_eq(_syslog_ident, "flop");
/* This test only runs if USE_JOURNAL is undefined, so should always fail */
rc = qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_USE_JOURNAL, 1);
ck_assert_int_eq(rc, -EOPNOTSUPP);
qb_log_fini();
}
END_TEST
#endif
static Suite *
log_suite(void)
{
TCase *tc;
Suite *s = suite_create("logging");
add_tcase(s, tc, test_va_serialize);
add_tcase(s, tc, test_log_stupid_inputs);
add_tcase(s, tc, test_log_basic);
add_tcase(s, tc, test_log_format);
add_tcase(s, tc, test_log_enable);
add_tcase(s, tc, test_log_threads, 360);
add_tcase(s, tc, test_log_long_msg);
add_tcase(s, tc, test_log_filter_fn);
add_tcase(s, tc, test_threaded_logging);
add_tcase(s, tc, test_line_length);
add_tcase(s, tc, test_file_logging);
#ifdef HAVE_PTHREAD_SETSCHEDPARAM
add_tcase(s, tc, test_threaded_logging_bad_sched_params);
#endif
add_tcase(s, tc, test_timestamps);
add_tcase(s, tc, test_extended_information);
add_tcase(s, tc, test_zero_tags);
/*
* You can still use syslog and journal in a normal application,
* but the syslog_override code doesn't work when -lsystemd is present
*/
#ifdef USE_JOURNAL
add_tcase(s, tc, test_journal);
#else
add_tcase(s, tc, test_syslog);
#endif
return s;
}
int32_t
main(void)
{
int32_t number_failed;
Suite *s = log_suite();
SRunner *sr = srunner_create(s);
srunner_run_all(sr, CK_VERBOSE);
number_failed = srunner_ntests_failed(sr);
srunner_free(sr);
return (number_failed == 0) ? EXIT_SUCCESS : EXIT_FAILURE;
}