[BUG]sof-logger filter is not working

[xiulipan]

Describe the bug
When try to use sof-logger with filter feature with WIKI guide from https://thesofproject.github.io/latest/developer_guides/debugability/logger/index.html?highlight=logger#trace-filtering
The logger always report error with

$ sudo sof-logger -l /home/ubuntu/pxl/sof-cnl.ldc -t -Fv=*
error: Unable to open version file =*

or

$ sudo sof-logger -l /home/ubuntu/pxl/sof-cnl.ldc -t -Fd=*
error: Multiple ldc files

To Reproduce

sudo sof-logger -l /home/ubuntu/pxl/sof-cnl.ldc -t -Fc=*
error: unable to find `=` in `(null)`
error: failed to apply trace filter, -22.

Reproduction Rate
10/10

Expected behavior
The logger should be able to accept the parameters and change the filter

Impact
unable to use VERBOSE trace to debug.

Environment
latest SOF with 8a5059a

[xiulipan]

Root cause to be

sof/tools/logger/logger.c

Line 164 in 8a5059a

static const char optstring[] = "ho:i:l:ps:c:u:tv:rd:Lf:gFn";

optstring changed by #3326

It should be
static const char optstring[] = "ho:i:l:ps:c:u:tv:rd:Lf:gF:n

[xiulipan]

After the logger fix, still got error from dmesg:

[ 5383.302121] sof-audio-pci 0000:00:1f.3: error: invalid trace filter entry '
               '
[ 5383.302124] sof-audio-pci 0000:00:1f.3: error: trace_filter_parse failed for '
               ', -22
[ 5383.302125] sof-audio-pci 0000:00:1f.3: error: fail in trace_filter_parse, -22

[xiulipan]

@ktrzcinx After add some debug logs and find the issue is caused by unhandled "\n"

[ 2204.062403] sof-audio-pci 0000:00:0e.0: PXL: sof_dfsentry_trace_filter_write 4 1FFFA120 -1 -1;4 1FFFA1E0 -1 -1;

[ 2204.062419] sof-audio-pci 0000:00:0e.0: PXL: trace_filter_parse_entry got line '4 1FFFA120 -1 -1'
[ 2204.062431] sof-audio-pci 0000:00:0e.0: PXL: trace_filter_parse_entry got line '4 1FFFA1E0 -1 -1'
[ 2204.062438] sof-audio-pci 0000:00:0e.0: PXL: trace_filter_parse_entry got line '
               '
[ 2204.062443] sof-audio-pci 0000:00:0e.0: error: invalid trace filter entry '
               '
[ 2204.062450] sof-audio-pci 0000:00:0e.0: error: trace_filter_parse failed for '
               ', -22
[ 2204.062456] sof-audio-pci 0000:00:0e.0: error: fail in trace_filter_parse, -22

After add some hack into the kernel it seems the ipc can be send now.

diff --git a/sound/soc/sof/trace.c b/sound/soc/sof/trace.c
index 90152daf0a95..3807a0185e88 100644
--- a/sound/soc/sof/trace.c
+++ b/sound/soc/sof/trace.c
@@ -169,6 +169,7 @@ static ssize_t sof_dfsentry_trace_filter_write(struct file *file, const char __u
        int num_elems;
        char *string;
        int ret;
+       char *tmp;
 
        if (count > TRACE_FILTER_MAX_CONFIG_STRING_LENGTH) {
                dev_err(sdev->dev, "%s too long input, %zu > %d\n", __func__, count,
@@ -186,6 +187,11 @@ static ssize_t sof_dfsentry_trace_filter_write(struct file *file, const char __u
        if (ret < 0)
                goto error;
 
+       tmp = strstr(string, "\n");
+       *tmp = 0;
+
+       dev_err(sdev->dev, "PXL: sof_dfsentry_trace_filter_write %s\n", string);
+
        ret = trace_filter_parse(sdev, string, &num_elems, &elems);
        if (ret < 0) {
                dev_err(sdev->dev, "error: fail in trace_filter_parse, %d\n", ret);

And I got some wired outptut in trace:
ubuntu@sh-apl-up2-pcm512x-03:~/pxl$ sudo ./sof-logger -l /etc/sof/sof-apl.ldc -t -Fc=* -Fi=ipc,pipe

I try to filter all error message and only allow ipc and pipe logs, but it seems there are more logs came. Any idea? @ktrzcinx

[2582928987.500000] ( 50678768.000000) c0 ipc                       src/ipc/handler.c:805  ipc: debug cmd 0x40000
[2582928991.510417] (        4.010417) c0 ipc                       src/ipc/handler.c:775  ipc: trace_filter_update received, size 5 elems
[2582929006.822917] (       15.312500) c0 ipc                       src/ipc/handler.c:792  trace_filter_update for UUID key 0x0, comp -1.-1 affected 57 components
[2582929019.947917] (       13.125000) c0 ipc                       src/ipc/handler.c:792  trace_filter_update for UUID key 0x1FFFA060, comp -1.-1 affected 1 components
[2582929032.812500] (       12.864583) c0 ipc                       src/ipc/handler.c:792  trace_filter_update for UUID key 0x1FFFA120, comp -1.-1 affected 9 components
[2589327446.302083] (  6398413.500000) c0 pipe         1.9       src/audio/pipeline.c:538  pipe params dir 0 frame_fmt 0 buffer_fmt 0 rate 48000
[2589327450.520833] (        4.218750) c0 pipe         1.9       src/audio/pipeline.c:542  pipe params stream_tag 1 channels 2 sample_valid_bytes 2 sample_container_bytes 2
[2589327482.500000] (       31.979166) c0 hda-dma            ..../intel/hda/hda-dma.c:479  hda-dmac: 5 channel 0 -> get
[2589327487.343750] (        4.843750) c0 hda-dma            ..../intel/hda/hda-dma.c:672  hda-dmac: 5 channel 0 -> config
[2589327529.895833] (       42.552082) c0 pipe         1.9       src/audio/pipeline.c:669  pipe prepare
[2589343826.927083] (    16297.031250) c0 pipe         1.9       src/audio/pipeline.c:863  pipe trigger cmd 1
[2589343832.812500] (        5.885417) c0 hda-dma            ..../intel/hda/hda-dma.c:536  hda-dmac: 5 channel 0 -> start
[2589343836.770833] (        3.958333) c0 hda-dma            ..../intel/hda/hda-dma.c:393  hda-dmac: 5 channel 0 -> enable
[2589343881.614583] (       44.843750) c0 ssp-dai      1.5   /drivers/intel/ssp/ssp.c:779  ssp_trigger() cmd 1
[2589343886.406250] (        4.791667) c0 ssp-dai      1.5   /drivers/intel/ssp/ssp.c:698  ssp_start()
[2589343938.958333] (       52.552082) c0 ll-schedule        ./schedule/ll_schedule.c:345  task add 0xbe04c300 pipe-task <f11818eb-e92e-4082-82a3-dc54c604ebb3>
[2589343942.812500] (        3.854167) c0 ll-schedule        ./schedule/ll_schedule.c:349  task params pri 0 flags 0 start 0 period 1000
[2589343947.656250] (        4.843750) c0 ll-schedule        ./schedule/ll_schedule.c:252  num_tasks 3 total_num_tasks 3
[2589344271.354167] (      323.697906) c0 ll-schedule        ./schedule/ll_schedule.c:202  perf ll_work peak plat 1877 cpu 31222
[2602810564.947917] ( 13466294.000000) c0 pipe         1.9       src/audio/pipeline.c:863  pipe trigger cmd 0
[2602810570.677083] (        5.729167) c0 hda-dma            ..../intel/hda/hda-dma.c:619  hda-dmac: 5 channel 0 -> stop
[2602810581.406250] (       10.729167) c0 dw-dma                 src/drivers/dw/dma.c:406  dw_dma_stop(): dma 0 channel 1 stop
[2602810586.875000] (        5.468750) c0 ssp-dai      1.5   /drivers/intel/ssp/ssp.c:779  ssp_trigger() cmd 0
[2602810755.572917] (      168.697922) c0 ssp-dai      1.5   /drivers/intel/ssp/ssp.c:750  ssp_stop(), TX stop

[ktrzcinx]

@xiulipan you see probably traces cached before logger-run, it's because filtering rejects messages in FW, so messages sent before setting up filters are just shown.

[xiulipan]

@ktrzcinx I just copy paste the log from the trace debug IPC, so I think the following logs should all follow the filter right?
Could you provide a way for us to test the filter feature? We would like to add a test case for this in sof-test.
PS: could you help to provide a PR to fix the \n parse? I do not think my hack is a good solution.

[2582928987.500000] ( 50678768.000000) c0 ipc                       src/ipc/handler.c:805  ipc: debug cmd 0x40000
[2582928991.510417] (        4.010417) c0 ipc                       src/ipc/handler.c:775  ipc: trace_filter_update received, size 5 elems
[2582929006.822917] (       15.312500) c0 ipc                       src/ipc/handler.c:792  trace_filter_update for UUID key 0x0, comp -1.-1 affected 57 components
[2582929019.947917] (       13.125000) c0 ipc                       src/ipc/handler.c:792  trace_filter_update for UUID key 0x1FFFA060, comp -1.-1 affected 1 components
[2582929032.812500] (       12.864583) c0 ipc                       src/ipc/handler.c:792  trace_filter_update for UUID key 0x1FFFA120, comp -1.-1 affected 9 components

[ktrzcinx]

so I think the following logs should all follow the filter right

Yes, I've added extra explanation in thesofproject/sof-docs#299

We would like to add a test case for this in sof-test.

Great idea.

Could you provide a way for us to test the filter feature?

There are two main aspects

1. optarg parsing - -F option argument has a quite wide possible range of input (1. single component instance 2. single component type 3. single pipeline 4. single component type on pipeline 5. every component)
2. Check if feature works as a whole

After setting up filters we will expect to receive only traces corresponding to used setup. If something won't be clear just let me know.

PS: could you help to provide a PR to fix the \n parse? I do not think my hack is a good solution.

Ok, I will do this.

[xiulipan]

@ktrzcinx New discussion issue for logger filter test case is thesofproject/sof-test#457