Author: aconway Date: Tue May 13 14:23:51 2014 New Revision: 1594235 URL: http://svn.apache.org/r1594235 Log: QPID-DISPATCH-16: Improve logging for dispatch
Patches provided by Rajith Attapattu on https://issues.apache.org/jira/browse/DISPATCH-16 - separately configurable logging levels for each module. - config stubs for syslog & file based logging (not yet implemented.) Made some modifications: Simplified schema: - single configuration section "log", to set defaults use "log : { module:DEFAULT, ... }" - shorter names for configuration items (print_to_stderr->stderr etc.) - simplified config logic. Changed correct but unintuitive bit mask logic: bits in mask were levels NOT selected. - Flipped it around. Only log ERROR and above before log system is configured. Avoid annoying INFO log message leakage to stderr. Modified: qpid/dispatch/trunk/include/qpid/dispatch/config.h qpid/dispatch/trunk/include/qpid/dispatch/dispatch.h qpid/dispatch/trunk/include/qpid/dispatch/log.h qpid/dispatch/trunk/python/qpid_dispatch_internal/config/parser.py qpid/dispatch/trunk/python/qpid_dispatch_internal/config/schema.py qpid/dispatch/trunk/router/src/main.c qpid/dispatch/trunk/src/config.c qpid/dispatch/trunk/src/dispatch.c qpid/dispatch/trunk/src/log.c qpid/dispatch/trunk/tests/compose_test.c qpid/dispatch/trunk/tests/parse_test.c qpid/dispatch/trunk/tests/server_test.c qpid/dispatch/trunk/tests/system_tests_broker.py Modified: qpid/dispatch/trunk/include/qpid/dispatch/config.h URL: http://svn.apache.org/viewvc/qpid/dispatch/trunk/include/qpid/dispatch/config.h?rev=1594235&r1=1594234&r2=1594235&view=diff ============================================================================== --- qpid/dispatch/trunk/include/qpid/dispatch/config.h (original) +++ qpid/dispatch/trunk/include/qpid/dispatch/config.h Tue May 13 14:23:51 2014 @@ -27,8 +27,11 @@ */ #include <qpid/dispatch/dispatch.h> #include <stdint.h> +#include <stdbool.h> +void qd_log_configure(const qd_dispatch_t *dispatch); int qd_config_item_count(const qd_dispatch_t *dispatch, const char *section); +bool qd_config_item_exists(const qd_dispatch_t *dispatch, const char *section, int index, const char* key); const char *qd_config_item_value_string(const qd_dispatch_t *dispatch, const char *section, int index, const char* key); uint32_t qd_config_item_value_int(const qd_dispatch_t *dispatch, const char *section, int index, const char* key); int qd_config_item_value_bool(const qd_dispatch_t *dispatch, const char *section, int index, const char* key); Modified: qpid/dispatch/trunk/include/qpid/dispatch/dispatch.h URL: http://svn.apache.org/viewvc/qpid/dispatch/trunk/include/qpid/dispatch/dispatch.h?rev=1594235&r1=1594234&r2=1594235&view=diff ============================================================================== --- qpid/dispatch/trunk/include/qpid/dispatch/dispatch.h (original) +++ qpid/dispatch/trunk/include/qpid/dispatch/dispatch.h Tue May 13 14:23:51 2014 @@ -94,6 +94,14 @@ void qd_dispatch_prepare(qd_dispatch_t * */ void qd_dispatch_post_configure_connections(qd_dispatch_t *dispatch); +/** + * \brief Configure the logging module from the + * parsed configuration file. This must be called after the + * call to qd_dispatch_prepare completes. + * + * @param dispatch The dispatch handle returned by qd_dispatch + */ +void qd_dispatch_configure_logging(qd_dispatch_t *qd); /** * @} Modified: qpid/dispatch/trunk/include/qpid/dispatch/log.h URL: http://svn.apache.org/viewvc/qpid/dispatch/trunk/include/qpid/dispatch/log.h?rev=1594235&r1=1594234&r2=1594235&view=diff ============================================================================== --- qpid/dispatch/trunk/include/qpid/dispatch/log.h (original) +++ qpid/dispatch/trunk/include/qpid/dispatch/log.h Tue May 13 14:23:51 2014 @@ -32,9 +32,7 @@ typedef struct qd_log_source_t qd_log_so qd_log_source_t* qd_log_source(const char *module); -void qd_log_impl(qd_log_source_t *source, int cls, const char *file, int line, const char *fmt, ...); +void qd_log_impl(qd_log_source_t *source, int level, const char *file, int line, const char *fmt, ...); #define qd_log(s, c, f, ...) qd_log_impl(s, c, __FILE__, __LINE__, f , ##__VA_ARGS__) -void qd_log_set_mask(int mask); - #endif Modified: qpid/dispatch/trunk/python/qpid_dispatch_internal/config/parser.py URL: http://svn.apache.org/viewvc/qpid/dispatch/trunk/python/qpid_dispatch_internal/config/parser.py?rev=1594235&r1=1594234&r2=1594235&view=diff ============================================================================== --- qpid/dispatch/trunk/python/qpid_dispatch_internal/config/parser.py (original) +++ qpid/dispatch/trunk/python/qpid_dispatch_internal/config/parser.py Tue May 13 14:23:51 2014 @@ -211,13 +211,12 @@ class DispatchConfig: self.raw_config = None self.config = None self.schema = None - self.log = LogAdapter('config.parser') + self.log = LogAdapter('CONFIG') def read_file(self, path): self.schema = Schema() try: - self.log.log(LOG_INFO, "Reading Configuration File: %s" % path) cfile = open(path) text = cfile.read() cfile.close() @@ -227,8 +226,8 @@ class DispatchConfig: self._validate_raw_config() self._process_schema() self._validate() - except Exception, E: - self.log.log(LOG_CRITICAL, "Exception in Configuration File Processing: %r" % E) + except Exception, e: + self.log.log(LOG_CRITICAL, "Error in configuration file '%s': %r" % (path, e)) raise Modified: qpid/dispatch/trunk/python/qpid_dispatch_internal/config/schema.py URL: http://svn.apache.org/viewvc/qpid/dispatch/trunk/python/qpid_dispatch_internal/config/schema.py?rev=1594235&r1=1594234&r2=1594235&view=diff ============================================================================== --- qpid/dispatch/trunk/python/qpid_dispatch_internal/config/schema.py (original) +++ qpid/dispatch/trunk/python/qpid_dispatch_internal/config/schema.py Tue May 13 14:23:51 2014 @@ -86,6 +86,15 @@ config_schema = { 'ra-interval' : (int, None, '', 30, None), 'remote-ls-max-age' : (int, None, '', 60, None), 'mobile-addr-max-age' : (int, None, '', 60, None) + }), + 'log' : (False, { + 'module' : (str, None, 'M', None, None), + 'level' : (str, None, '', 'INFO', ['NONE', 'TRACE', 'DEBUG', 'INFO', 'NOTICE', 'WARNING', 'ERROR', 'CRITICAL']), + 'timestamp' : (bool, None, '', True, None), + 'stderr' : (bool, None, '', True, None), + 'syslog' : (bool, None, '', False, None), + 'file' : (str, None, '', None, None), # File name + 'max-size' : (int, None, "", 1024, None), # Max file size }) } Modified: qpid/dispatch/trunk/router/src/main.c URL: http://svn.apache.org/viewvc/qpid/dispatch/trunk/router/src/main.c?rev=1594235&r1=1594234&r2=1594235&view=diff ============================================================================== --- qpid/dispatch/trunk/router/src/main.c (original) +++ qpid/dispatch/trunk/router/src/main.c Tue May 13 14:23:51 2014 @@ -131,11 +131,11 @@ int main(int argc, char **argv) } } - qd_log_set_mask(0xFFFFFFFE); dispatch = qd_dispatch(python_pkgdir); qd_dispatch_extend_config_schema(dispatch, app_config); qd_dispatch_load_config(dispatch, config_path); + qd_log_configure(dispatch); qd_dispatch_configure_container(dispatch); qd_dispatch_configure_router(dispatch); qd_dispatch_prepare(dispatch); Modified: qpid/dispatch/trunk/src/config.c URL: http://svn.apache.org/viewvc/qpid/dispatch/trunk/src/config.c?rev=1594235&r1=1594234&r2=1594235&view=diff ============================================================================== --- qpid/dispatch/trunk/src/config.c (original) +++ qpid/dispatch/trunk/src/config.c Tue May 13 14:23:51 2014 @@ -220,6 +220,14 @@ static PyObject *item_value(const qd_dis } +bool qd_config_item_exists(const qd_dispatch_t *dispatch, const char *section, int index, const char* key) +{ + PyObject *pResult = item_value(dispatch, section, index, key, "value_string"); + bool exists = pResult; + if (pResult) Py_DECREF(pResult); + return exists; +} + const char *qd_config_item_value_string(const qd_dispatch_t *dispatch, const char *section, int index, const char* key) { PyObject *pResult = item_value(dispatch, section, index, key, "value_string"); Modified: qpid/dispatch/trunk/src/dispatch.c URL: http://svn.apache.org/viewvc/qpid/dispatch/trunk/src/dispatch.c?rev=1594235&r1=1594234&r2=1594235&view=diff ============================================================================== --- qpid/dispatch/trunk/src/dispatch.c (original) +++ qpid/dispatch/trunk/src/dispatch.c Tue May 13 14:23:51 2014 @@ -160,4 +160,3 @@ void qd_dispatch_post_configure_connecti qd_connection_manager_start(qd); qd_waypoint_activate_all(qd); } - Modified: qpid/dispatch/trunk/src/log.c URL: http://svn.apache.org/viewvc/qpid/dispatch/trunk/src/log.c?rev=1594235&r1=1594234&r2=1594235&view=diff ============================================================================== --- qpid/dispatch/trunk/src/log.c (original) +++ qpid/dispatch/trunk/src/log.c Tue May 13 14:23:51 2014 @@ -18,7 +18,9 @@ */ #include "log_private.h" +#include <qpid/dispatch/config.h> #include <qpid/dispatch/ctools.h> +#include <qpid/dispatch/dispatch.h> #include <qpid/dispatch/alloc.h> #include <qpid/dispatch/threading.h> #include <stdarg.h> @@ -28,13 +30,14 @@ #define TEXT_MAX 512 #define LIST_MAX 1000 +#define LOG_MAX 640 typedef struct qd_log_entry_t qd_log_entry_t; struct qd_log_entry_t { DEQ_LINKS(qd_log_entry_t); const char *module; - int cls; + int level; const char *file; int line; time_t time; @@ -48,12 +51,13 @@ DEQ_DECLARE(qd_log_entry_t, qd_log_list_ struct qd_log_source_t { DEQ_LINKS(qd_log_source_t); - const char *module_name; - //int mask; - //int print_timestamp; - //int print_to_stderr; - //int print_to_file; - //int print_to_syslog; + const char *module; + int mask; + int timestamp; + int print; + int stderr; + char* file; + int syslog; //FILE *file; }; @@ -62,46 +66,110 @@ DEQ_DECLARE(qd_log_source_t, qd_log_sour static qd_log_list_t entries; static sys_mutex_t *log_lock = 0; +static sys_mutex_t *log_source_lock = 0; static qd_log_source_list_t source_list; -static int mask = QD_LOG_INFO; +static qd_log_source_t *default_log_source=0; +static qd_log_source_t *logging_log_source=0; -static const char *cls_prefix(int cls) -{ - switch (cls) { - case QD_LOG_TRACE : return "TRACE"; - case QD_LOG_DEBUG : return "DEBUG"; - case QD_LOG_INFO : return "INFO"; - case QD_LOG_NOTICE : return "NOTICE"; - case QD_LOG_WARNING : return "WARNING"; - case QD_LOG_ERROR : return "ERROR"; - case QD_LOG_CRITICAL : return "CRITICAL"; +static const int nlevels = 7; +static const char* level_names[]={"TRACE", "DEBUG", "INFO", "NOTICE", "WARNING", "ERROR", "CRITICAL"}; +static const int level_bits[] ={QD_LOG_TRACE, QD_LOG_DEBUG, QD_LOG_INFO, QD_LOG_NOTICE, QD_LOG_WARNING, QD_LOG_ERROR, QD_LOG_CRITICAL}; +static const int all_bits = ((QD_LOG_CRITICAL-1) | QD_LOG_CRITICAL); + +static const char *level_str(int level) { + if (level == 0) return "NONE"; + int i = 0; + while (i < nlevels && level_bits[i] != level) ++i; + return (i == nlevels) ? "NONE" : level_names[i]; +} + + +static int get_mask(const char *level) { + if (strcasecmp(level, "NONE") == 0) return 0; + int i = 0; + while (i < nlevels && strcasecmp(level_names[i], level) != 0) ++i; + if (i == nlevels) { + qd_log(logging_log_source, QD_LOG_ERROR, "'%s' is not a valid log level. Should be one of {NONE, TRACE, DEBUG, INFO, NOTICE, WARNING, ERROR, CRITICAL}. Defaulting to INFO", level); + return get_mask("INFO"); } + return all_bits & ~(level_bits[i]-1); +} - return ""; +/// Caller must hold log_source_lock +static qd_log_source_t* lookup_log_source_lh(const char *module) +{ + if (strcasecmp(module, "DEFAULT") == 0) + return default_log_source; + qd_log_source_t *src = DEQ_HEAD(source_list); + while(src && strcasecmp(module, src->module) != 0) + src = DEQ_NEXT(src); + return src; +} + +static void write_log(qd_log_source_t *log_source, const char *fmt, ...) +{ + int stderr_ = log_source->stderr == -1 ? default_log_source->stderr : log_source->stderr; + int syslog = log_source->syslog == -1 ? default_log_source->syslog : log_source->syslog; + const char* file = log_source->file == 0 ? default_log_source->file : log_source->file; + + if (!(stderr_ || syslog || file)) return; + + char log_str[LOG_MAX]; + va_list arglist; + va_start(arglist, fmt); + vsnprintf(log_str, LOG_MAX, fmt, arglist); + va_end(arglist); + + if (stderr_) fputs(log_str, stderr); + /* FIXME aconway 2014-05-12: unfinished + if (syslog) ... + if (file) ... + */ +} + +/// Caller must hold the log_source_lock +static qd_log_source_t *qd_log_source_lh(const char *module) +{ + qd_log_source_t *log_source = lookup_log_source_lh(module); + if (!log_source) + { + log_source = NEW(qd_log_source_t); + memset(log_source, 0, sizeof(qd_log_source_t)); + DEQ_ITEM_INIT(log_source); + log_source->module = module; + log_source->mask = -1; + log_source->timestamp = -1; + log_source->stderr = -1; + log_source->syslog = -1; + log_source->file = 0; + DEQ_INSERT_TAIL(source_list, log_source); + } + return log_source; } qd_log_source_t *qd_log_source(const char *module) { - qd_log_source_t *source = NEW(qd_log_source_t); - memset(source, 0, sizeof(qd_log_source_t)); - DEQ_ITEM_INIT(source); - source->module_name = module; - - // TODO - Configure the source + sys_mutex_lock(log_source_lock); + qd_log_source_t* src = qd_log_source_lh(module); + sys_mutex_unlock(log_source_lock); + return src; +} - return source; +void qd_log_source_free(qd_log_source_t* src) { + free(src->file); + free(src); } -void qd_log_impl(qd_log_source_t *source, int cls, const char *file, int line, const char *fmt, ...) +void qd_log_impl(qd_log_source_t *source, int level, const char *file, int line, const char *fmt, ...) { - if (!(cls & mask)) - return; + int mask = source->mask == -1 ? default_log_source->mask : source->mask; + if (!(level & mask)) return; qd_log_entry_t *entry = new_qd_log_entry_t(); DEQ_ITEM_INIT(entry); - entry->module = source->module_name; - entry->cls = cls; - entry->file = file; + entry->module = source->module; + entry->level = level; + entry->file = file ? strdup(file) : 0; entry->line = line; time(&entry->time); @@ -113,7 +181,7 @@ void qd_log_impl(qd_log_source_t *source va_end(ap); ctime_r(&entry->time, ctime); ctime[24] = '\0'; - fprintf(stderr, "%s %s (%s) %s\n", ctime, entry->module, cls_prefix(cls), entry->text); + write_log(source, "%s %s (%s) %s\n", ctime, entry->module, level_str(level), entry->text); sys_mutex_lock(log_lock); DEQ_INSERT_TAIL(entries, entry); @@ -125,22 +193,61 @@ void qd_log_impl(qd_log_source_t *source sys_mutex_unlock(log_lock); } -void qd_log_set_mask(int _mask) -{ - mask = _mask; -} - - void qd_log_initialize(void) { DEQ_INIT(entries); DEQ_INIT(source_list); log_lock = sys_mutex(); + log_source_lock = sys_mutex(); + + default_log_source = NEW(qd_log_source_t); + memset(default_log_source, 0, sizeof(qd_log_source_t)); + default_log_source->module = "DEFAULT"; + // Only report errors until we have configured the logging system. + default_log_source->mask = get_mask("ERROR"); + default_log_source->timestamp = 1; + default_log_source->stderr = 1; + default_log_source->syslog = 0; + default_log_source->file = 0; + logging_log_source = qd_log_source("LOGGING"); } -void qd_log_finalize(void) -{ +void qd_log_finalize(void) { + for (qd_log_source_t *src = DEQ_HEAD(source_list); src != 0; src = DEQ_HEAD(source_list)) { + DEQ_REMOVE_HEAD(source_list); + qd_log_source_free(src); + } } +///@return 0,1 or -1 if not present +static int get_optional_bool(const qd_dispatch_t *qd, const char* item, int i, const char* name) { + if (!qd_config_item_exists(qd, item, i, name)) return -1; + return qd_config_item_value_bool(qd, item, i, name); +} + +#define ITEM_STRING(NAME) qd_config_item_value_string(qd, "log", i, NAME) +#define ITEM_OPT_BOOL(NAME) get_optional_bool(qd, "log", i, NAME) + +void qd_log_configure(const qd_dispatch_t *qd) +{ + if (!qd) return; + // Default to INFO now that we are configuring the logging system. + default_log_source->mask = get_mask("INFO"); + int count = qd_config_item_count(qd, "log"); + for (int i=0; i < count; i++) { + sys_mutex_lock(log_source_lock); + const char* module = ITEM_STRING("module"); + qd_log_source_t *src = qd_log_source_lh(module); + src->module = ITEM_STRING("module"); + src->mask = get_mask(ITEM_STRING("level")); + src->timestamp = ITEM_OPT_BOOL("timestamp"); + src->stderr = ITEM_OPT_BOOL("stderr"); + src->syslog = ITEM_OPT_BOOL("syslog"); + const char* file = ITEM_STRING("file"); + src->file = file ? strdup(file) : 0; + sys_mutex_unlock(log_source_lock); + } + qd_log(logging_log_source, QD_LOG_INFO, "Logging system configured"); +} Modified: qpid/dispatch/trunk/tests/compose_test.c URL: http://svn.apache.org/viewvc/qpid/dispatch/trunk/tests/compose_test.c?rev=1594235&r1=1594234&r2=1594235&view=diff ============================================================================== --- qpid/dispatch/trunk/tests/compose_test.c (original) +++ qpid/dispatch/trunk/tests/compose_test.c Tue May 13 14:23:51 2014 @@ -281,7 +281,6 @@ static char *test_compose_scalars(void * int compose_tests() { int result = 0; - qd_log_set_mask(QD_LOG_NONE); TEST_CASE(test_compose_list_of_maps, 0); TEST_CASE(test_compose_nested_composites, 0); Modified: qpid/dispatch/trunk/tests/parse_test.c URL: http://svn.apache.org/viewvc/qpid/dispatch/trunk/tests/parse_test.c?rev=1594235&r1=1594234&r2=1594235&view=diff ============================================================================== --- qpid/dispatch/trunk/tests/parse_test.c (original) +++ qpid/dispatch/trunk/tests/parse_test.c Tue May 13 14:23:51 2014 @@ -156,7 +156,6 @@ static char *test_parser_errors(void *co int parse_tests() { int result = 0; - qd_log_set_mask(QD_LOG_NONE); TEST_CASE(test_parser_fixed_scalars, 0); TEST_CASE(test_parser_errors, 0); Modified: qpid/dispatch/trunk/tests/server_test.c URL: http://svn.apache.org/viewvc/qpid/dispatch/trunk/tests/server_test.c?rev=1594235&r1=1594234&r2=1594235&view=diff ============================================================================== --- qpid/dispatch/trunk/tests/server_test.c (original) +++ qpid/dispatch/trunk/tests/server_test.c Tue May 13 14:23:51 2014 @@ -206,7 +206,6 @@ int server_tests(const char *_config_fil { int result = 0; test_lock = sys_mutex(); - qd_log_set_mask(QD_LOG_NONE); config_file = _config_file; Modified: qpid/dispatch/trunk/tests/system_tests_broker.py URL: http://svn.apache.org/viewvc/qpid/dispatch/trunk/tests/system_tests_broker.py?rev=1594235&r1=1594234&r2=1594235&view=diff ============================================================================== --- qpid/dispatch/trunk/tests/system_tests_broker.py (original) +++ qpid/dispatch/trunk/tests/system_tests_broker.py Tue May 13 14:23:51 2014 @@ -48,6 +48,8 @@ class BrokerSystemTest(TestCase): # Start a qdrouterd router_conf = Qdrouterd.Config([ + ('log', { 'module':'DEFAULT', 'level':'TRACE' }), + ('container', {'container-name':self.id()}), ('container', {'container-name':self.id()}), ('router', { 'mode': 'standalone', 'router-id': self.id() }), ('listener', {'addr':'0.0.0.0', 'port':self.get_port()}), --------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
