From 59a5791d41ca834152a3381377cfd6ae9d3e0660 Mon Sep 17 00:00:00 2001 From: Peter Hutterer Date: Tue, 14 Sep 2021 14:49:03 +1000 Subject: [PATCH] spa: implement the new topic logging for the provided loggers Both simple log implementation now support the new topic-based functions, and so does the journal logger too. --- spa/include/spa/support/log-impl.h | 57 ++++++++++++--- spa/plugins/support/journal.c | 73 ++++++++++++++++++-- spa/plugins/support/log-patterns.c | 107 +++++++++++++++++++++++++++++ spa/plugins/support/logger.c | 68 ++++++++++++++++-- spa/plugins/support/meson.build | 1 + test/pwtest.h | 11 +++ test/test-logger.c | 76 ++++++++++++++++++-- 7 files changed, 366 insertions(+), 27 deletions(-) create mode 100644 spa/plugins/support/log-patterns.c diff --git a/spa/include/spa/support/log-impl.h b/spa/include/spa/support/log-impl.h index 00f5a9d02..be5080bc9 100644 --- a/spa/include/spa/support/log-impl.h +++ b/spa/include/spa/support/log-impl.h @@ -39,8 +39,9 @@ extern "C" { * \{ */ -static inline SPA_PRINTF_FUNC(6, 0) void spa_log_impl_logv(void *object, +static inline SPA_PRINTF_FUNC(7, 0) void spa_log_impl_logtv(void *object, enum spa_log_level level, + const struct spa_log_topic *topic, const char *file, int line, const char *func, @@ -50,18 +51,50 @@ static inline SPA_PRINTF_FUNC(6, 0) void spa_log_impl_logv(void *object, static const char * const levels[] = { "-", "E", "W", "I", "D", "T" }; const char *basename = strrchr(file, '/'); - char text[512], location[1024]; + char text[512], location[1024]; + char topicstr[32] = {0}; if (basename) basename += 1; /* skip '/' */ else basename = file; /* use whole string if no '/' is found */ - vsnprintf(text, sizeof(text), fmt, args); - snprintf(location, sizeof(location), "[%s][%s:%i %s()] %s\n", - levels[level], basename, line, func, text); - fputs(location, stderr); + if (topic && topic->topic) + snprintf(topicstr, sizeof(topicstr), " %s ", topic->topic); + vsnprintf(text, sizeof(text), fmt, args); + snprintf(location, sizeof(location), "[%s]%s[%s:%i %s()] %s\n", + levels[level], + topicstr, + basename, line, func, text); + fputs(location, stderr); } + +static inline SPA_PRINTF_FUNC(7,8) void spa_log_impl_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, ...) +{ + va_list args; + va_start(args, fmt); + spa_log_impl_logtv(object, level, topic, file, line, func, fmt, args); + va_end(args); +} + +static inline SPA_PRINTF_FUNC(6, 0) void spa_log_impl_logv(void *object, + enum spa_log_level level, + const char *file, + int line, + const char *func, + const char *fmt, + va_list args) +{ + + spa_log_impl_logtv(object, level, NULL, file, line, func, fmt, args); +} + static inline SPA_PRINTF_FUNC(6,7) void spa_log_impl_log(void *object, enum spa_log_level level, const char *file, @@ -75,6 +108,11 @@ static inline SPA_PRINTF_FUNC(6,7) void spa_log_impl_log(void *object, va_end(args); } +static inline void spa_log_impl_topic_init(void *object, struct spa_log_topic *topic) +{ + /* noop */ +} + #define SPA_LOG_IMPL_DEFINE(name) \ struct { \ struct spa_log log; \ @@ -85,9 +123,12 @@ struct { \ { { { SPA_TYPE_INTERFACE_Log, SPA_VERSION_LOG, \ SPA_CALLBACKS_INIT(&name.methods, &name) }, \ SPA_LOG_LEVEL_INFO, }, \ - { SPA_VERSION_LOG_METHODS, \ + { SPA_VERSION_LOG_METHODS_LOGT, \ spa_log_impl_log, \ - spa_log_impl_logv,} } + spa_log_impl_logv, \ + spa_log_impl_logt, \ + spa_log_impl_logtv, \ + } } #define SPA_LOG_IMPL(name) \ SPA_LOG_IMPL_DEFINE(name) = SPA_LOG_IMPL_INIT(name) diff --git a/spa/plugins/support/journal.c b/spa/plugins/support/journal.c index a7c67e9da..d1362540c 100644 --- a/spa/plugins/support/journal.c +++ b/spa/plugins/support/journal.c @@ -43,17 +43,22 @@ #define DEFAULT_LOG_LEVEL SPA_LOG_LEVEL_INFO +#include "log-patterns.c" + struct impl { struct spa_handle handle; struct spa_log log; /* if non-null, we'll additionally forward all logging to there */ struct spa_log *chain_log; + + struct spa_list patterns; }; -static SPA_PRINTF_FUNC(6,0) void -impl_log_logv(void *object, +static SPA_PRINTF_FUNC(7,0) void +impl_log_logtv(void *object, enum spa_log_level level, + const struct spa_log_topic *topic, const char *file, int line, const char *func, @@ -65,12 +70,14 @@ impl_log_logv(void *object, char file_buffer[strlen("CODE_FILE=") + strlen(file) + 1]; char message_buffer[LINE_MAX]; int priority; + size_t sz = 0; if (impl->chain_log != NULL) { va_list args_copy; va_copy(args_copy, args); - spa_log_logv(impl->chain_log, - level, file, line, func, fmt, args_copy); + spa_log_logtv(impl->chain_log, + level, topic, + file, line, func, fmt, args_copy); va_end(args_copy); } @@ -92,13 +99,17 @@ impl_log_logv(void *object, break; } + if (topic) + sz = spa_scnprintf(message_buffer, sizeof(message_buffer), + "%s: ", topic->topic); + /* we'll be using the low-level journal API, which expects us to provide * the location explicitly. line and file are to be passed as preformatted * entries, whereas the function name is passed as-is, and converted into * a field inside sd_journal_send_with_location(). */ snprintf(line_buffer, sizeof(line_buffer), "CODE_LINE=%d", line); snprintf(file_buffer, sizeof(file_buffer), "CODE_FILE=%s", file); - vsnprintf(message_buffer, sizeof(message_buffer), fmt, args); + vsnprintf(message_buffer + sz, sizeof(message_buffer) - sz, fmt, args); sd_journal_send_with_location(file_buffer, line_buffer, func, "MESSAGE=%s", message_buffer, @@ -116,14 +127,53 @@ impl_log_log(void *object, { va_list args; va_start(args, fmt); - impl_log_logv(object, level, file, line, func, fmt, args); + impl_log_logtv(object, level, NULL, file, line, func, fmt, args); va_end(args); } +static SPA_PRINTF_FUNC(6,0) void +impl_log_logv(void *object, + enum spa_log_level level, + const char *file, + int line, + const char *func, + const char *fmt, + va_list args) +{ + impl_log_logtv(object, level, NULL, file, line, func, fmt, args); +} + +static SPA_PRINTF_FUNC(7,8) void +impl_log_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, ...) +{ + va_list args; + va_start(args, fmt); + impl_log_logtv(object, level, topic, file, line, func, fmt, args); + va_end(args); +} + +static void +impl_log_topic_init(void *object, struct spa_log_topic *t) +{ + struct impl *impl = object; + enum spa_log_level level = impl->log.level; + + support_log_topic_init(&impl->patterns, level, t); +} + static const struct spa_log_methods impl_log = { - SPA_VERSION_LOG_METHODS, + SPA_VERSION_LOG_METHODS_LOGT, .log = impl_log_log, .logv = impl_log_logv, + .logt = impl_log_logt, + .logtv = impl_log_logtv, + .topic_init = impl_log_topic_init, }; static int impl_get_interface(struct spa_handle *handle, const char *type, void **interface) @@ -145,8 +195,13 @@ static int impl_get_interface(struct spa_handle *handle, const char *type, void static int impl_clear(struct spa_handle *handle) { + struct impl *this; + spa_return_val_if_fail(handle != NULL, -EINVAL); + this = (struct impl *) handle; + support_log_free_patterns(&this->patterns); + return 0; } @@ -211,9 +266,13 @@ impl_init(const struct spa_handle_factory *factory, &impl_log, impl); impl->log.level = DEFAULT_LOG_LEVEL; + spa_list_init(&impl->patterns); + if (info) { if ((str = spa_dict_lookup(info, SPA_KEY_LOG_LEVEL)) != NULL) impl->log.level = atoi(str); + if ((str = spa_dict_lookup(info, SPA_KEY_LOG_PATTERNS)) != NULL) + support_log_parse_patterns(&impl->patterns, str); } /* if our stderr goes to the journal, there's no point in logging both diff --git a/spa/plugins/support/log-patterns.c b/spa/plugins/support/log-patterns.c new file mode 100644 index 000000000..65a9a9f2c --- /dev/null +++ b/spa/plugins/support/log-patterns.c @@ -0,0 +1,107 @@ +/* Spa + * + * 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 + +#include +#include +#include + +struct support_log_pattern { + struct spa_list link; + const char *pattern; + enum spa_log_level level; +}; + +static void +support_log_topic_init(struct spa_list *patterns, enum spa_log_level default_level, + struct spa_log_topic *t) +{ + enum spa_log_level level = default_level; + const char *topic = t->topic; + struct support_log_pattern *pattern; + + spa_list_for_each(pattern, patterns, link) { + if (fnmatch(pattern->pattern, topic, 0) != 0) + continue; + level = pattern->level; + t->has_custom_level = true; + } + + t->level = level; +} + +static int +support_log_parse_patterns(struct spa_list *patterns, const char *jsonstr) +{ + struct spa_json iter, array, elem; + int res; + + spa_json_init(&iter, jsonstr, strlen(jsonstr)); + + if (spa_json_enter_array(&iter, &array) < 0) + return -EINVAL; + + while (spa_json_enter_object(&array, &elem) > 0) { + char pattern[512] = {0}; + + while (spa_json_get_string(&elem, pattern, sizeof(pattern) - 1) > 0) { + struct support_log_pattern *p; + const char *val; + int len; + int lvl; + + if ((len = spa_json_next(&elem, &val)) <= 0) + break; + + if (!spa_json_is_int(val, len)) + break; + + if ((res = spa_json_parse_int(val, len, &lvl)) < 0) + break; + + SPA_CLAMP(lvl, SPA_LOG_LEVEL_NONE, SPA_LOG_LEVEL_TRACE); + + p = calloc(1, sizeof(*p) + strlen(pattern) + 1); + p->level = lvl; + memcpy(p + 1, pattern, strlen(pattern)); + p->pattern = (const char *)(p+1); + spa_list_append(patterns, &p->link); + } + } + + return res; +} + +static void +support_log_free_patterns(struct spa_list *patterns) +{ + struct support_log_pattern *p, *tmp; + + spa_list_for_each_safe(p, tmp, patterns, link) { + spa_list_remove(&p->link); + free(p); + } +} diff --git a/spa/plugins/support/logger.c b/spa/plugins/support/logger.c index e6aa51447..82f90d663 100644 --- a/spa/plugins/support/logger.c +++ b/spa/plugins/support/logger.c @@ -28,6 +28,7 @@ #include #include #include +#include #include #include @@ -49,6 +50,8 @@ #define TRACE_BUFFER (16*1024) +#include "log-patterns.c" + struct impl { struct spa_handle handle; struct spa_log log; @@ -64,11 +67,14 @@ struct impl { unsigned int colors:1; unsigned int timestamp:1; unsigned int line:1; + + struct spa_list patterns; }; -static SPA_PRINTF_FUNC(6,0) void -impl_log_logv(void *object, +static SPA_PRINTF_FUNC(7,0) void +impl_log_logtv(void *object, enum spa_log_level level, + const struct spa_log_topic *topic, const char *file, int line, const char *func, @@ -79,6 +85,7 @@ impl_log_logv(void *object, struct impl *impl = object; char timestamp[15] = {0}; + char topicstr[32] = {0}; char filename[64] = {0}; char location[1000 + RESERVED_LENGTH], *p, *s; static const char * const levels[] = { "-", "E", "W", "I", "D", "T", "*T*" }; @@ -109,20 +116,24 @@ impl_log_logv(void *object, spa_scnprintf(timestamp, sizeof(timestamp), "[%05lu.%06lu]", (now.tv_sec & 0x1FFFFFFF) % 100000, now.tv_nsec / 1000); } + + if (topic && topic->topic) + spa_scnprintf(topicstr, sizeof(topicstr), " %-12s | ", topic->topic); + + if (impl->line && line != 0) { s = strrchr(file, '/'); spa_scnprintf(filename, sizeof(filename), "[%16.16s:%5i %s()]", s ? s + 1 : file, line, func); } - size = spa_scnprintf(p, len, "%s[%s]%s%s ", prefix, levels[level], - timestamp, filename); + size = spa_scnprintf(p, len, "%s[%s]%s%s%s ", prefix, levels[level], + timestamp, topicstr, filename); /* * it is assumed that at this point `size` <= `len`, * which is reasonable as long as file names and function names * don't become very long */ - size += spa_vscnprintf(p + size, len - size, fmt, args); /* @@ -160,6 +171,32 @@ impl_log_logv(void *object, #undef RESERVED_LENGTH } +static SPA_PRINTF_FUNC(6,0) void +impl_log_logv(void *object, + enum spa_log_level level, + const char *file, + int line, + const char *func, + const char *fmt, + va_list args) +{ + impl_log_logtv(object, level, NULL, file, line, func, fmt, args); +} + +static SPA_PRINTF_FUNC(7,8) void +impl_log_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, ...) +{ + va_list args; + va_start(args, fmt); + impl_log_logtv(object, level, topic, file, line, func, fmt, args); + va_end(args); +} static SPA_PRINTF_FUNC(6,7) void impl_log_log(void *object, @@ -171,7 +208,7 @@ impl_log_log(void *object, { va_list args; va_start(args, fmt); - impl_log_logv(object, level, file, line, func, fmt, args); + impl_log_logtv(object, level, NULL, file, line, func, fmt, args); va_end(args); } @@ -203,10 +240,22 @@ static void on_trace_event(struct spa_source *source) } } +static void +impl_log_topic_init(void *object, struct spa_log_topic *t) +{ + struct impl *impl = object; + enum spa_log_level level = impl->log.level; + + support_log_topic_init(&impl->patterns, level, t); +} + static const struct spa_log_methods impl_log = { - SPA_VERSION_LOG_METHODS, + SPA_VERSION_LOG_METHODS_LOGT, .log = impl_log_log, .logv = impl_log_logv, + .logt = impl_log_logt, + .logtv = impl_log_logtv, + .topic_init = impl_log_topic_init, }; static int impl_get_interface(struct spa_handle *handle, const char *type, void **interface) @@ -234,6 +283,8 @@ static int impl_clear(struct spa_handle *handle) this = (struct impl *) handle; + support_log_free_patterns(&this->patterns); + if (this->have_source) { spa_loop_remove_source(this->source.loop, &this->source); spa_system_close(this->system, this->source.fd); @@ -276,6 +327,7 @@ impl_init(const struct spa_handle_factory *factory, loop = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_Loop); this->system = spa_support_find(support, n_support, SPA_TYPE_INTERFACE_System); + spa_list_init(&this->patterns); if (loop != NULL && this->system != NULL) { this->source.func = on_trace_event; @@ -305,6 +357,8 @@ impl_init(const struct spa_handle_factory *factory, if (this->file == NULL) fprintf(stderr, "Warning: failed to open file %s: (%m)", str); } + if ((str = spa_dict_lookup(info, SPA_KEY_LOG_PATTERNS)) != NULL) + support_log_parse_patterns(&this->patterns, str); } if (this->file == NULL) this->file = stderr; diff --git a/spa/plugins/support/meson.build b/spa/plugins/support/meson.build index 5c0c71aff..9f24644fd 100644 --- a/spa/plugins/support/meson.build +++ b/spa/plugins/support/meson.build @@ -1,6 +1,7 @@ spa_support_sources = [ 'cpu.c', 'logger.c', + 'log-patterns.c', 'loop.c', 'node-driver.c', 'null-audio-sink.c', diff --git a/test/pwtest.h b/test/pwtest.h index 63ca3ee2a..8ccba9c42 100644 --- a/test/pwtest.h +++ b/test/pwtest.h @@ -344,6 +344,17 @@ struct pwtest_context *pwtest_get_context(struct pwtest_test *t); } while(0) +/** Assert haystack contains needle */ +#define pwtest_str_contains(haystack_, needle_) \ + do { \ + const char *_h = haystack_; \ + const char *_n = needle_; \ + if (!strstr(_h, _n)) \ + _pwtest_fail_comparison_str(__FILE__, __LINE__, __func__, \ + #haystack_ " contains " #needle_, _h, _n); \ + } while(0) + + /* Needs to be a #define NULL for SPA_SENTINEL */ enum pwtest_arg { PWTEST_NOARG = 0, diff --git a/test/test-logger.c b/test/test-logger.c index 895cbe2d8..7f264aecd 100644 --- a/test/test-logger.c +++ b/test/test-logger.c @@ -287,6 +287,52 @@ PWTEST(logger_debug_env_alpha) return PWTEST_PASS; } +PWTEST(logger_topics) +{ + struct pwtest_spa_plugin *plugin; + void *iface; + char fname[PATH_MAX]; + struct spa_dict_item items[2]; + struct spa_dict info; + char buffer[1024]; + FILE *fp; + bool mark_line_found = false; + struct spa_log_topic topic = { + .version = 0, + .topic = "my topic", + .level = SPA_LOG_LEVEL_DEBUG, + }; + + pw_init(0, NULL); + + pwtest_mkstemp(fname); + items[0] = SPA_DICT_ITEM_INIT(SPA_KEY_LOG_FILE, fname); + items[1] = SPA_DICT_ITEM_INIT(SPA_KEY_LOG_COLORS, "true"); + info = SPA_DICT_INIT(items, 2); + plugin = pwtest_spa_plugin_new(); + iface = pwtest_spa_plugin_load_interface(plugin, "support/libspa-support", + SPA_NAME_SUPPORT_LOG, SPA_TYPE_INTERFACE_Log, + &info); + pwtest_ptr_notnull(iface); + + spa_logt_info(iface, &topic, "MARK\n"); + + fp = fopen(fname, "r"); + while (fgets(buffer, sizeof(buffer), fp) != NULL) { + if (strstr(buffer, "MARK")) { + mark_line_found = true; + pwtest_str_contains(buffer, "my topic"); + } + } + + pwtest_bool_true(mark_line_found); + pwtest_spa_plugin_destroy(plugin); + + fclose(fp); + + return PWTEST_PASS; +} + PWTEST(logger_journal) { enum pwtest_result result = PWTEST_SKIP; @@ -296,6 +342,11 @@ PWTEST(logger_journal) struct spa_dict_item items[2]; struct spa_dict info; bool mark_line_found = false; + struct spa_log_topic topic = { + .version = 0, + .topic = "pwtest journal", + .level = SPA_LOG_LEVEL_DEBUG, + }; sd_journal *journal; int rc; @@ -319,7 +370,7 @@ PWTEST(logger_journal) sd_journal_seek_tail(journal); - spa_log_info(iface, "MARK\n"); + spa_logt_info(iface, &topic, "MARK\n"); while ((rc = sd_journal_next(journal)) > 0) { char buffer[1024] = {0}; const char *d; @@ -327,8 +378,10 @@ PWTEST(logger_journal) int r = sd_journal_get_data(journal, "MESSAGE", (const void **)&d, &l); pwtest_neg_errno_ok(r); spa_scnprintf(buffer, sizeof(buffer), "%.*s", (int) l, d); - if (strstr(buffer, "MARK")) + if (strstr(buffer, "MARK")) { mark_line_found = true; + pwtest_str_contains(buffer, "pwtest journal"); + } } pwtest_neg_errno_ok(rc); pwtest_bool_true(mark_line_found); @@ -356,6 +409,11 @@ PWTEST(logger_journal_chain) struct spa_dict_item items[2]; struct spa_dict info; bool mark_line_found = false; + struct spa_log_topic topic = { + .version = 0, + .topic = "pwtest journal", + .level = SPA_LOG_LEVEL_DEBUG, + }; sd_journal *journal; int rc; @@ -389,7 +447,7 @@ PWTEST(logger_journal_chain) sd_journal_seek_tail(journal); - spa_log_info(iface, "MARK\n"); + spa_logt_info(iface, &topic, "MARK\n"); while ((rc = sd_journal_next(journal)) > 0) { char buffer[1024] = {0}; const char *d; @@ -397,8 +455,10 @@ PWTEST(logger_journal_chain) int r = sd_journal_get_data(journal, "MESSAGE", (const void **)&d, &l); pwtest_neg_errno_ok(r); spa_scnprintf(buffer, sizeof(buffer), "%.*s", (int) l, d); - if (strstr(buffer, "MARK")) + if (strstr(buffer, "MARK")) { mark_line_found = true; + pwtest_str_contains(buffer, "pwtest journal"); + } } pwtest_neg_errno_ok(rc); pwtest_bool_true(mark_line_found); @@ -407,8 +467,13 @@ PWTEST(logger_journal_chain) mark_line_found = false; fp = fopen(fname, "r"); while (fgets(buffer, sizeof(buffer), fp) != NULL) { - if (strstr(buffer, "MARK")) + if (strstr(buffer, "MARK")) { mark_line_found = true; + pwtest_ptr_null(strstr(buffer, SPA_ANSI_RESET)); + pwtest_ptr_null(strstr(buffer, SPA_ANSI_RED)); + pwtest_ptr_null(strstr(buffer, SPA_ANSI_BRIGHT_RED)); + pwtest_ptr_null(strstr(buffer, SPA_ANSI_BOLD_RED)); + } } fclose(fp); @@ -438,6 +503,7 @@ PWTEST_SUITE(logger) pwtest_add(logger_debug_env_alpha, PWTEST_ARG_RANGE, SPA_LOG_LEVEL_NONE, SPA_LOG_LEVEL_TRACE + 1, PWTEST_NOARG); + pwtest_add(logger_topics, PWTEST_NOARG); pwtest_add(logger_journal, PWTEST_NOARG); pwtest_add(logger_journal_chain, PWTEST_NOARG);