From 0e60e9c063277164b02d6ddad5a00c6ef8224d1f Mon Sep 17 00:00:00 2001 From: Peter Hutterer Date: Thu, 9 Sep 2021 14:32:43 +1000 Subject: [PATCH] spa: add topic-based logging Add a struct spa_log_topic that allows for logical grouping of messages. The new macros spa_log_logt() and spa_log_logtv() take a topic as argument, the topic's level acts as filter. A new macro spa_log_topic_init() initializes a topic. By default a topic inherits its logger's debug level but a logger implementation may set that topic to a specific fixed log level. The various spa_log_*() macros transparently wrap new and old implementations: - if the implementation is version 0, the new logt() calls drop the topic and get routed into the old log() calls - if the implementation is version 1, the old log() calls use a NULL topic and get routed into the new logt() calls All spa_log_* macros use the SPA_LOG_DEFAULT_TOPIC topic (NULL), it is up to the caller to redefine that. Alternatively, use spa_logt_* to pass an explicit topic. There is one crucial flaw in this implementation: log topics are initialized to their target level by the current logger. Where a topic is initialized but the logger is switched later, the topic is not automatically re-initialized. Ultimately this shouldn't matter for real-world use-cases. --- spa/include/spa/support/log.h | 183 +++++++++++++++++++++++++++-- spa/include/spa/utils/defs.h | 2 + test/meson.build | 1 + test/test-spa-log.c | 213 ++++++++++++++++++++++++++++++++++ 4 files changed, 387 insertions(+), 12 deletions(-) create mode 100644 test/test-spa-log.c diff --git a/spa/include/spa/support/log.h b/spa/include/spa/support/log.h index 46bbdd88e..bcc260242 100644 --- a/spa/include/spa/support/log.h +++ b/spa/include/spa/support/log.h @@ -43,6 +43,17 @@ extern "C" { * \{ */ +/** The default log topic. Redefine this in your code to + * allow for the spa_log_* macros to work correctly, e.g: + * + * \code{.c} + * struct spa_log_topic *mylogger; + * #undef SPA_LOG_TOPIC_DEFAULT + * #define SPA_LOG_TOPIC_DEFAULT mylogger + * \endcode + */ +#define SPA_LOG_TOPIC_DEFAULT NULL + enum spa_log_level { SPA_LOG_LEVEL_NONE = 0, SPA_LOG_LEVEL_ERROR, @@ -69,12 +80,41 @@ struct spa_log { enum spa_log_level level; }; +/** + * \struct spa_log_topic + * + * Identifier for a topic. Topics are string-based filters that logically + * group messages together. An implementation may decide to filter different + * topics on different levels, for example the "protocol" topic may require + * debug level TRACE while the "core" topic defaults to debug level INFO. + * + * spa_log_topics require a spa_log_methods version of 1 or higher. + */ +struct spa_log_topic { +#define SPA_VERSION_LOG_TOPIC 0 + /** the version of this topic. This can be used to expand this + * structure in the future */ + uint32_t version; + /** The string identifier for the topic */ + const char *topic; + /** Logging level set for this topic */ + enum spa_log_level level; + /** False if this topic follows the \ref spa_log level */ + bool has_custom_level; +}; + struct spa_log_methods { -#define SPA_VERSION_LOG_METHODS 0 +#define SPA_VERSION_LOG_METHODS 0 +/* version 1: added logt and logtv */ +#define SPA_VERSION_LOG_METHODS_LOGT 1 uint32_t version; /** * Log a message with the given log level. * + * \note If compiled with this header, this function is only called + * for implementations of version 0. For versions 1 and above, see + * logt() instead. + * * \param log a spa_log * \param level a spa_log_level * \param file the file name @@ -93,6 +133,10 @@ struct spa_log_methods { /** * Log a message with the given log level. * + * \note If compiled with this header, this function is only called + * for implementations of version 0. For versions 1 and above, see + * logtv() instead. + * * \param log a spa_log * \param level a spa_log_level * \param file the file name @@ -108,34 +152,148 @@ struct spa_log_methods { const char *func, const char *fmt, va_list args) SPA_PRINTF_FUNC(6, 0); + /** + * Log a message with the given log level for the given topic. + * + * \note Callers that do not use topic-based logging (version 0), the \a + * topic is NULL + * + * \param log a spa_log + * \param level a spa_log_level + * \param topic the topic for this message, may be NULL + * \param file the file name + * \param line the line number + * \param func the function name + * \param fmt printf style format + * \param ... format arguments + * + * \since 1 + */ + void (*logt) (void *object, + enum spa_log_level level, + const struct spa_log_topic *topic, + const char *file, + int line, + const char *func, + const char *fmt, ...) SPA_PRINTF_FUNC(7, 8); + + /** + * Log a message with the given log level for the given topic. + * + * \note For callers that do not use topic-based logging (version 0), + * the \a topic is NULL + * + * \param log a spa_log + * \param level a spa_log_level + * \param topic the topic for this message, may be NULL + * \param file the file name + * \param line the line number + * \param func the function name + * \param fmt printf style format + * \param args format arguments + * + * \since 1 + */ + void (*logtv) (void *object, + enum spa_log_level level, + const struct spa_log_topic *topic, + const char *file, + int line, + const char *func, + const char *fmt, + va_list args) SPA_PRINTF_FUNC(7, 0); + + /** + * Initializes a \ref spa_log_topic to the correct logging level. + * + * \since 1 + */ + void (*topic_init) (void *object, struct spa_log_topic *topic); }; + +#define SPA_LOG_TOPIC(v, t) \ + (struct spa_log_topic){ .version = v, .topic = (t)} + +#define spa_log_topic_init(l, topic) \ +do { \ + struct spa_log *_l = l; \ + if (SPA_LIKELY(_l)) { \ + struct spa_interface *_if = &_l->iface; \ + spa_interface_call(_if, struct spa_log_methods, \ + topic_init, 1, topic); \ + } \ +} while(0) + +/* Unused, left for backwards compat */ #define spa_log_level_enabled(l,lev) ((l) && (l)->level >= (lev)) -#define spa_log_log(l,lev,...) \ +#define spa_log_level_topic_enabled(l,topic,lev) \ ({ \ - struct spa_log *_l = l; \ - if (SPA_UNLIKELY(spa_log_level_enabled(_l, lev))) \ - spa_interface_call(&_l->iface, \ - struct spa_log_methods, log, 0, lev, \ - __VA_ARGS__); \ + struct spa_log *_log = l; \ + enum spa_log_level _lev = _log ? _log->level : SPA_LOG_LEVEL_NONE; \ + struct spa_log_topic *_t = (struct spa_log_topic *)topic; \ + if (_t && _t->has_custom_level) \ + _lev = _t->level; \ + _lev >= lev; \ }) -#define spa_log_logv(l,lev,...) \ +/* Transparently calls to version 0 log if v1 is not supported */ +#define spa_log_logt(l,lev,topic,...) \ ({ \ struct spa_log *_l = l; \ - if (SPA_UNLIKELY(spa_log_level_enabled(_l, lev))) \ - spa_interface_call(&_l->iface, \ - struct spa_log_methods, logv, 0, lev, \ - __VA_ARGS__); \ + struct spa_interface *_if = &_l->iface; \ + if (SPA_UNLIKELY(spa_log_level_topic_enabled(_l, topic, lev))) { \ + if (spa_interface_callback_version_min( \ + _if, struct spa_log_methods, 1)) \ + spa_interface_call(_if, \ + struct spa_log_methods, logt, 1, \ + lev, topic, \ + __VA_ARGS__); \ + else \ + spa_interface_call(_if, \ + struct spa_log_methods, log, 0, \ + lev, __VA_ARGS__); \ + } \ }) +/* Transparently calls to version 0 logv if v1 is not supported */ +#define spa_log_logtv(l,lev,topic,...) \ +({ \ + struct spa_log *_l = l; \ + struct spa_interface *_if = &_l->iface; \ + if (SPA_UNLIKELY(spa_log_level_topic_enabled(_l, topic, lev))) { \ + if (spa_interface_callback_version_min( \ + _if, struct spa_log_methods, 1)) \ + spa_interface_call(_if, \ + struct spa_log_methods, logtv, 1, \ + lev, topic, \ + __VA_ARGS__); \ + else \ + spa_interface_call(_if, \ + struct spa_log_methods, logv, 0, \ + lev, __VA_ARGS__); \ + } \ +}) + +#define spa_log_log(l,lev,...) \ + spa_log_logt(l,lev,SPA_LOG_TOPIC_DEFAULT,__VA_ARGS__) + +#define spa_log_logv(l,lev,...) \ + spa_log_logtv(l,lev,SPA_LOG_TOPIC_DEFAULT,__VA_ARGS__) + #define spa_log_error(l,...) spa_log_log(l,SPA_LOG_LEVEL_ERROR,__FILE__,__LINE__,__func__,__VA_ARGS__) #define spa_log_warn(l,...) spa_log_log(l,SPA_LOG_LEVEL_WARN,__FILE__,__LINE__,__func__,__VA_ARGS__) #define spa_log_info(l,...) spa_log_log(l,SPA_LOG_LEVEL_INFO,__FILE__,__LINE__,__func__,__VA_ARGS__) #define spa_log_debug(l,...) spa_log_log(l,SPA_LOG_LEVEL_DEBUG,__FILE__,__LINE__,__func__,__VA_ARGS__) #define spa_log_trace(l,...) spa_log_log(l,SPA_LOG_LEVEL_TRACE,__FILE__,__LINE__,__func__,__VA_ARGS__) +#define spa_logt_error(l,t,...) spa_log_logt(l,SPA_LOG_LEVEL_ERROR,t,__FILE__,__LINE__,__func__,__VA_ARGS__) +#define spa_logt_warn(l,t,...) spa_log_logt(l,SPA_LOG_LEVEL_WARN,t,__FILE__,__LINE__,__func__,__VA_ARGS__) +#define spa_logt_info(l,t,...) spa_log_logt(l,SPA_LOG_LEVEL_INFO,t,__FILE__,__LINE__,__func__,__VA_ARGS__) +#define spa_logt_debug(l,t,...) spa_log_logt(l,SPA_LOG_LEVEL_DEBUG,t,__FILE__,__LINE__,__func__,__VA_ARGS__) +#define spa_logt_trace(l,t,...) spa_log_logt(l,SPA_LOG_LEVEL_TRACE,t,__FILE__,__LINE__,__func__,__VA_ARGS__) + #ifndef FASTPATH #define spa_log_trace_fp(l,...) spa_log_log(l,SPA_LOG_LEVEL_TRACE,__FILE__,__LINE__,__func__,__VA_ARGS__) #else @@ -151,6 +309,7 @@ struct spa_log_methods { * stderr. */ #define SPA_KEY_LOG_TIMESTAMP "log.timestamp" /**< log timestamps */ #define SPA_KEY_LOG_LINE "log.line" /**< log file and line numbers */ +#define SPA_KEY_LOG_PATTERNS "log.patterns" /**< Spa:String:JSON array of [ {"pattern" : level}, ... ] */ /** * \} diff --git a/spa/include/spa/utils/defs.h b/spa/include/spa/utils/defs.h index f55117b45..08c550e73 100644 --- a/spa/include/spa/utils/defs.h +++ b/spa/include/spa/utils/defs.h @@ -207,6 +207,7 @@ struct spa_fraction { #define SPA_SENTINEL __attribute__((__sentinel__)) #define SPA_UNUSED __attribute__ ((unused)) #define SPA_NORETURN __attribute__ ((noreturn)) +#define SPA_WEAK __attribute__ ((weak)) #else #define SPA_PRINTF_FUNC(fmt, arg1) #define SPA_FORMAT_ARG_FUNC(arg1) @@ -216,6 +217,7 @@ struct spa_fraction { #define SPA_SENTINEL #define SPA_UNUSED #define SPA_NORETURN +/* SPA_WEAK intentionally undef here */ #endif #if defined(__STDC_VERSION__) && __STDC_VERSION__ >= 199901L diff --git a/test/meson.build b/test/meson.build index 7fe118ed7..d8906e0ec 100644 --- a/test/meson.build +++ b/test/meson.build @@ -96,6 +96,7 @@ test('test spa', 'test-spa-buffer.c', 'test-spa-json.c', 'test-spa-utils.c', + 'test-spa-log.c', 'test-spa-node.c', 'test-spa-pod.c', include_directories: pwtest_inc, diff --git a/test/test-spa-log.c b/test/test-spa-log.c new file mode 100644 index 000000000..4bcc76bf6 --- /dev/null +++ b/test/test-spa-log.c @@ -0,0 +1,213 @@ +/* Simple Plugin API + * Copyright © 2021 Red Hat, Inc. + * + * Permission is hereby granted, free of charge, to any person obtaining a + * copy of this software and associated documentation files (the "Software"), + * to deal in the Software without restriction, including without limitation + * the rights to use, copy, modify, merge, publish, distribute, sublicense, + * and/or sell copies of the Software, and to permit persons to whom the + * Software is furnished to do so, subject to the following conditions: + * + * The above copyright notice and this permission notice (including the next + * paragraph) shall be included in all copies or substantial portions of the + * Software. + * + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, + * FITNESS FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL + * THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER + * LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING + * FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER + * DEALINGS IN THE SOFTWARE. + */ + +#include + +#include "pwtest.h" + +#define OTHER_ARGS const char *file, int line, const char *func, const char *fmt + +struct data { + bool invoked; + const char *func; + const char *msg; + const struct spa_log_topic *topic; +}; + + +static void impl_log_log(void *object, enum spa_log_level level, OTHER_ARGS, ...) { + struct data *data = object; + *data = (struct data) { + .func = __func__, + .invoked = true, + .msg = fmt, + .topic = NULL, + }; +}; + +static void impl_log_logv(void *object, enum spa_log_level level, OTHER_ARGS, va_list args) { + struct data *data = object; + *data = (struct data) { + .func = __func__, + .invoked = true, + .msg = fmt, + .topic = NULL, + }; +}; + +static void impl_log_logt(void *object, enum spa_log_level level, const struct spa_log_topic *topic, OTHER_ARGS, ...) { + struct data *data = object; + *data = (struct data) { + .func = __func__, + .invoked = true, + .msg = fmt, + .topic = topic, + }; +}; + +static void impl_log_logtv(void *object, enum spa_log_level level, const struct spa_log_topic *topic, OTHER_ARGS, va_list args) { + struct data *data = object; + *data = (struct data) { + .func = __func__, + .invoked = true, + .msg = fmt, + .topic = topic, + }; +}; + +PWTEST(utils_log_logt) +{ + struct spa_log_methods impl_log = { + SPA_VERSION_LOG_METHODS, + .log = impl_log_log, + .logv = impl_log_logv, + .logt = impl_log_logt, + .logtv = impl_log_logtv, + }; + struct spa_log log; + struct data data; + struct spa_log_topic topic = { + .version = 0, + .topic = "log topic", + .level = SPA_LOG_LEVEL_DEBUG, + }; + + log.level = SPA_LOG_LEVEL_DEBUG; + log.iface = SPA_INTERFACE_INIT(SPA_TYPE_INTERFACE_Log, 0, &impl_log, &data); + + impl_log.version = SPA_VERSION_LOG_METHODS; + + /* impl_log is v0 so we expect the non-topic function to be called */ + spa_log_debug(&log, "call v0"); + pwtest_bool_true(data.invoked); + pwtest_str_eq(data.func, "impl_log_log"); + pwtest_str_eq(data.msg, "call v0"); + pwtest_ptr_null(data.topic); + data.invoked = false; + + /* impl_log is v0 so we expect the topic to be ignored */ + spa_logt_debug(&log, &topic, "call v0 logt"); + pwtest_bool_true(data.invoked); + pwtest_str_eq(data.func, "impl_log_log"); + pwtest_str_eq(data.msg, "call v0 logt"); + pwtest_ptr_null(data.topic); + data.invoked = false; + + impl_log.version = SPA_VERSION_LOG_METHODS_LOGT; + + /* impl_log is v1 so we expect logt to be called */ + spa_log_debug(&log, "call v1"); + pwtest_bool_true(data.invoked); + pwtest_str_eq(data.func, "impl_log_logt"); + pwtest_str_eq(data.msg, "call v1"); + pwtest_ptr_null(data.topic); + data.invoked = false; + + /* impl_log is v1 so we expect the topic to be passed through */ + spa_logt_debug(&log, &topic, "call v1 logt"); + pwtest_bool_true(data.invoked); + pwtest_str_eq(data.func, "impl_log_logt"); + pwtest_str_eq(data.msg, "call v1 logt"); + pwtest_ptr_eq(data.topic, &topic); + data.invoked = false; + + /* simulated: + * impl_log is v1 but we have an old caller that uses v0, this goes + * through to the non-topic log function */ + spa_interface_call(&log.iface, struct spa_log_methods, log, 0, + SPA_LOG_LEVEL_DEBUG, "file", 123, "function", "call from v0"); + pwtest_bool_true(data.invoked); + pwtest_str_eq(data.func, "impl_log_log"); + pwtest_str_eq(data.msg, "call from v0"); + pwtest_ptr_null(data.topic); + data.invoked = false; + + return PWTEST_PASS; +} + +PWTEST(utils_log_logt_levels) +{ + struct spa_log_methods impl_log = { + SPA_VERSION_LOG_METHODS_LOGT, + .log = impl_log_log, + .logv = impl_log_logv, + .logt = impl_log_logt, + .logtv = impl_log_logtv, + }; + struct spa_log log; + struct data data; + struct spa_log_topic topic = { + .version = 0, + .topic = "log topic", + .level = SPA_LOG_LEVEL_INFO, + .has_custom_level = true, + }; + + log.level = SPA_LOG_LEVEL_DEBUG; + log.iface = SPA_INTERFACE_INIT(SPA_TYPE_INTERFACE_Log, 0, &impl_log, &data); + + /* Topic is NULL for spa_log_*, so expect this to be invoked */ + spa_log_debug(&log, "spa_log_debug"); + pwtest_bool_true(data.invoked); + pwtest_str_eq(data.msg, "spa_log_debug"); + pwtest_ptr_null(data.topic); + data.invoked = false; + + spa_log_info(&log, "spa_log_info"); + pwtest_bool_true(data.invoked); + pwtest_str_eq(data.msg, "spa_log_info"); + pwtest_ptr_null(data.topic); + data.invoked = false; + + spa_log_warn(&log, "spa_log_warn"); + pwtest_bool_true(data.invoked); + pwtest_str_eq(data.msg, "spa_log_warn"); + pwtest_ptr_null(data.topic); + data.invoked = false; + + spa_logt_debug(&log, &topic, "spa_logt_debug"); + pwtest_bool_false(data.invoked); + data.invoked = false; + + spa_logt_info(&log, &topic, "spa_logt_info"); + pwtest_bool_true(data.invoked); + pwtest_str_eq(data.msg, "spa_logt_info"); + pwtest_ptr_eq(data.topic, &topic); + data.invoked = false; + + spa_logt_warn(&log, &topic, "spa_logt_warn"); + pwtest_bool_true(data.invoked); + pwtest_str_eq(data.msg, "spa_logt_warn"); + pwtest_ptr_eq(data.topic, &topic); + data.invoked = false; + + return PWTEST_PASS; +} + +PWTEST_SUITE(spa_log) +{ + pwtest_add(utils_log_logt, PWTEST_NOARG); + pwtest_add(utils_log_logt_levels, PWTEST_NOARG); + + return PWTEST_PASS; +}