diff --git a/doc/pipewire-daemon.dox b/doc/pipewire-daemon.dox index 665fe53b5..e40664197 100644 --- a/doc/pipewire-daemon.dox +++ b/doc/pipewire-daemon.dox @@ -127,9 +127,16 @@ Allowed configuration file sections are: \section sec_logging Logging The `PIPEWIRE_DEBUG` environment variable can be used to enable -more debugging. The format is: +more debugging. This variable supports one of two formats: -`[,,...]` +- `PIPEWIRE_DEBUG=` where `` is either a numerical log level or it's + respective key, see below. +- `PIPEWIRE_DEBUG=:,:,...` where the globs are + shell-globs to match on log topics and the levels are the respective + log level to set for that topic. Globs are applied in-order and a matching + glob overrides an earlier glob for that category. For example, + `PIPEWIRE_DEBUG=*:E,mod.*:D,mod.foo:X" enables global error messages, + debugging on all modules but no messages on the foo module. - `` specifies the log level: + `X` or `0`: no logging is enabled @@ -140,9 +147,14 @@ more debugging. The format is: + `T` or `5`: Trace messages are enabled. These messages can be logged from the realtime threads. -- ``: Specifies a string category to enable. Many categories - can be separated by commas. Current categories are: - + `connection`: to log connection messages +PipeWire uses a "category.topic" naming scheme, with the following categories: +- `pw.*`: pipewire-internal topics +- `mod.*`: module topics, for example `mod.foo` would usually refer to the + "foo" module +- `conn.*`: connection-specific topics such as printing raw messages sent over + a communication socket. These are in a separate namespace as they are + usually vastly more verbose than the normal debugging topics. + This namespace must be explicitly enabled with a `conn.` glob. The behavior of the logging can be further controlled with the following diff --git a/src/pipewire/log.c b/src/pipewire/log.c index 4fe516a4a..55fb381e7 100644 --- a/src/pipewire/log.c +++ b/src/pipewire/log.c @@ -22,11 +22,15 @@ * DEALINGS IN THE SOFTWARE. */ +#include +#include + #include #include #include #include +#include #include #include @@ -40,6 +44,18 @@ enum spa_log_level pw_log_level = DEFAULT_LOG_LEVEL; static struct spa_log *global_log = &default_log.log; +SPA_EXPORT +struct spa_log_topic *PW_LOG_TOPIC_DEFAULT; + +PW_LOG_TOPIC_STATIC(log_topic, "pw.log"); /* log topic for this file here */ +PW_LOG_TOPIC(log_conf, "pw.conf"); +PW_LOG_TOPIC(log_context, "pw.context"); +PW_LOG_TOPIC(log_metadata, "pw.metadata"); +PW_LOG_TOPIC(log_node, "pw.node"); +PW_LOG_TOPIC(log_port, "pw.port"); + +PW_LOG_TOPIC(PW_LOG_TOPIC_DEFAULT, "default"); + /** Set the global log interface * \param log the global log to set */ @@ -74,8 +90,9 @@ void pw_log_set_level(enum spa_log_level level) global_log->level = level; } -/** Log a message +/** Log a message for the given topic * \param level the log level + * \param topic the topic * \param file the file this message originated from * \param line the line number * \param func the function @@ -85,21 +102,46 @@ void pw_log_set_level(enum spa_log_level level) */ SPA_EXPORT void -pw_log_log(enum spa_log_level level, - const char *file, - int line, - const char *func, - const char *fmt, ...) +pw_log_logt(enum spa_log_level level, + const struct spa_log_topic *topic, + const char *file, + int line, + const char *func, + const char *fmt, ...) { - if (SPA_UNLIKELY(pw_log_level_enabled(level))) { + if (SPA_UNLIKELY(pw_log_topic_enabled(level, topic))) { va_list args; va_start(args, fmt); - spa_log_logv(global_log, level, file, line, func, fmt, args); + spa_log_logtv(global_log, level, topic, file, line, func, fmt, args); va_end(args); } } -/** Log a message with va_list +/** Log a message for the given topic with va_list + * \param level the log level + * \param topic the topic + * \param file the file this message originated from + * \param line the line number + * \param func the function + * \param fmt the printf style format + * \param args a va_list of arguments + * + */ +SPA_EXPORT +void +pw_log_logtv(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_log_logtv(global_log, level, topic, file, line, func, fmt, args); +} + + +/** Log a message for the default topic with va_list * \param level the log level * \param file the file this message originated from * \param line the line number @@ -117,9 +159,30 @@ pw_log_logv(enum spa_log_level level, const char *fmt, va_list args) { - if (SPA_UNLIKELY(pw_log_level_enabled(level))) { - spa_log_logv(global_log, level, file, line, func, fmt, args); - } + pw_log_logtv(level, PW_LOG_TOPIC_DEFAULT, file, line, func, fmt, args); +} + +/** Log a message for the default topic + * \param level the log level + * \param file the file this message originated from + * \param line the line number + * \param func the function + * \param fmt the printf style format + * \param ... printf style arguments to log + * + */ +SPA_EXPORT +void +pw_log_log(enum spa_log_level level, + const char *file, + int line, + const char *func, + const char *fmt, ...) +{ + va_list args; + va_start(args, fmt); + pw_log_logtv(level, PW_LOG_TOPIC_DEFAULT, file, line, func, fmt, args); + va_end(args); } /** \fn void pw_log_error (const char *format, ...) @@ -333,3 +396,21 @@ void pw_log_log_object(enum spa_log_level level, } } } + +SPA_EXPORT +void +_pw_log_topic_new(struct spa_log_topic *topic) +{ + spa_log_topic_init(global_log, topic); +} + +void +pw_log_init(void) +{ + PW_LOG_TOPIC_INIT(PW_LOG_TOPIC_DEFAULT); + PW_LOG_TOPIC_INIT(log_topic); + PW_LOG_TOPIC_INIT(log_context); + PW_LOG_TOPIC_INIT(log_metadata); + PW_LOG_TOPIC_INIT(log_node); + PW_LOG_TOPIC_INIT(log_port); +} diff --git a/src/pipewire/log.h b/src/pipewire/log.h index 50a2cf32a..d4b650fb1 100644 --- a/src/pipewire/log.h +++ b/src/pipewire/log.h @@ -47,6 +47,8 @@ extern "C" { /** The global log level */ extern enum spa_log_level pw_log_level; +extern struct spa_log_topic *PW_LOG_TOPIC_DEFAULT; + /** Configure a logging module. This is usually done automatically * in pw_init() but you can install a custom logger before calling * pw_init(). */ @@ -58,37 +60,107 @@ struct spa_log *pw_log_get(void); /** Configure the logging level */ void pw_log_set_level(enum spa_log_level level); +/** Log a message for a topic */ +void +pw_log_logt(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(6, 7); -/** Log a message */ +/** Log a message for a topic */ +void +pw_log_logtv(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(6, 0); + + + +/** Log a message for the default topic */ void pw_log_log(enum spa_log_level level, const char *file, int line, const char *func, const char *fmt, ...) SPA_PRINTF_FUNC(5, 6); -/** Log a message */ +/** Log a message for the default topic */ void pw_log_logv(enum spa_log_level level, const char *file, int line, const char *func, const char *fmt, va_list args) SPA_PRINTF_FUNC(5, 0); +/** Initialize the log topic. The returned topic is owned by the pipewire + * context and the topic must not be modified or freed. + * Do not use this function directly, use one of PW_LOG_TOPIC_* instead. + * + * \see PW_LOG_TOPIC_STATIC + * \see PW_LOG_TOPIC_EXTERN + * \see PW_LOG_TOPIC + */ +void +_pw_log_topic_new(struct spa_log_topic *topic); + +/** + * Declare a static log topic named \a var. The usual usage is: + * \code + * PW_LOG_TOPIC_STATIC(my_topic); + * #define PW_LOG_TOPIC_DEFAULT my_topic + * + * void foo() { + * pw_log_debug("bar"); + * } + * \endcode + */ +#define PW_LOG_TOPIC_STATIC(var, topic) \ + static struct spa_log_topic var##__LINE__ = SPA_LOG_TOPIC(0, topic); \ + static struct spa_log_topic *var = &(var##__LINE__) + +/** + * Declare a static log topic named \a var. + * See \ref PW_LOG_TOPIC_STATIC for an example usage. + */ +#define PW_LOG_TOPIC_EXTERN(var) \ + extern struct spa_log_topic *var + +/** + * Declare a static log topic named \a var. + * See \ref PW_LOG_TOPIC_STATIC for an example usage. + */ +#define PW_LOG_TOPIC(var, topic) \ + struct spa_log_topic var##__LINE__ = SPA_LOG_TOPIC(0, topic); \ + struct spa_log_topic *var = &(var##__LINE__) + +#define PW_LOG_TOPIC_INIT(var) \ + spa_log_topic_init(pw_log_get(), var); /** Check if a loglevel is enabled */ #define pw_log_level_enabled(lev) (pw_log_level >= (lev)) +#define pw_log_topic_enabled(lev,t) ((t) && (t)->has_custom_level ? (t)->level >= (lev) : pw_log_level_enabled((lev))) -#define pw_log(lev,...) \ -({ \ - if (SPA_UNLIKELY(pw_log_level_enabled (lev))) \ - pw_log_log(lev,__FILE__,__LINE__,__func__,__VA_ARGS__); \ + +#define pw_logt(lev,topic,...) \ +({ \ + if (SPA_UNLIKELY(pw_log_topic_enabled(lev,topic))) \ + pw_log_logt(lev,topic,__FILE__,__LINE__,__func__,__VA_ARGS__); \ }) +#define pw_log(lev,...) pw_logt(lev,PW_LOG_TOPIC_DEFAULT,__VA_ARGS__) + #define pw_log_error(...) pw_log(SPA_LOG_LEVEL_ERROR,__VA_ARGS__) #define pw_log_warn(...) pw_log(SPA_LOG_LEVEL_WARN,__VA_ARGS__) #define pw_log_info(...) pw_log(SPA_LOG_LEVEL_INFO,__VA_ARGS__) #define pw_log_debug(...) pw_log(SPA_LOG_LEVEL_DEBUG,__VA_ARGS__) #define pw_log_trace(...) pw_log(SPA_LOG_LEVEL_TRACE,__VA_ARGS__) +#define pw_logt_error(t,...) pw_logt(SPA_LOG_LEVEL_ERROR,t,__VA_ARGS__) +#define pw_logt_warn(t,...) pw_logt(SPA_LOG_LEVEL_WARN,t,__VA_ARGS__) +#define pw_logt_info(t,...) pw_logt(SPA_LOG_LEVEL_INFO,t,__VA_ARGS__) +#define pw_logt_debug(t,...) pw_logt(SPA_LOG_LEVEL_DEBUG,t,__VA_ARGS__) +#define pw_logt_trace(t,...) pw_logt(SPA_LOG_LEVEL_TRACE,t,__VA_ARGS__) + #ifndef FASTPATH #define pw_log_trace_fp(...) pw_log(SPA_LOG_LEVEL_TRACE,__VA_ARGS__) #else diff --git a/src/pipewire/pipewire.c b/src/pipewire/pipewire.c index f3d567a1b..b8d6d66cc 100644 --- a/src/pipewire/pipewire.c +++ b/src/pipewire/pipewire.c @@ -213,30 +213,6 @@ static void unref_handle(struct handle *handle) } } -static void configure_debug(struct support *support, const char *str) -{ - char **level; - int n_tokens; - - level = pw_split_strv(str, ":", INT_MAX, &n_tokens); - if (n_tokens > 0) { - switch (level[0][0]) { - case 'X': pw_log_set_level(SPA_LOG_LEVEL_NONE); break; - case 'E': pw_log_set_level(SPA_LOG_LEVEL_ERROR); break; - case 'W': pw_log_set_level(SPA_LOG_LEVEL_WARN); break; - case 'I': pw_log_set_level(SPA_LOG_LEVEL_INFO); break; - case 'D': pw_log_set_level(SPA_LOG_LEVEL_DEBUG); break; - case 'T': pw_log_set_level(SPA_LOG_LEVEL_TRACE); break; - default: pw_log_set_level(atoi(level[0])); break; - } - } - - if (n_tokens > 1) - support->categories = pw_split_strv(level[1], ",", INT_MAX, &n_tokens); - - pw_free_strv(level); -} - SPA_EXPORT uint32_t pw_get_support(struct spa_support *support, uint32_t max_support) { @@ -623,9 +599,6 @@ void pw_init(int *argc, char **argv[]) if ((str = getenv("PIPEWIRE_NO_CONFIG")) != NULL) support->no_config = pw_properties_parse_bool(str); - if ((str = getenv("PIPEWIRE_DEBUG")) != NULL) - configure_debug(support, str); - init_i18n(support); if ((str = getenv("SPA_PLUGIN_DIR")) == NULL) @@ -672,6 +645,8 @@ void pw_init(int *argc, char **argv[]) SPA_SUPPORT_INIT(SPA_TYPE_INTERFACE_Log, pw_log_get()); } + pw_log_init(); + n_items = 0; if ((str = getenv("PIPEWIRE_CPU"))) items[n_items++] = SPA_DICT_ITEM_INIT(SPA_KEY_CPU_FORCE, str); diff --git a/src/pipewire/private.h b/src/pipewire/private.h index 011090abb..94f9e36a7 100644 --- a/src/pipewire/private.h +++ b/src/pipewire/private.h @@ -1257,6 +1257,9 @@ void pw_log_log_object(enum spa_log_level level, const char *file, int line, bool pw_log_is_default(void); +void pw_log_init(void); +void pw_log_deinit(void); + int pw_settings_init(struct pw_context *context); void pw_settings_clean(struct pw_context *context); diff --git a/test/test-logger.c b/test/test-logger.c index 7f264aecd..2e7820c72 100644 --- a/test/test-logger.c +++ b/test/test-logger.c @@ -24,6 +24,7 @@ #include "pwtest.h" +#include #include #include @@ -287,6 +288,114 @@ PWTEST(logger_debug_env_alpha) return PWTEST_PASS; } +PWTEST(logger_debug_env_topic_all) +{ + enum spa_log_level level = pwtest_get_iteration(current_test); + enum spa_log_level default_level = pw_log_level; + struct spa_log *default_logger = pw_log_get(); + char *oldenv = getenv("PIPEWIRE_DEBUG"); + char lvlstr[32]; + char *lvl = SPA_LOG_LEVEL_NONE; + + if (oldenv) + oldenv = strdup(oldenv); + + switch(level) { + case SPA_LOG_LEVEL_NONE: lvl = "X"; break; + case SPA_LOG_LEVEL_ERROR: lvl = "E"; break; + case SPA_LOG_LEVEL_WARN: lvl = "W"; break; + case SPA_LOG_LEVEL_INFO: lvl = "I"; break; + case SPA_LOG_LEVEL_DEBUG: lvl = "D"; break; + case SPA_LOG_LEVEL_TRACE: lvl = "T"; break; + default: + pwtest_fail_if_reached(); + break; + } + + /* Check that the * glob works to enable all topics */ + spa_scnprintf(lvlstr, sizeof(lvlstr), "*:%s", lvl); + setenv("PIPEWIRE_DEBUG", lvlstr, 1); + + /* Disable logging, let PIPEWIRE_DEBUG set the level */ + pw_log_set_level(SPA_LOG_LEVEL_NONE); + + test_log_levels(level); + + if (oldenv) { + setenv("PIPEWIRE_DEBUG", oldenv, 1); + free(oldenv); + } else { + unsetenv("PIPEWIRE_DEBUG"); + } + + pw_log_set(default_logger); + pw_log_set_level(default_level); + + return PWTEST_PASS; +} + +PWTEST(logger_debug_env_invalid) +{ + enum spa_log_level default_level = pw_log_level; + struct spa_log *default_logger = pw_log_get(); + char *oldenv = getenv("PIPEWIRE_DEBUG"); + char fname[PATH_MAX]; + char buf[1024] = {0}; + int fd; + int rc; + bool error_message_found = false; + long unsigned int which = pwtest_get_iteration(current_test); + const char *envvars[] = { + "invalid value", + "*:5,some invalid value", + "*:W,foo.bar:3,invalid:", + "*:W,1,foo.bar:D", + "*:W,D,foo.bar:3", + }; + + pwtest_int_lt(which, SPA_N_ELEMENTS(envvars)); + + if (oldenv) + oldenv = strdup(oldenv); + + /* The error message during pw_init() will go to stderr because no + * logger has been set up yet. Intercept that in our temp file */ + pwtest_mkstemp(fname); + fd = open(fname, O_RDWR); + pwtest_errno_ok(fd); + rc = dup2(fd, STDERR_FILENO); + setlinebuf(stderr); + pwtest_errno_ok(rc); + + setenv("PIPEWIRE_DEBUG", envvars[which], 1); + pw_init(0, NULL); + + fsync(STDERR_FILENO); + lseek(fd, SEEK_SET, 0); + while ((rc = read(fd, buf, sizeof(buf) - 1) > 0)) { + if (strstr(buf, "Ignoring invalid format in PIPEWIRE_DEBUG")) { + error_message_found = true; + break; + } + } + pwtest_errno_ok(rc); + close(fd); + pwtest_bool_true(error_message_found); + + if (oldenv) { + setenv("PIPEWIRE_DEBUG", oldenv, 1); + free(oldenv); + } else { + unsetenv("PIPEWIRE_DEBUG"); + } + + pw_log_set(default_logger); + pw_log_set_level(default_level); + pw_deinit(); + + return PWTEST_PASS; +} + PWTEST(logger_topics) { struct pwtest_spa_plugin *plugin; @@ -503,6 +612,12 @@ 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_debug_env_topic_all, + PWTEST_ARG_RANGE, SPA_LOG_LEVEL_NONE, SPA_LOG_LEVEL_TRACE + 1, + PWTEST_NOARG); + pwtest_add(logger_debug_env_invalid, + PWTEST_ARG_RANGE, 0, 5, /* see the test */ + PWTEST_NOARG); pwtest_add(logger_topics, PWTEST_NOARG); pwtest_add(logger_journal, PWTEST_NOARG); pwtest_add(logger_journal_chain, PWTEST_NOARG);