diff --git a/include/qb/qblog.h b/include/qb/qblog.h index d8f0882..3dcdf9c 100644 --- a/include/qb/qblog.h +++ b/include/qb/qblog.h @@ -1,758 +1,818 @@ /* * Copyright (c) 2017 Red Hat, Inc. * * All rights reserved. * * Author: Angus Salkeld * Jan Pokorny * * 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 . */ #ifndef QB_LOG_H_DEFINED #define QB_LOG_H_DEFINED /* *INDENT-OFF* */ #ifdef __cplusplus extern "C" { #endif /* *INDENT-ON* */ #include #include #include #include #include #include #include #include #include /** * @file qblog.h * The logging API provides four main parts (basics, filtering, threading & blackbox). * * The idea behind this logging system is not to be prescriptive but to provide a * set of tools to help the developer achieve what they want quickly and easily. * * @par Basic logging API. * Call qb_log() to generate a log message. Then to write the message * somewhere meaningful call qb_log_ctl() to configure the targets. * * Simplest possible use: * @code * main() { * qb_log_init("simple-log", LOG_DAEMON, LOG_INFO); * // ... * qb_log(LOG_WARNING, "watch out"); * // ... * qb_log_fini(); * } * @endcode * * @par Configuring log targets. * A log target can be syslog, stderr, the blackbox, stdout, or a text file. * By default, only syslog is enabled. While this is usual for daemons, * it is rarely appropriate for ordinary programs, which should * disable it when other targets (see below) are to be used: * @code * qb_log_ctl(B_LOG_SYSLOG, QB_LOG_CONF_ENABLED, QB_FALSE); * @endcode * * To enable a target do the following: * @code * qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_ENABLED, QB_TRUE); * @endcode * * syslog, stderr, the blackbox, and stdout are static (they don't need * to be created, just enabled or disabled). However, you can open multiple * logfiles (falling within inclusive range @c QB_LOG_TARGET_DYNAMIC_START * up to @c QB_LOG_TARGET_DYNAMIC_END). To do this, use the following code: * @code * mytarget = qb_log_file_open("/var/log/mylogfile"); * qb_log_ctl(mytarget, QB_LOG_CONF_ENABLED, QB_TRUE); * @endcode * * Once your targets are enabled/opened, you can configure them as follows: * Configure the size of blackbox: * @code * qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_SIZE, 1024*10); * @endcode * * Make logging to file threaded: * @code * qb_log_ctl(mytarget, QB_LOG_CONF_THREADED, QB_TRUE); * @endcode * * Sometimes, syslog daemons are (pre)configured to filter messages not * exceeding a particular priority. When this happens to be the logging * target, the designated priority of the message is passed along unchanged, * possibly resulting in message loss. For messages up to @c LOG_DEBUG * importance, this can be worked around by proportionally bumping the * priorities to be passed to syslog (here, the step is such that * @c LOG_DEBUG gets promoted to @c LOG_INFO): * @code * qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_PRIORITY_BUMP, * LOG_INFO - LOG_DEBUG); * @endcode * * To ensure all logs to file targets are fsync'ed (new messages expressly * transferred to the storage device as they keep coming, otherwise defaults * to @c QB_FALSE): * @code * qb_log_ctl(mytarget, QB_LOG_CONF_FILE_SYNC, QB_TRUE); * @endcode * * * @par Filtering messages. * To have more power over what log messages go to which target you can apply * filters to the targets. What happens is the desired callsites have the * correct bit set. Then when the log message is generated it gets sent to the * targets based on which bit is set in the callsite's "target" bitmap. * Messages can be filtered based on the: * -# filename + priority * -# function name + priority * -# format string + priority * * So to make all logs from evil_function() go to stderr, do the following: * @code * qb_log_filter_ctl(QB_LOG_STDERR, QB_LOG_FILTER_ADD, * QB_LOG_FILTER_FUNCTION, "evil_function", LOG_TRACE); * @endcode * * So to make all logs from totem* (with a priority <= LOG_INFO) go to stderr, * do the following: * @code * qb_log_filter_ctl(QB_LOG_STDERR, QB_LOG_FILTER_ADD, * QB_LOG_FILTER_FILE, "totem", LOG_INFO); * @endcode * * So to make all logs with the substring "ringbuffer" go to stderr, * do the following: * @code * qb_log_filter_ctl(QB_LOG_STDERR, QB_LOG_FILTER_ADD, * QB_LOG_FILTER_FORMAT, "ringbuffer", LOG_TRACE); * @endcode * * @par Thread safe non-blocking logging. * Logging is only thread safe when threaded logging is in use. If you plan * on logging from multiple threads, you must initialize libqb's logger thread * and use qb_log_filter_ctl to set the QB_LOG_CONF_THREADED flag on all the * logging targets in use. * * To achieve non-blocking logging, so that any calls to write() or syslog() * will not hold up your program, you can use threaded logging as well. * * Threaded logging use: * @code * main() { * qb_log_init("simple-log", LOG_DAEMON, LOG_INFO); * qb_log_ctl(QB_LOG_SYSLOG, QB_LOG_CONF_THREADED, QB_TRUE); * // ... * daemonize(); * // call this after you fork() * qb_log_thread_start(); * // ... * qb_log(LOG_WARNING, "watch out"); * // ... * qb_log_fini(); * } * @endcode * * @par A blackbox for in-field diagnosis. * This stores log messages in a ringbuffer so they can be written to * file if the program crashes (you will need to catch SIGSEGV). These * can then be easily printed out later. * * @note the blackbox is not enabled by default. * * Blackbox usage: * @code * * static void sigsegv_handler(int sig) * { * (void)signal (SIGSEGV, SIG_DFL); * qb_log_blackbox_write_to_file("simple-log.fdata"); * qb_log_fini(); * raise(SIGSEGV); * } * * main() { * * signal(SIGSEGV, sigsegv_handler); * * qb_log_init("simple-log", LOG_DAEMON, LOG_INFO); * 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, 1024*10); * qb_log_ctl(QB_LOG_BLACKBOX, QB_LOG_CONF_ENABLED, QB_TRUE); * // ... * qb_log(LOG_WARNING, "watch out"); * // ... * qb_log_fini(); * } * @endcode * * @par Tagging messages. * You can tag messages using the second argument to qb_logt() or * by using qb_log_filter_ctl(). * This can be used to add feature or sub-system information to the logs. * * @code * const char* my_tags_stringify(uint32_t tags) { * if (qb_bit_is_set(tags, QB_LOG_TAG_LIBQB_MSG_BIT) { * return "libqb"; * } else if (tags == 3) { * return "three"; * } else { * return "MAIN"; * } * } * main() { * // ... * qb_log_tags_stringify_fn_set(my_tags_stringify); * qb_log_format_set(QB_LOG_STDERR, "[%5g] %p %b"); * // ... * qb_logt(LOG_INFO, 3, "hello"); * qb_logt(LOG_INFO, 0, "hello"); * } * @endcode * The code above will produce: * @code * [libqb] some message * [three] info hello * [MAIN ] info hello * @endcode * * @example simplelog.c */ #undef LOG_TRACE #define LOG_TRACE (LOG_DEBUG + 1) #define QB_LOG_MAX_LEN 512 #define QB_LOG_ABSOLUTE_MAX_LEN 4096 #define QB_LOG_STRERROR_MAX_LEN 128 typedef const char *(*qb_log_tags_stringify_fn)(uint32_t tags); /** * An instance of this structure is created for each log message + * with the message-id */ struct qb_log_callsite { const char *function; const char *filename; const char *format; uint8_t priority; uint32_t lineno; uint32_t targets; uint32_t tags; + const char *message_id; } __attribute__((aligned(8))); typedef void (*qb_log_filter_fn)(struct qb_log_callsite * cs); #define QB_LOG_INIT_DATA(name) /** * Internal function: use qb_log() or qb_logt() */ void qb_log_real_(struct qb_log_callsite *cs, ...); void qb_log_real_va_(struct qb_log_callsite *cs, va_list ap); #define QB_LOG_TAG_LIBQB_MSG_BIT 31 #define QB_LOG_TAG_LIBQB_MSG (1U << QB_LOG_TAG_LIBQB_MSG_BIT) /** * This function is to import logs from other code (like libraries) * that provide a callback with their logs. * * @note the performance of this will not impress you, as * the filtering is done on each log message, not * beforehand. So try doing basic pre-filtering. * * @param function originating function name * @param filename originating filename * @param format format string * @param priority this takes syslog priorities. * @param lineno file line number * @param tags this is a uint32_t that you can use with * qb_log_tags_stringify_fn_set() to "tag" a log message * with a feature or sub-system then you can use "%g" * in the format specifer to print it out. */ void qb_log_from_external_source(const char *function, const char *filename, const char *format, uint8_t priority, uint32_t lineno, uint32_t tags, ...) __attribute__ ((format (printf, 3, 7))); /** * Get or create a callsite at the given position. * * The result can then be passed into qb_log_real_() * * @param function originating function name * @param filename originating filename * @param format format string * @param priority this takes syslog priorities. * @param lineno file line number * @param tags the tag */ struct qb_log_callsite* qb_log_callsite_get(const char *function, const char *filename, const char *format, uint8_t priority, uint32_t lineno, uint32_t tags); +/** + * Get or create a callsite at the given position. + * The same that qb_log_callsite_get but with the + * message_id parameter. + * + * The result can then be passed into qb_log_real_() + * + * @param message_id in the systemd catalog or NULL + * @param function originating function name + * @param filename originating filename + * @param format format string + * @param priority this takes syslog priorities. + * @param lineno file line number + * @param tags the tag + */ +struct qb_log_callsite* qb_log_callsite_get2(const char *message_id, + const char *function, + const char *filename, + const char *format, + uint8_t priority, + uint32_t lineno, + uint32_t tags); + +void qb_log_from_external_source_va2(const char *message_id, + const char *function, + const char *filename, + const char *format, + uint8_t priority, + uint32_t lineno, + uint32_t tags, + va_list ap) + __attribute__ ((format (printf, 4, 0))); + void qb_log_from_external_source_va(const char *function, const char *filename, const char *format, uint8_t priority, uint32_t lineno, uint32_t tags, va_list ap) __attribute__ ((format (printf, 3, 0))); /** * This is the function to generate a log message if you want to * manually add tags. * + * @param message_id in the systemd catalog or NULL * @param priority this takes syslog priorities. * @param tags this is a uint32_t that you can use with * qb_log_tags_stringify_fn_set() to "tag" a log message * with a feature or sub-system then you can use "%g" * in the format specifer to print it out. * @param fmt usual printf style format specifiers * @param args usual printf style args */ -#define qb_logt(priority, tags, fmt, args...) do { \ +#define qb_logt2(message_id, priority, tags, fmt, args...) do { \ struct qb_log_callsite* descriptor_pt = \ - qb_log_callsite_get(__func__, __FILE__, fmt, \ + qb_log_callsite_get2(message_id, __func__, __FILE__, fmt, \ priority, __LINE__, tags); \ qb_log_real_(descriptor_pt, ##args); \ } while(0) +/** + * This is the function to generate a log message if you want to + * manually add tags. + * + * @param priority this takes syslog priorities. + * @param tags this is a uint32_t that you can use with + * qb_log_tags_stringify_fn_set() to "tag" a log message + * with a feature or sub-system then you can use "%g" + * in the format specifer to print it out. + * @param fmt usual printf style format specifiers + * @param args usual printf style args + */ +#define qb_logt(priority, tags, fmt, args...) qb_logt2(NULL, priority, tags, fmt, ##args) + + +/** + * This is the main function to generate a log message. + * + * @param message_id in the systemd catalog or NULL + * @param priority this takes syslog priorities. + * @param fmt usual printf style format specifiers + * @param args usual printf style args + */ +#define qb_log2(message_id, priority, fmt, args...) qb_logt2(message_id, priority, 0, fmt, ##args) /** * This is the main function to generate a log message. * * @param priority this takes syslog priorities. * @param fmt usual printf style format specifiers * @param args usual printf style args */ #define qb_log(priority, fmt, args...) qb_logt(priority, 0, fmt, ##args) /* Define the character used to mark the beginning of "extended" information; * a string equivalent is also defined so clients can use it like: * qb_log(level, "blah blah "QB_XS" yada yada", __func__); */ #define QB_XC '\a' #define QB_XS "\a" /** * This is similar to perror except it goes into the logging system. * * @param priority this takes syslog priorities. * @param fmt usual printf style format specifiers * @param args usual printf style args * * @note Because qb_perror() adds the system error message and error number onto * the end of the given fmt, that information will become extended * information if QB_XS is used inside fmt and will not show up in any * logs that strip extended information. */ #ifndef S_SPLINT_S #define qb_perror(priority, fmt, args...) do { \ char _perr_buf_[QB_LOG_STRERROR_MAX_LEN]; \ const char *_perr_str_ = qb_strerror_r(errno, _perr_buf_, sizeof(_perr_buf_)); \ qb_logt(priority, 0, fmt ": %s (%d)", ##args, _perr_str_, errno); \ } while(0) #else #define qb_perror #endif #define qb_enter() qb_log(LOG_TRACE, "ENTERING %s()", __func__) #define qb_leave() qb_log(LOG_TRACE, "LEAVING %s()", __func__) /* * Note that QB_LOG_TARGET_{STATIC_,}MAX are sentinel indexes * as non-inclusive higher bounds of the respective categories * (static and all the log targets) and also denote the number * of (reserved) items in the category. Both are possibly subject * to change, so you should always refer to them using * these defined values. * Similarly, there are QB_LOG_TARGET_{STATIC_,DYNAMIC_,}START * and QB_LOG_TARGET_{STATIC_,DYNAMIC_,}END values, but these * are inclusive lower and higher bounds, respectively. */ enum qb_log_target_slot { QB_LOG_TARGET_START, /* static */ QB_LOG_TARGET_STATIC_START = QB_LOG_TARGET_START, QB_LOG_SYSLOG = QB_LOG_TARGET_STATIC_START, QB_LOG_STDERR, QB_LOG_BLACKBOX, QB_LOG_STDOUT, QB_LOG_TARGET_STATIC_MAX, QB_LOG_TARGET_STATIC_END = QB_LOG_TARGET_STATIC_MAX - 1, /* dynamic */ QB_LOG_TARGET_DYNAMIC_START = QB_LOG_TARGET_STATIC_MAX, QB_LOG_TARGET_MAX = 32, QB_LOG_TARGET_DYNAMIC_END = QB_LOG_TARGET_MAX - 1, QB_LOG_TARGET_END = QB_LOG_TARGET_DYNAMIC_END, }; enum qb_log_target_state { QB_LOG_STATE_UNUSED = 1, QB_LOG_STATE_DISABLED = 2, QB_LOG_STATE_ENABLED = 3, }; enum qb_log_conf { QB_LOG_CONF_ENABLED, QB_LOG_CONF_FACILITY, QB_LOG_CONF_DEBUG, QB_LOG_CONF_SIZE, QB_LOG_CONF_THREADED, QB_LOG_CONF_PRIORITY_BUMP, QB_LOG_CONF_STATE_GET, QB_LOG_CONF_FILE_SYNC, QB_LOG_CONF_EXTENDED, QB_LOG_CONF_IDENT, QB_LOG_CONF_MAX_LINE_LEN, QB_LOG_CONF_ELLIPSIS, QB_LOG_CONF_USE_JOURNAL, }; enum qb_log_filter_type { QB_LOG_FILTER_FILE, QB_LOG_FILTER_FUNCTION, QB_LOG_FILTER_FORMAT, QB_LOG_FILTER_FILE_REGEX, QB_LOG_FILTER_FUNCTION_REGEX, QB_LOG_FILTER_FORMAT_REGEX, }; enum qb_log_filter_conf { QB_LOG_FILTER_ADD, QB_LOG_FILTER_REMOVE, QB_LOG_FILTER_CLEAR_ALL, QB_LOG_TAG_SET, QB_LOG_TAG_CLEAR, QB_LOG_TAG_CLEAR_ALL, }; typedef void (*qb_log_logger_fn)(int32_t t, struct qb_log_callsite *cs, struct timespec *timestamp, const char *msg); typedef void (*qb_log_vlogger_fn)(int32_t t, struct qb_log_callsite *cs, struct timespec *timestamp, va_list ap); typedef void (*qb_log_close_fn)(int32_t t); typedef void (*qb_log_reload_fn)(int32_t t); /** * Init the logging system. * * @param name will be passed into openlog() * @param facility default for all new targets. * @param priority a basic filter with this priority will be added. */ void qb_log_init(const char *name, int32_t facility, uint8_t priority); /** * Logging system finalization function. * * It releases any shared memory. * Stops the logging thread if running. * Flushes the last messages to their destinations. */ void qb_log_fini(void); /** * If you are using dynamically loadable modules via dlopen() and * you load them after qb_log_init() then after you load the module * you will need to do the following to get the filters to work * in that module: * @code * _start = dlsym (dl_handle, QB_ATTR_SECTION_START_STR); * _stop = dlsym (dl_handle, QB_ATTR_SECTION_STOP_STR); * qb_log_callsites_register(_start, _stop); * @endcode */ int32_t qb_log_callsites_register(struct qb_log_callsite *_start, struct qb_log_callsite *_stop); /** * Dump the callsite info to stdout. */ void qb_log_callsites_dump(void); /** * Main logging control function. * * @param target QB_LOG_SYSLOG, QB_LOG_STDERR or result from qb_log_file_open() * @param conf_type configuration directive ("what to configure") that accepts * @c int32_t argument determining the new value unless ignored * for particular directive altogether * (incompatible directives: QB_LOG_CONF_IDENT) * @param arg the new value for a state-changing configuration directive, * ignored otherwise * @see qb_log_conf * * @retval -errno on error * @retval 0 on success * @retval qb_log_target_state for QB_LOG_CONF_STATE_GET */ int32_t qb_log_ctl(int32_t target, enum qb_log_conf conf_type, int32_t arg); typedef union { int32_t i32; const char *s; } qb_log_ctl2_arg_t; /** * Extension of main logging control function accepting also strings. * * @param target QB_LOG_SYSLOG, QB_LOG_STDERR or result from qb_log_file_open() * @param conf_type configuration directive ("what to configure") that accepts * either @c int32_t or a null-terminated string argument * determining the new value unless ignored for particular directive * (compatible directives: those valid for qb_log_ctl * + QB_LOG_CONF_IDENT) * @param arg the new value for a state-changing configuration directive, * ignored otherwise; for QB_LOG_CONF_IDENT, 's' member as new * identifier to openlog(), for all qb_log_ctl-compatible ones, * 'i32' member is assumed (although a preferred way is to use * that original function directly as it allows for more type safety) * @see qb_log_ctl * * @note You can use @ref QB_LOG_CTL2_I32 and @ref QB_LOG_CTL2_S macros * for a convenient on-the-fly construction of the object * to be passed as an @p arg argument. */ int32_t qb_log_ctl2(int32_t target, enum qb_log_conf conf_type, qb_log_ctl2_arg_t arg); # ifndef S_SPLINT_S #define QB_LOG_CTL2_I32(a) ((qb_log_ctl2_arg_t) { .i32 = (a) }) #define QB_LOG_CTL2_S(a) ((qb_log_ctl2_arg_t) { .s = (a) }) #else #define QB_LOG_CTL2_I32(a) ((qb_log_ctl2_arg_t)(a)) #define QB_LOG_CTL2_S(a) ((qb_log_ctl2_arg_t)(a)) #endif /** * This allows you modify the 'tags' and 'targets' callsite fields at runtime. */ int32_t qb_log_filter_ctl(int32_t value, enum qb_log_filter_conf c, enum qb_log_filter_type type, const char * text, uint8_t low_priority); /** * This extends qb_log_filter_ctl() by been able to provide a high_priority. */ int32_t qb_log_filter_ctl2(int32_t value, enum qb_log_filter_conf c, enum qb_log_filter_type type, const char * text, uint8_t high_priority, uint8_t low_priority); /** * Instead of using the qb_log_filter_ctl() functions you * can apply the filters manually by defining a callback * and setting the targets field using qb_bit_set() and * qb_bit_clear() like the following below: * @code * static void * m_filter(struct qb_log_callsite *cs) * { * if ((cs->priority >= LOG_ALERT && * cs->priority <= LOG_DEBUG) && * strcmp(cs->filename, "my_c_file.c") == 0) { * qb_bit_set(cs->targets, QB_LOG_SYSLOG); * } else { * qb_bit_clear(cs->targets, QB_LOG_SYSLOG); * } * } * @endcode */ int32_t qb_log_filter_fn_set(qb_log_filter_fn fn); /** * Set the callback to map the 'tags' bit map to a string. */ void qb_log_tags_stringify_fn_set(qb_log_tags_stringify_fn fn); /** *This is a Feature Test macro so that calling applications know that * millisecond timestamps are implemented. Because %T a string in * function call with an indirect effect, there is no easy test for it * beyond the library version (which is a very blunt instrument) */ #define QB_FEATURE_LOG_HIRES_TIMESTAMPS 1 /** * Set the format specifiers. * * \%n FUNCTION NAME * * \%f FILENAME * * \%l FILELINE * * \%p PRIORITY * * \%t TIMESTAMP * * \%T TIMESTAMP with milliseconds * * \%b BUFFER * * \%g TAGS * * \%N name (passed into qb_log_init) * * \%P PID * * \%H hostname * * Any number between % and character specify field length to pad or chop. * * @note Some of the fields are immediately evaluated and remembered * for performance reasons, so whenlog messages carry PIDs (not the default) * this function needs to be reinvoked following @c fork * (@c clone) in the respective children. When already linking * with @c libpthread, @c pthread_atfork callback registration * could be useful. */ void qb_log_format_set(int32_t t, const char* format); /** * Open a log file. * * @retval -errno on error * @retval value in inclusive range QB_LOG_TARGET_DYNAMIC_START * to QB_LOG_TARGET_DYNAMIC_END * (to be passed into other qb_log_* functions) */ int32_t qb_log_file_open(const char *filename); /** * Close a log file and release its resources. */ void qb_log_file_close(int32_t t); /** * Open a new log file for an existing target * @param t target * @param filename may be NULL to use existing file name * * @retval -errno on error * */ int32_t qb_log_file_reopen(int32_t t, const char *filename); /** * When using threaded logging set the pthread policy and priority. * * @retval -errno on error * @retval 0 success */ int32_t qb_log_thread_priority_set(int32_t policy, int32_t priority); /** * Start the logging pthread. */ int32_t qb_log_thread_start(void); /** * Write the blackbox to file. */ ssize_t qb_log_blackbox_write_to_file(const char *filename); /** * Read the blackbox for file and print it out. */ int qb_log_blackbox_print_from_file(const char* filename); /** * Open a custom log target. * * @retval -errno on error * @retval value in inclusive range QB_LOG_TARGET_DYNAMIC_START * to QB_LOG_TARGET_DYNAMIC_END * (to be passed into other qb_log_* functions) */ int32_t qb_log_custom_open(qb_log_logger_fn log_fn, qb_log_close_fn close_fn, qb_log_reload_fn reload_fn, void *user_data); /** * Close a custom log target and release its resources. */ void qb_log_custom_close(int32_t t); /** * Retrieve the user data set by either qb_log_custom_open or * qb_log_target_user_data_set. */ void *qb_log_target_user_data_get(int32_t t); /** * Associate user data with this log target. * @note only use this with custom targets */ int32_t qb_log_target_user_data_set(int32_t t, void *user_data); /** * Format the callsite and timestamp info according to the format. * set using qb_log_format_set() * It is intended to be used from your custom logger function. */ void qb_log_target_format(int32_t target, struct qb_log_callsite *cs, struct timespec *timestamp, const char* formatted_message, char *output_buffer); /** * Convert string "auth" to equivalent number "LOG_AUTH" etc. */ int32_t qb_log_facility2int(const char *fname); /** * Convert number "LOG_AUTH" to equivalent string "auth" etc. */ const char * qb_log_facility2str(int32_t fnum); /* *INDENT-OFF* */ #ifdef __cplusplus } #endif /* __cplusplus */ /* *INDENT-ON* */ #endif /* QB_LOG_H_DEFINED */ diff --git a/lib/log.c b/lib/log.c index d6074b8..4d66018 100644 --- a/lib/log.c +++ b/lib/log.c @@ -1,1135 +1,1161 @@ /* * Copyright (C) 2011 Red Hat, Inc. * * All rights reserved. * * Author: Angus Salkeld * * 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 . */ #include "os_base.h" #include #ifdef HAVE_LINK_H #include #endif /* HAVE_LINK_H */ #include #include #include #include #include #include #include #include #include #include #include "log_int.h" #include "util_int.h" #include static struct qb_log_target conf[QB_LOG_TARGET_MAX]; static uint32_t conf_active_max = 0; static int32_t in_logger = QB_FALSE; static int32_t logger_inited = QB_FALSE; static pthread_rwlock_t _listlock; static qb_log_filter_fn _custom_filter_fn = NULL; static QB_LIST_DECLARE(tags_head); static QB_LIST_DECLARE(callsite_sections); struct callsite_section { struct qb_log_callsite *start; struct qb_log_callsite *stop; struct qb_list_head list; }; static int32_t _log_target_enable(struct qb_log_target *t); static void _log_target_disable(struct qb_log_target *t); static void _log_filter_apply(struct callsite_section *sect, uint32_t t, enum qb_log_filter_conf c, enum qb_log_filter_type type, const char *text, regex_t *regex, uint8_t high_priority, uint8_t low_priority); static void _log_filter_apply_to_cs(struct qb_log_callsite *cs, uint32_t t, enum qb_log_filter_conf c, enum qb_log_filter_type type, const char *text, regex_t *regex, uint8_t high_priority, uint8_t low_priority); /* deprecated method of getting internal log messages */ static qb_util_log_fn_t old_internal_log_fn = NULL; void qb_util_set_log_function(qb_util_log_fn_t fn) { old_internal_log_fn = fn; } static void _log_free_filter(struct qb_log_filter *flt) { if (flt->regex) { regfree(flt->regex); } free(flt->regex); free(flt->text); free(flt); } static int32_t _cs_matches_filter_(struct qb_log_callsite *cs, enum qb_log_filter_type type, const char *text, regex_t *regex, uint8_t high_priority, uint8_t low_priority) { int32_t match = QB_FALSE; const char *offset = NULL; const char *next = NULL; if (cs->priority > low_priority || cs->priority < high_priority) { return QB_FALSE; } if (strcmp(text, "*") == 0) { return QB_TRUE; } switch (type) { case QB_LOG_FILTER_FILE: case QB_LOG_FILTER_FUNCTION: next = text; do { char token[500]; offset = next; next = strchrnul(offset, ','); snprintf(token, 499, "%.*s", (int)(next - offset), offset); if (type == QB_LOG_FILTER_FILE) { match = (strcmp(cs->filename, token) == 0) ? 1 : 0; } else { match = (strcmp(cs->function, token) == 0) ? 1 : 0; } if (!match && next[0] != 0) { next++; } } while (match == QB_FALSE && next != NULL && next[0] != 0); break; case QB_LOG_FILTER_FILE_REGEX: next = next ? next : cs->filename; /* fallthrough */ case QB_LOG_FILTER_FUNCTION_REGEX: next = next ? next : cs->function; /* fallthrough */ case QB_LOG_FILTER_FORMAT_REGEX: next = next ? next : cs->format; if (regex == NULL) { return QB_FALSE; } match = regexec(regex, next, 0, NULL, 0); if (match == 0) { match = QB_TRUE; } else { match = QB_FALSE; } break; case QB_LOG_FILTER_FORMAT: if (strstr(cs->format, text)) { match = QB_TRUE; } break; } return match; } /** * @internal * @brief Format a log message into a string buffer * * @param[out] str Destination buffer to contain formatted string * @param[in] cs Callsite containing format to use * @param[in] ap Variable arguments for format */ /* suppress suggestion that we currently can do nothing better about as the format specification is hidden in cs argument */ #ifdef HAVE_GCC_FORMAT_COMPLAINTS #pragma GCC diagnostic push #ifdef HAVE_GCC_MISSING_FORMAT_ATTRIBUTE #pragma GCC diagnostic ignored "-Wmissing-format-attribute" #endif #ifdef HAVE_GCC_SUGGEST_ATTRIBUTE_FORMAT #pragma GCC diagnostic ignored "-Wsuggest-attribute=format" #endif #endif static inline void cs_format(char *str, size_t maxlen, struct qb_log_callsite *cs, va_list ap) { va_list ap_copy; int len; va_copy(ap_copy, ap); len = vsnprintf(str, maxlen, cs->format, ap_copy); va_end(ap_copy); if (len > maxlen) { len = maxlen; } if (str[len - 1] == '\n') { str[len - 1] = '\0'; } } #ifdef HAVE_GCC_FORMAT_COMPLAINTS #pragma GCC diagnostic pop #endif void qb_log_real_va_(struct qb_log_callsite *cs, va_list ap) { int32_t found_threaded = QB_FALSE; struct qb_log_target *t; struct timespec tv; enum qb_log_target_slot pos; size_t max_line_length = 0; int32_t formatted = QB_FALSE; char buf[QB_LOG_MAX_LEN]; char *str = buf; va_list ap_copy; if (qb_atomic_int_compare_and_exchange(&in_logger, QB_FALSE, QB_TRUE) == QB_FALSE || cs == NULL) { return; } /* 0 Work out the longest line length available */ for (pos = QB_LOG_TARGET_START; pos <= conf_active_max; pos++) { t = &conf[pos]; if ((t->state == QB_LOG_STATE_ENABLED) && qb_bit_is_set(cs->targets, pos)) { if (t->max_line_length > max_line_length) { max_line_length = t->max_line_length; } } } if (max_line_length > QB_LOG_MAX_LEN) { str = malloc(max_line_length); if (!str) { return; } } if (old_internal_log_fn && qb_bit_is_set(cs->tags, QB_LOG_TAG_LIBQB_MSG_BIT)) { if (formatted == QB_FALSE) { cs_format(str, max_line_length, cs, ap); formatted = QB_TRUE; } qb_do_extended(str, QB_TRUE, old_internal_log_fn(cs->filename, cs->lineno, cs->priority, str)); } qb_util_timespec_from_epoch_get(&tv); /* * 1 if we can find a threaded target that needs this log then post it * 2 foreach non-threaded target call it's logger function */ for (pos = QB_LOG_TARGET_START; pos <= conf_active_max; pos++) { t = &conf[pos]; if ((t->state == QB_LOG_STATE_ENABLED) && qb_bit_is_set(cs->targets, pos)) { if (t->threaded) { if (!found_threaded) { found_threaded = QB_TRUE; if (formatted == QB_FALSE) { cs_format(str, max_line_length, cs, ap); formatted = QB_TRUE; } } } else if (t->vlogger) { va_copy(ap_copy, ap); t->vlogger(t->pos, cs, &tv, ap_copy); va_end(ap_copy); } else if (t->logger) { if (formatted == QB_FALSE) { cs_format(str, max_line_length, cs, ap); formatted = QB_TRUE; } qb_do_extended(str, t->extended, t->logger(t->pos, cs, &tv, str)); } } } if (found_threaded) { qb_log_thread_log_post(cs, &tv, str); } qb_atomic_int_set(&in_logger, QB_FALSE); if (max_line_length > QB_LOG_MAX_LEN) { free(str); } } void qb_log_real_(struct qb_log_callsite *cs, ...) { va_list ap; va_start(ap, cs); qb_log_real_va_(cs, ap); va_end(ap); } void qb_log_thread_log_write(struct qb_log_callsite *cs, struct timespec *timestamp, const char *buffer) { struct qb_log_target *t; enum qb_log_target_slot pos; for (pos = QB_LOG_TARGET_START; pos <= conf_active_max; pos++) { t = &conf[pos]; if ((t->state == QB_LOG_STATE_ENABLED) && t->threaded && qb_bit_is_set(cs->targets, t->pos)) { qb_do_extended(buffer, t->extended, t->logger(t->pos, cs, timestamp, buffer)); } } } struct qb_log_callsite* -qb_log_callsite_get(const char *function, +qb_log_callsite_get2(const char *message_id, + const char *function, const char *filename, const char *format, uint8_t priority, uint32_t lineno, uint32_t tags) { struct qb_log_target *t; struct qb_log_filter *flt; struct qb_log_callsite *cs; int32_t new_dcs = QB_FALSE; struct qb_list_head *f_item; enum qb_log_target_slot pos; if (!logger_inited) { return NULL; } - cs = qb_log_dcs_get(&new_dcs, function, filename, - format, priority, lineno, tags); + cs = qb_log_dcs_get(&new_dcs, message_id, function, filename, + format, priority, lineno, tags); + if (cs == NULL) { return NULL; } if (new_dcs) { pthread_rwlock_rdlock(&_listlock); for (pos = QB_LOG_TARGET_START; pos <= conf_active_max; pos++) { t = &conf[pos]; if (t->state != QB_LOG_STATE_ENABLED) { continue; } qb_list_for_each(f_item, &t->filter_head) { flt = qb_list_entry(f_item, struct qb_log_filter, list); _log_filter_apply_to_cs(cs, t->pos, flt->conf, flt->type, flt->text, flt->regex, flt->high_priority, flt->low_priority); } } if (tags == 0) { qb_list_for_each(f_item, &tags_head) { flt = qb_list_entry(f_item, struct qb_log_filter, list); _log_filter_apply_to_cs(cs, flt->new_value, flt->conf, flt->type, flt->text, flt->regex, flt->high_priority, flt->low_priority); } } else { cs->tags = tags; } if (_custom_filter_fn) { _custom_filter_fn(cs); } pthread_rwlock_unlock(&_listlock); } else { if (tags && cs->tags != tags) { cs->tags = tags; } if (_custom_filter_fn) { _custom_filter_fn(cs); } } return cs; } +struct qb_log_callsite* +qb_log_callsite_get(const char *function, + const char *filename, + const char *format, + uint8_t priority, + uint32_t lineno, + uint32_t tags) +{ + return qb_log_callsite_get2(NULL, function, filename, format, + priority, lineno, tags); +} + void -qb_log_from_external_source_va(const char *function, +qb_log_from_external_source_va2(const char *message_id, + const char *function, const char *filename, const char *format, uint8_t priority, uint32_t lineno, uint32_t tags, va_list ap) { struct qb_log_callsite *cs; if (!logger_inited) { return; } - cs = qb_log_callsite_get(function, filename, + cs = qb_log_callsite_get2(message_id, function, filename, format, priority, lineno, tags); qb_log_real_va_(cs, ap); } +void +qb_log_from_external_source_va(const char *function, + const char *filename, + const char *format, + uint8_t priority, + uint32_t lineno, uint32_t tags, va_list ap) +{ + qb_log_from_external_source_va2(NULL, function, filename, + format, priority, lineno, tags, ap); +} + void qb_log_from_external_source(const char *function, const char *filename, const char *format, uint8_t priority, uint32_t lineno, uint32_t tags, ...) { struct qb_log_callsite *cs; va_list ap; if (!logger_inited) { return; } cs = qb_log_callsite_get(function, filename, format, priority, lineno, tags); va_start(ap, tags); qb_log_real_va_(cs, ap); va_end(ap); } static void qb_log_callsites_dump_sect(struct callsite_section *sect) { struct qb_log_callsite *cs; printf(" start %p - stop %p\n", sect->start, sect->stop); printf("filename lineno targets tags\n"); for (cs = sect->start; cs < sect->stop; cs++) { if (cs->lineno > 0) { #ifndef S_SPLINT_S printf("%12s %6" PRIu32 " %16" PRIu32 " %16u\n", cs->filename, cs->lineno, cs->targets, cs->tags); #endif /* S_SPLINT_S */ } } } int32_t qb_log_callsites_register(struct qb_log_callsite *_start, struct qb_log_callsite *_stop) { struct callsite_section *sect; struct qb_log_callsite *cs; struct qb_log_target *t; struct qb_log_filter *flt; enum qb_log_target_slot pos; if (_start == NULL || _stop == NULL) { return -EINVAL; } pthread_rwlock_rdlock(&_listlock); qb_list_for_each_entry(sect, &callsite_sections, list) { if (sect->start == _start || sect->stop == _stop) { pthread_rwlock_unlock(&_listlock); return -EEXIST; } } pthread_rwlock_unlock(&_listlock); sect = calloc(1, sizeof(struct callsite_section)); if (sect == NULL) { return -ENOMEM; } sect->start = _start; sect->stop = _stop; qb_list_init(§->list); pthread_rwlock_wrlock(&_listlock); qb_list_add(§->list, &callsite_sections); /* * Now apply the filters on these new callsites */ for (pos = QB_LOG_TARGET_START; pos <= conf_active_max; pos++) { t = &conf[pos]; if (t->state != QB_LOG_STATE_ENABLED) { continue; } qb_list_for_each_entry(flt, &t->filter_head, list) { _log_filter_apply(sect, t->pos, flt->conf, flt->type, flt->text, flt->regex, flt->high_priority, flt->low_priority); } } qb_list_for_each_entry(flt, &tags_head, list) { _log_filter_apply(sect, flt->new_value, flt->conf, flt->type, flt->text, flt->regex, flt->high_priority, flt->low_priority); } pthread_rwlock_unlock(&_listlock); if (_custom_filter_fn) { for (cs = sect->start; cs < sect->stop; cs++) { if (cs->lineno > 0) { _custom_filter_fn(cs); } } } /* qb_log_callsites_dump_sect(sect); */ return 0; } void qb_log_callsites_dump(void) { struct callsite_section *sect; int32_t l; pthread_rwlock_rdlock(&_listlock); l = qb_list_length(&callsite_sections); printf("Callsite Database [%d]\n", l); printf("---------------------\n"); qb_list_for_each_entry(sect, &callsite_sections, list) { qb_log_callsites_dump_sect(sect); } pthread_rwlock_unlock(&_listlock); } static int32_t _log_filter_exists(struct qb_list_head *list_head, enum qb_log_filter_type type, const char *text, uint8_t high_priority, uint8_t low_priority, uint32_t new_value) { struct qb_log_filter *flt; qb_list_for_each_entry(flt, list_head, list) { if (flt->type == type && flt->high_priority == high_priority && flt->low_priority == low_priority && flt->new_value == new_value && strcmp(flt->text, text) == 0) { return QB_TRUE; } } return QB_FALSE; } static int32_t _log_filter_store(uint32_t t, enum qb_log_filter_conf c, enum qb_log_filter_type type, const char *text, uint8_t high_priority, uint8_t low_priority, struct qb_log_filter **new) { struct qb_log_filter *flt; struct qb_list_head *iter; struct qb_list_head *next; struct qb_list_head *list_head; switch (c) { case QB_LOG_FILTER_ADD: case QB_LOG_FILTER_REMOVE: case QB_LOG_FILTER_CLEAR_ALL: list_head = &conf[t].filter_head; break; case QB_LOG_TAG_SET: case QB_LOG_TAG_CLEAR: case QB_LOG_TAG_CLEAR_ALL: list_head = &tags_head; break; default: return -ENOSYS; } if (c == QB_LOG_FILTER_ADD || c == QB_LOG_TAG_SET) { if (text == NULL) { return -EINVAL; } if (_log_filter_exists(list_head, type, text, high_priority, low_priority, t)) { return -EEXIST; } flt = calloc(1, sizeof(struct qb_log_filter)); if (flt == NULL) { return -ENOMEM; } qb_list_init(&flt->list); flt->conf = c; flt->type = type; flt->text = strdup(text); if (flt->text == NULL) { _log_free_filter(flt); return -ENOMEM; } if (type == QB_LOG_FILTER_FUNCTION_REGEX || type == QB_LOG_FILTER_FILE_REGEX || type == QB_LOG_FILTER_FORMAT_REGEX) { int res; flt->regex = calloc(1, sizeof(regex_t)); if (flt->regex == NULL) { _log_free_filter(flt); return -ENOMEM; } res = regcomp(flt->regex, flt->text, 0); if (res) { _log_free_filter(flt); return -EINVAL; } } flt->high_priority = high_priority; flt->low_priority = low_priority; flt->new_value = t; qb_list_add_tail(&flt->list, list_head); if (new) { *new = flt; } } else if (c == QB_LOG_FILTER_REMOVE || c == QB_LOG_TAG_CLEAR) { qb_list_for_each_safe(iter, next, list_head) { flt = qb_list_entry(iter, struct qb_log_filter, list); if (flt->type == type && flt->low_priority <= low_priority && flt->high_priority >= high_priority && (strcmp(flt->text, text) == 0 || strcmp("*", text) == 0)) { qb_list_del(iter); _log_free_filter(flt); return 0; } } } else if (c == QB_LOG_FILTER_CLEAR_ALL || c == QB_LOG_TAG_CLEAR_ALL) { qb_list_for_each_safe(iter, next, list_head) { flt = qb_list_entry(iter, struct qb_log_filter, list); qb_list_del(iter); _log_free_filter(flt); } } return 0; } static void _log_filter_apply(struct callsite_section *sect, uint32_t t, enum qb_log_filter_conf c, enum qb_log_filter_type type, const char *text, regex_t *regex, uint8_t high_priority, uint8_t low_priority) { struct qb_log_callsite *cs; for (cs = sect->start; cs < sect->stop; cs++) { if (cs->lineno > 0) { _log_filter_apply_to_cs(cs, t, c, type, text, regex, high_priority, low_priority); } } } /* #define _QB_FILTER_DEBUGGING_ 1 */ static void _log_filter_apply_to_cs(struct qb_log_callsite *cs, uint32_t t, enum qb_log_filter_conf c, enum qb_log_filter_type type, const char *text, regex_t *regex, uint8_t high_priority, uint8_t low_priority) { if (c == QB_LOG_FILTER_CLEAR_ALL) { qb_bit_clear(cs->targets, t); return; } else if (c == QB_LOG_TAG_CLEAR_ALL) { cs->tags = 0; return; } if (_cs_matches_filter_(cs, type, text, regex, high_priority, low_priority)) { #ifdef _QB_FILTER_DEBUGGING_ uint32_t old_targets = cs->targets; uint32_t old_tags = cs->tags; #endif /* _QB_FILTER_DEBUGGING_ */ if (c == QB_LOG_FILTER_ADD) { qb_bit_set(cs->targets, t); } else if (c == QB_LOG_FILTER_REMOVE) { qb_bit_clear(cs->targets, t); } else if (c == QB_LOG_TAG_SET) { cs->tags = t; } else if (c == QB_LOG_TAG_CLEAR) { cs->tags = 0; } #ifdef _QB_FILTER_DEBUGGING_ if (old_targets != cs->targets) { printf("targets: %s:%u value(%d) %d -> %d\n", cs->filename, cs->lineno, t, old_targets, cs->targets); } if (old_tags != cs->tags) { printf("tags: %s:%u value(%d) %d -> %d\n", cs->filename, cs->lineno, t, old_tags, cs->tags); } #endif /* _QB_FILTER_DEBUGGING_ */ } } int32_t qb_log_filter_ctl2(int32_t t, enum qb_log_filter_conf c, enum qb_log_filter_type type, const char * text, uint8_t high_priority, uint8_t low_priority) { struct qb_log_filter *new_flt = NULL; regex_t *regex = NULL; struct callsite_section *sect; int32_t rc; if (!logger_inited) { return -EINVAL; } if (c == QB_LOG_FILTER_ADD || c == QB_LOG_FILTER_CLEAR_ALL || c == QB_LOG_FILTER_REMOVE) { if (t < 0 || t >= QB_LOG_TARGET_MAX || conf[t].state == QB_LOG_STATE_UNUSED) { return -EBADF; } } if (text == NULL || low_priority < high_priority || type > QB_LOG_FILTER_FORMAT_REGEX || c > QB_LOG_TAG_CLEAR_ALL) { return -EINVAL; } pthread_rwlock_rdlock(&_listlock); rc = _log_filter_store(t, c, type, text, high_priority, low_priority, &new_flt); if (rc < 0) { pthread_rwlock_unlock(&_listlock); return rc; } if (new_flt && new_flt->regex) { regex = new_flt->regex; } qb_list_for_each_entry(sect, &callsite_sections, list) { _log_filter_apply(sect, t, c, type, text, regex, high_priority, low_priority); } pthread_rwlock_unlock(&_listlock); return 0; } int32_t qb_log_filter_fn_set(qb_log_filter_fn fn) { struct callsite_section *sect; struct qb_log_callsite *cs; if (!logger_inited) { return -EINVAL; } _custom_filter_fn = fn; if (_custom_filter_fn == NULL) { return 0; } qb_list_for_each_entry(sect, &callsite_sections, list) { for (cs = sect->start; cs < sect->stop; cs++) { if (cs->lineno > 0) { _custom_filter_fn(cs); } } } return 0; } int32_t qb_log_filter_ctl(int32_t t, enum qb_log_filter_conf c, enum qb_log_filter_type type, const char *text, uint8_t priority) { return qb_log_filter_ctl2(t, c, type, text, LOG_EMERG, priority); } static void _log_target_state_set(struct qb_log_target *t, enum qb_log_target_state s) { enum qb_log_target_slot i; int32_t a_set = QB_FALSE; int32_t u_set = QB_FALSE; t->state = s; for (i = QB_LOG_TARGET_MAX; i > QB_LOG_TARGET_START; i--) { if (!a_set && conf[i-1].state == QB_LOG_STATE_ENABLED) { a_set = QB_TRUE; conf_active_max = i-1; } if (!u_set && conf[i-1].state != QB_LOG_STATE_UNUSED) { u_set = QB_TRUE; } } } void qb_log_init(const char *name, int32_t facility, uint8_t priority) { int32_t l; enum qb_log_target_slot i; l = pthread_rwlock_init(&_listlock, NULL); assert(l == 0); qb_log_format_init(); for (i = QB_LOG_TARGET_START; i < QB_LOG_TARGET_MAX; i++) { conf[i].pos = i; conf[i].debug = QB_FALSE; conf[i].file_sync = QB_FALSE; conf[i].extended = QB_TRUE; conf[i].state = QB_LOG_STATE_UNUSED; (void)strlcpy(conf[i].name, name, PATH_MAX); conf[i].facility = facility; conf[i].max_line_length = QB_LOG_MAX_LEN; qb_list_init(&conf[i].filter_head); } qb_log_dcs_init(); for (i = QB_LOG_TARGET_STATIC_START; i < QB_LOG_TARGET_STATIC_MAX; i++) conf[i].state = QB_LOG_STATE_DISABLED; logger_inited = QB_TRUE; (void)qb_log_syslog_open(&conf[QB_LOG_SYSLOG]); _log_target_state_set(&conf[QB_LOG_SYSLOG], QB_LOG_STATE_ENABLED); (void)qb_log_filter_ctl(QB_LOG_SYSLOG, QB_LOG_FILTER_ADD, QB_LOG_FILTER_FILE, "*", priority); } void qb_log_fini(void) { struct qb_log_target *t; struct qb_log_filter *flt; struct callsite_section *s; struct qb_list_head *iter; struct qb_list_head *iter2; struct qb_list_head *next; struct qb_list_head *next2; enum qb_log_target_slot pos; if (!logger_inited) { return; } logger_inited = QB_FALSE; qb_log_thread_stop(); pthread_rwlock_destroy(&_listlock); for (pos = QB_LOG_TARGET_START; pos <= conf_active_max; pos++) { t = &conf[pos]; _log_target_disable(t); qb_list_for_each_safe(iter2, next2, &t->filter_head) { flt = qb_list_entry(iter2, struct qb_log_filter, list); qb_list_del(iter2); _log_free_filter(flt); } } qb_log_format_fini(); qb_log_dcs_fini(); qb_list_for_each_safe(iter, next, &callsite_sections) { s = qb_list_entry(iter, struct callsite_section, list); qb_list_del(iter); free(s); } qb_list_for_each_safe(iter, next, &tags_head) { flt = qb_list_entry(iter, struct qb_log_filter, list); qb_list_del(iter); _log_free_filter(flt); } } struct qb_log_target * qb_log_target_alloc(void) { enum qb_log_target_slot i; for (i = QB_LOG_TARGET_START; i < QB_LOG_TARGET_MAX; i++) { if (conf[i].state == QB_LOG_STATE_UNUSED) { _log_target_state_set(&conf[i], QB_LOG_STATE_DISABLED); return &conf[i]; } } errno = EMFILE; return NULL; } void qb_log_target_free(struct qb_log_target *t) { (void)qb_log_filter_ctl(t->pos, QB_LOG_FILTER_CLEAR_ALL, QB_LOG_FILTER_FILE, NULL, 0); t->debug = QB_FALSE; t->filename[0] = '\0'; qb_log_format_set(t->pos, NULL); _log_target_state_set(t, QB_LOG_STATE_UNUSED); } struct qb_log_target * qb_log_target_get(int32_t pos) { return &conf[pos]; } void * qb_log_target_user_data_get(int32_t t) { if (t < 0 || t >= QB_LOG_TARGET_MAX || conf[t].state == QB_LOG_STATE_UNUSED) { errno = EBADF; return NULL; } return conf[t].instance; } int32_t qb_log_target_user_data_set(int32_t t, void *user_data) { if (!logger_inited) { return -EINVAL; } if (t < 0 || t >= QB_LOG_TARGET_MAX || conf[t].state == QB_LOG_STATE_UNUSED) { return -EBADF; } conf[t].instance = user_data; return 0; } int32_t qb_log_custom_open(qb_log_logger_fn log_fn, qb_log_close_fn close_fn, qb_log_reload_fn reload_fn, void *user_data) { struct qb_log_target *t; t = qb_log_target_alloc(); if (t == NULL) { return -errno; } t->instance = user_data; #ifndef S_SPLINT_S snprintf(t->filename, PATH_MAX, "custom-%" PRIu32, t->pos); #endif /* S_SPLINT_S */ t->logger = log_fn; t->vlogger = NULL; t->reload = reload_fn; t->close = close_fn; return t->pos; } void qb_log_custom_close(int32_t t) { struct qb_log_target *target; if (!logger_inited) { return; } if (t < 0 || t >= QB_LOG_TARGET_MAX || conf[t].state == QB_LOG_STATE_UNUSED) { return; } target = qb_log_target_get(t); if (target->close) { qb_atomic_int_set(&in_logger, QB_TRUE); target->close(t); qb_atomic_int_set(&in_logger, QB_FALSE); } qb_log_target_free(target); } static int32_t _log_target_enable(struct qb_log_target *t) { int32_t rc = 0; if (t->state == QB_LOG_STATE_ENABLED) { return 0; } if (t->pos == QB_LOG_STDERR || t->pos == QB_LOG_STDOUT) { rc = qb_log_stderr_open(t); } else if (t->pos == QB_LOG_SYSLOG) { rc = qb_log_syslog_open(t); } else if (t->pos == QB_LOG_BLACKBOX) { rc = qb_log_blackbox_open(t); } if (rc == 0) { _log_target_state_set(t, QB_LOG_STATE_ENABLED); } return rc; } static void _log_target_disable(struct qb_log_target *t) { if (t->state != QB_LOG_STATE_ENABLED) { return; } _log_target_state_set(t, QB_LOG_STATE_DISABLED); if (t->close) { qb_atomic_int_set(&in_logger, QB_TRUE); t->close(t->pos); qb_atomic_int_set(&in_logger, QB_FALSE); } } int32_t qb_log_ctl2(int32_t t, enum qb_log_conf c, qb_log_ctl2_arg_t arg_not4directuse) { int32_t rc = 0; int32_t need_reload = QB_FALSE; /* extract the constants and do not touch the origin anymore */ const int32_t arg_i32 = arg_not4directuse.i32; const char * const arg_s = arg_not4directuse.s; if (!logger_inited) { return -EINVAL; } if (t < 0 || t >= QB_LOG_TARGET_MAX || conf[t].state == QB_LOG_STATE_UNUSED) { return -EBADF; } /* Starting/stopping the thread has its own locking that can interfere with this */ if (c != QB_LOG_CONF_THREADED) { qb_log_thread_pause(&conf[t]); } switch (c) { case QB_LOG_CONF_ENABLED: if (arg_i32) { rc = _log_target_enable(&conf[t]); } else { _log_target_disable(&conf[t]); } break; case QB_LOG_CONF_STATE_GET: rc = conf[t].state; break; case QB_LOG_CONF_FACILITY: conf[t].facility = arg_i32; if (t == QB_LOG_SYSLOG) { need_reload = QB_TRUE; } break; case QB_LOG_CONF_IDENT: (void)strlcpy(conf[t].name, arg_s, PATH_MAX); if (t == QB_LOG_SYSLOG) { need_reload = QB_TRUE; } break; case QB_LOG_CONF_FILE_SYNC: conf[t].file_sync = arg_i32; break; case QB_LOG_CONF_PRIORITY_BUMP: conf[t].priority_bump = arg_i32; break; case QB_LOG_CONF_SIZE: if (t == QB_LOG_BLACKBOX) { if (arg_i32 <= 0) { rc = -EINVAL; goto unlock_fini; } conf[t].size = arg_i32; need_reload = QB_TRUE; } else { rc = -ENOSYS; } break; case QB_LOG_CONF_THREADED: conf[t].threaded = arg_i32; break; case QB_LOG_CONF_EXTENDED: conf[t].extended = arg_i32; break; case QB_LOG_CONF_MAX_LINE_LEN: /* arbitrary limit, but you'd be insane to go further */ if (arg_i32 > QB_LOG_ABSOLUTE_MAX_LEN) { rc = -EINVAL; } else { conf[t].max_line_length = arg_i32; } break; case QB_LOG_CONF_ELLIPSIS: conf[t].ellipsis = arg_i32; break; case QB_LOG_CONF_USE_JOURNAL: #ifdef USE_JOURNAL if (t == QB_LOG_SYSLOG) { conf[t].use_journal = arg_i32; need_reload = QB_TRUE; } else { rc = -EINVAL; } #else rc = -EOPNOTSUPP; #endif break; default: rc = -EINVAL; } if (rc == 0 && need_reload && conf[t].reload) { qb_atomic_int_set(&in_logger, QB_TRUE); conf[t].reload(t); qb_atomic_int_set(&in_logger, QB_FALSE); } unlock_fini: if (c != QB_LOG_CONF_THREADED) { qb_log_thread_resume(&conf[t]); } return rc; } int32_t qb_log_ctl(int32_t t, enum qb_log_conf c, int32_t arg) { return qb_log_ctl2(t, c, QB_LOG_CTL2_I32(arg)); } diff --git a/lib/log_dcs.c b/lib/log_dcs.c index e8e3b6f..1021a84 100644 --- a/lib/log_dcs.c +++ b/lib/log_dcs.c @@ -1,220 +1,226 @@ /* * Copyright (C) 2011 Red Hat, Inc. * * All rights reserved. * * Author: Angus Salkeld * * 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 . */ #include "os_base.h" #include #ifdef HAVE_LINK_H #include #endif #include #include #include #include #include #include "log_int.h" static qb_array_t *lookup_arr = NULL; static qb_array_t *callsite_arr = NULL; static uint32_t callsite_arr_next = 0; static uint32_t callsite_elems_per_bin = 0; static qb_thread_lock_t *arr_next_lock = NULL; struct callsite_list { struct qb_log_callsite *cs; struct callsite_list *next; }; static void _log_register_callsites(qb_array_t * a, uint32_t bin) { struct qb_log_callsite *start; struct qb_log_callsite *stop; int32_t rc = qb_array_index(callsite_arr, bin * callsite_elems_per_bin, (void **)&start); if (rc == 0) { stop = &start[callsite_elems_per_bin]; rc = qb_log_callsites_register(start, stop); assert(rc == 0); } } static struct qb_log_callsite * -_log_dcs_new_cs(const char *function, +_log_dcs_new_cs(const char *message_id, + const char *function, const char *filename, const char *format, uint8_t priority, uint32_t lineno, uint32_t tags) { struct qb_log_callsite *cs; int32_t rc = qb_array_index(callsite_arr, callsite_arr_next++, (void **)&cs); assert(rc == 0); assert(cs != NULL); + cs->message_id = message_id ? strdup(message_id) : NULL; cs->function = strdup(function); cs->filename = strdup(filename); cs->format = strdup(format); cs->priority = priority; cs->lineno = lineno; cs->tags = tags; return cs; } struct qb_log_callsite * qb_log_dcs_get(int32_t * newly_created, + const char *message_id, const char *function, const char *filename, const char *format, uint8_t priority, uint32_t lineno, uint32_t tags) { int32_t rc; struct qb_log_callsite *cs = NULL; struct callsite_list *csl_head; struct callsite_list *csl_last = NULL; struct callsite_list *csl; const char *safe_filename = filename; const char *safe_function = function; const char *safe_format = format; if (filename == NULL) { safe_filename = ""; } if (function == NULL) { safe_function = ""; } if (format == NULL) { safe_format = ""; } /* * try the fastest access first. */ rc = qb_array_index(lookup_arr, lineno, (void **)&csl_head); assert(rc == 0); /* * Still need to lock here as we are reading from cs->* members * and they might not be completely filled in yet by another thread * that's running in _log_dcs_new_cs() below */ (void)qb_thread_lock(arr_next_lock); if (csl_head->cs && priority == csl_head->cs->priority && + (message_id ? (strcmp(message_id, csl_head->cs->message_id) == 0) : 1) && strcmp(safe_filename, csl_head->cs->filename) == 0 && strcmp(safe_format, csl_head->cs->format) == 0) { (void)qb_thread_unlock(arr_next_lock); return csl_head->cs; } /* * so we will either have to create it or go through a list */ if (csl_head->cs == NULL) { - csl_head->cs = _log_dcs_new_cs(safe_function, safe_filename, safe_format, + csl_head->cs = _log_dcs_new_cs(message_id, safe_function, + safe_filename, safe_format, priority, lineno, tags); cs = csl_head->cs; csl_head->next = NULL; *newly_created = QB_TRUE; } else { for (csl = csl_head; csl; csl = csl->next) { assert(csl->cs->lineno == lineno); if (priority == csl->cs->priority && strcmp(safe_format, csl->cs->format) == 0 && strcmp(safe_filename, csl->cs->filename) == 0) { cs = csl->cs; break; } csl_last = csl; } if (cs == NULL) { csl = calloc(1, sizeof(struct callsite_list)); if (csl == NULL) { goto cleanup; } - csl->cs = _log_dcs_new_cs(safe_function, safe_filename, safe_format, + csl->cs = _log_dcs_new_cs(message_id, safe_function, + safe_filename, safe_format, priority, lineno, tags); csl->next = NULL; csl_last->next = csl; cs = csl->cs; *newly_created = QB_TRUE; } } cleanup: (void)qb_thread_unlock(arr_next_lock); return cs; } void qb_log_dcs_init(void) { int32_t rc; lookup_arr = qb_array_create_2(16, sizeof(struct callsite_list), 1); callsite_arr = qb_array_create_2(16, sizeof(struct qb_log_callsite), 1); arr_next_lock = qb_thread_lock_create(QB_THREAD_LOCK_SHORT); callsite_elems_per_bin = qb_array_elems_per_bin_get(callsite_arr); rc = qb_array_new_bin_cb_set(callsite_arr, _log_register_callsites); assert(rc == 0); } void qb_log_dcs_fini(void) { struct callsite_list *csl_head; struct callsite_list *csl_next; struct callsite_list *csl; int32_t i; int32_t rc; struct qb_log_callsite *cs = NULL; int32_t cnt = qb_array_num_bins_get(lookup_arr); cnt *= qb_array_elems_per_bin_get(lookup_arr); for (i = 0; i < cnt; i++) { rc = qb_array_index(lookup_arr, i, (void **)&csl_head); if (rc != 0 || csl_head->next == NULL) { continue; } for (csl = csl_head->next; csl; csl = csl_next) { csl_next = csl->next; free(csl); } } for (i = 0; i < callsite_arr_next; i++) { rc = qb_array_index(callsite_arr, i, (void **)&cs); if (rc == 0 && cs){ free((char*)cs->function); free((char*)cs->filename); free((char*)cs->format); } } qb_array_free(lookup_arr); qb_array_free(callsite_arr); (void)qb_thread_lock_destroy(arr_next_lock); } diff --git a/lib/log_int.h b/lib/log_int.h index 9ae818f..3d17fd6 100644 --- a/lib/log_int.h +++ b/lib/log_int.h @@ -1,144 +1,145 @@ /* * Copyright (C) 2011 Red Hat, Inc. * * All rights reserved. * * Author: Angus Salkeld * * 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 . */ #ifndef _QB_LOG_INT_H_ #define _QB_LOG_INT_H_ #include #include #include #include struct qb_log_target; struct qb_log_target { uint32_t pos; enum qb_log_target_state state; char name[PATH_MAX]; char filename[PATH_MAX]; struct qb_list_head filter_head; int32_t facility; int32_t priority_bump; int32_t file_sync; int32_t debug; int32_t extended; int32_t use_journal; size_t size; size_t max_line_length; int32_t ellipsis; char *format; int32_t threaded; void *instance; qb_log_reload_fn reload; qb_log_close_fn close; qb_log_logger_fn logger; qb_log_vlogger_fn vlogger; }; struct qb_log_filter { enum qb_log_filter_conf conf; enum qb_log_filter_type type; char *text; uint8_t high_priority; uint8_t low_priority; uint32_t new_value; struct qb_list_head list; regex_t *regex; }; struct qb_log_record { struct qb_log_callsite *cs; struct timespec timestamp; char *buffer; struct qb_list_head list; }; #define TIME_STRING_SIZE 64 /** * @internal * @brief Call a log function, handling any extended information marker * * If the string to be passed to the log function contains an extended * information marker, temporarily modify the string to strip the extended * information if appropriate. Special cases: if a marker occurs with nothing * after it, it will always be stripped; if only extended information is * present, stmt will be called only if extended is true. * * @param[in] str Null-terminated log message * @param[in] extended QB_TRUE if extended information should be printed * @param[in] stmt Code block to call log function * * @note Because this is a macro, none of the arguments other than stmt should * have side effects. */ #define qb_do_extended(str, extended, stmt) do { \ char *qb_xc = strchr((str), QB_XC); \ if (qb_xc) { \ if ((qb_xc != (str)) || (extended)) { \ *qb_xc = ((extended) && *(qb_xc + 1))? '|' : '\0'; \ stmt; \ *qb_xc = QB_XC; \ } \ } else { \ stmt; \ } \ } while (0) struct qb_log_target * qb_log_target_alloc(void); void qb_log_target_free(struct qb_log_target *t); struct qb_log_target * qb_log_target_get(int32_t pos); int32_t qb_log_syslog_open(struct qb_log_target *t); int32_t qb_log_stderr_open(struct qb_log_target *t); int32_t qb_log_blackbox_open(struct qb_log_target *t); void qb_log_thread_stop(void); void qb_log_thread_log_post(struct qb_log_callsite *cs, struct timespec *current_time, const char *buffer); void qb_log_thread_log_write(struct qb_log_callsite *cs, struct timespec *current_time, const char *buffer); void qb_log_thread_pause(struct qb_log_target *t); void qb_log_thread_resume(struct qb_log_target *t); void qb_log_dcs_init(void); void qb_log_dcs_fini(void); struct qb_log_callsite *qb_log_dcs_get(int32_t *newly_created, + const char *message_id, const char *function, const char *filename, const char *format, uint8_t priority, uint32_t lineno, uint32_t tags); void qb_log_format_init(void); void qb_log_format_fini(void); const char * qb_log_priority2str(uint8_t priority); size_t qb_vsnprintf_serialize(char *serialize, size_t max_len, const char *fmt, va_list ap); size_t qb_vsnprintf_deserialize(char *string, size_t str_len, const char *buf); void qb_log_target_format_static(int32_t target, const char * format, char *output_buffer); #endif /* _QB_LOG_INT_H_ */ diff --git a/lib/log_syslog.c b/lib/log_syslog.c index b1b8246..f7a68bf 100644 --- a/lib/log_syslog.c +++ b/lib/log_syslog.c @@ -1,117 +1,128 @@ /* * Copyright (C) 2011 Red Hat, Inc. * * All rights reserved. * * Author: Angus Salkeld * * 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 . */ #include "os_base.h" #ifdef HAVE_SYSLOG_H #include #endif /* HAVE_SYSLOG_H */ #ifdef USE_JOURNAL #define SD_JOURNAL_SUPPRESS_LOCATION #include #endif #include "log_int.h" static void _syslog_logger(int32_t target, struct qb_log_callsite *cs, struct timespec *timestamp, const char *msg) { char buffer[QB_LOG_MAX_LEN]; char *output_buffer = buffer; struct qb_log_target *t = qb_log_target_get(target); int32_t final_priority = cs->priority; if (final_priority > LOG_INFO) { /* * only bump the priority if it is greater than info. */ final_priority += t->priority_bump; } if (final_priority > LOG_DEBUG) { return; } if (t->max_line_length > QB_LOG_MAX_LEN) { output_buffer = malloc(t->max_line_length); if (!output_buffer) { return; } } output_buffer[0] = '\0'; qb_log_target_format(target, cs, timestamp, msg, output_buffer); if (final_priority < LOG_EMERG) { final_priority = LOG_EMERG; } #ifdef USE_JOURNAL if (t->use_journal) { - sd_journal_send("PRIORITY=%d", final_priority, + if (cs->message_id) { + sd_journal_send("MESSAGE_ID=%s", cs->message_id, + "PRIORITY=%d", final_priority, "CODE_LINE=%d", cs->lineno, "CODE_FILE=%s", cs->filename, "CODE_FUNC=%s", cs->function, "SYSLOG_IDENTIFIER=%s", t->name, "MESSAGE=%s", output_buffer, NULL); + } else { + sd_journal_send("PRIORITY=%d", final_priority, + "CODE_LINE=%d", cs->lineno, + "CODE_FILE=%s", cs->filename, + "CODE_FUNC=%s", cs->function, + "SYSLOG_IDENTIFIER=%s", t->name, + "MESSAGE=%s", output_buffer, + NULL); + } } else { #endif syslog(final_priority, "%s", output_buffer); #ifdef USE_JOURNAL } #endif if (t->max_line_length > QB_LOG_MAX_LEN) { free(output_buffer); } } static void _syslog_close(int32_t target) { struct qb_log_target *t = qb_log_target_get(target); if (!t->use_journal) { closelog(); } } static void _syslog_reload(int32_t target) { struct qb_log_target *t = qb_log_target_get(target); closelog(); if (!t->use_journal) { openlog(t->name, LOG_PID, t->facility); } } int32_t qb_log_syslog_open(struct qb_log_target *t) { t->logger = _syslog_logger; t->reload = _syslog_reload; t->close = _syslog_close; if (!t->use_journal) { openlog(t->name, LOG_PID, t->facility); } return 0; } diff --git a/tests/check_log.c b/tests/check_log.c index 994bda9..039a4bb 100644 --- a/tests/check_log.c +++ b/tests/check_log.c @@ -1,1132 +1,1136 @@ /* * Copyright (c) 2011-2015 Red Hat, Inc. * * All rights reserved. * * Author: Angus Salkeld * * 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 . */ #include "os_base.h" #include #include "check_common.h" #include #include #include #ifdef USE_JOURNAL #include #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"); 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_log(LOG_ERR, "Test message 1 from libqb"); + 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; }