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.
This commit is contained in:
Peter Hutterer 2021-09-14 14:49:03 +10:00 committed by Wim Taymans
parent 0e60e9c063
commit 59a5791d41
7 changed files with 366 additions and 27 deletions

View file

@ -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)

View file

@ -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

View file

@ -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 <errno.h>
#include <fnmatch.h>
#include <spa/support/log.h>
#include <spa/utils/list.h>
#include <spa/utils/json.h>
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);
}
}

View file

@ -28,6 +28,7 @@
#include <errno.h>
#include <stdio.h>
#include <time.h>
#include <fnmatch.h>
#include <spa/support/log.h>
#include <spa/support/loop.h>
@ -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;

View file

@ -1,6 +1,7 @@
spa_support_sources = [
'cpu.c',
'logger.c',
'log-patterns.c',
'loop.c',
'node-driver.c',
'null-audio-sink.c',

View file

@ -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,

View file

@ -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);