Skip to content

Extend the use of debug categories though log topics

Peter Hutterer requested to merge whot/pipewire:wip/debug-categories into master

This MR attempts to improve the wall of messages that scroll past when the log level is set to debug. We already have support for categories but the only user seems to be the protocol debugging. The goal here is to eventually have most debug messages assigned to a topic so we can select or filter those.

This is implemented in SPA and the current loggers we ship. For configuration a new SPA_KEY_LOG_PATTERNS as a JSON array of [ {"pattern" : level}, ... can be supplied to the logger. Our provided logger.c and journal.c have been updated accordingly.

The approach is mainly modeled after gstreamer. A caller initializes a struct spa_log_topic which may have a custom log level, assigned during spa_log_topic_init(). In SPA plugins this would typically be used like this:

struct spa_log_topic mytopic = SPA_LOG_TOPIC(0, "my.topic");
#undef SPA_LOG_TOPIC_DEFAULT
#define SPA_LOG_TOPIC_DEFAULT (&mytopic)

void init(...) {
    spa_logt_debug(&mytopic, "explicitly logs through the given topic");
    spa_log_debug("Will be routed through the default topic");
}

In pipewire, there's another layer of wrapping to make it use the right logger, typically used like this:

PW_LOG_TOPIC_STATIC(mytopic, "my.topic");
#define PW_LOG_TOPIC_DEFAULT mytopic

void init(...) {
   PW_LOG_INIT(mytopic);

   pw_logt_debug(somevar, "this explicitly logs through mytopic"); 
   pw_log_debug("this also logs through mytopic thanks to the PW_LOG_TOPIC_DEFAULT define");
}

Most of pipewire, its modules, media session and its modules and some of the SPA plugins have been switched to log topics. With those, the output is now

$ export PIPEWIRE_LOG_LINE=false
$ export PIPEWIRE_DEBUG="*:I,pw.*:I,spa.*:D,mod.*:D,conn.*:0"
$ pipewire                                                   
[D][20702.503170] spa.cpu      |  0x55ccfbf0ab08: count:16 align:32 flags:0007cbdb
[I][20702.503207] pw.context   |  version 0.3.37
[D][20702.503224] spa.system   |  0x55ccfbf0afb8: initialized
[D][20702.503241] spa.system   |  0x55ccfbf0afb8: new fd:4
[D][20702.503247] spa.system   |  0x55ccfbf0afb8: new fd:5
[D][20702.503280] spa.system   |  0x55ccfbf0afb8: new fd:6
[D][20702.503284] spa.loop     |  0x55ccfbf0b128: initialized
[D][20702.503290] spa.system   |  0x55ccfbf0afb8: new fd:7
[D][20702.503297] spa.system   |  0x55ccfbf0afb8: new fd:8
[D][20702.503303] spa.system   |  0x55ccfbf0afb8: new fd:9
[I][20702.503404] pw.context   |  0x55ccfbf136c0: parsed context.properties section
[D][20702.503459] spa.system   |  0x55ccfbf177d8: initialized
[D][20702.503476] spa.system   |  0x55ccfbf177d8: new fd:10
[D][20702.503482] spa.system   |  0x55ccfbf177d8: new fd:11
[D][20702.503488] spa.system   |  0x55ccfbf177d8: new fd:12
[D][20702.503493] spa.loop     |  0x55ccfbf17888: initialized
[D][20702.503499] spa.system   |  0x55ccfbf177d8: new fd:13
[I][20702.503792] pw.context   |  0x55ccfbf136c0: parsed 8 context.spa-libs items
[D][20702.509503] mod.protocol-native |  0x55ccfbf2d790: new debug:0
[D][20702.509519] mod.protocol-native |  0x55ccfbf2d790: created server 0x55ccfbf2dba0
[D][20702.509527] mod.protocol-native |  0x55ccfbf2d790: created server 0x55ccfbf2dd60
[D][20702.509532] mod.protocol-native |  name:pipewire-0 runtime_dir:/run/user/1000
[D][20702.509661] spa.system   |  0x55ccfbf0afb8: new fd:17
[I][20702.509671] mod.protocol-native |  0x55ccfbf2d790: Listening on 'pipewire-0'
[D][20702.509735] spa.system   |  0x55ccfbf0afb8: new fd:18
[D][20702.509788] mod.metadata |  module 0x55ccfbf2f690: new
[D][20702.509988] mod.client-node |  module 0x55ccfbf33190: new
[D][20702.510044] mod.client-device |  module 0x55ccfbf34530: new
...

Topic log levels are set through PIPEWIRE_DEBUG which supports fnmatch, so we can have something like: PIPEWIRE_DEBUG="*:I,mod.*:E,mod.access:D" which reads as "everything on INFO, modules on ERROR but the access module on DEBUG".

Thoughts?

Summary significantly edited for v4 of the patch.

Edited by Peter Hutterer

Merge request reports