log: add topic loggers and a default topic

pw_log_log/logv now go through the topic-based logger using the
"default" topic. Log topics themselves can be allocated by the call
sites. The simplest way to use a topic from e.g. a module:

    PW_LOG_TOPIC_STATIC(mod_topic, "mod.foo");
    #define PW_LOG_TOPIC_DEFAULT mod_topic
    ...
    void pipewire__module_init() {
  	  PW_LOG_TOPIC_INIT(mod_topic);
  	  ...
    }

With the #define all pw_log_foo() are now routed through the custom
topic. For the cases where the log topic must be specified, a
pw_logt_foo() set of macros is available.

Log topics are enabled through the PIPEWIRE_DEBUG environment variable
which now supports globs, e.g. PIPEWIRE_DEBUG="*:I;mod.access:D"
to enable global INFO but DEBUG for the access module.

Namespaces documented are "pw", "mod" and "conn", for pipewire-internal
stuff, modules and connection dumping. The latter is special-cased to
avoid spamming the log files, it requires an expcit "conn.<glob>"
pattern to enable.

The "default" topic always exists and is the fallback for any
pw_log_foo() invocation that does not use a topic.

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:
 
-`<level>[<category>,<category>,...]`
+- `PIPEWIRE_DEBUG=<level>` where `<level>` is either a numerical log level or it's
+   respective key, see below.
+- `PIPEWIRE_DEBUG=<glob1>:<level1>,<glob2>:<level2>,...` 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.
 
 - `<level>` 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.
 
-- `<category>`:  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>` glob.
 
 
 The behavior of the logging can be further controlled with the following

src/pipewire/log.c

@@ -22,11 +22,15 @@
  * DEALINGS IN THE SOFTWARE.
  */
 
+#include <limits.h>
+#include <fnmatch.h>
+
 #include <spa/support/log-impl.h>
 
 #include <spa/pod/pod.h>
 #include <spa/debug/types.h>
 #include <spa/pod/iter.h>
+#include <spa/utils/list.h>
 
 #include <pipewire/log.h>
 #include <pipewire/private.h>
@@ -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);
+}

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

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

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

test/test-logger.c

@@ -24,6 +24,7 @@
 
 #include "pwtest.h"
 
+#include <fcntl.h>
 #include <unistd.h>
 
 #include <spa/utils/ansi.h>
@@ -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);