[BUG][Zephyr] IPC error for FILTER_UPDATE when kmod unload after playback on Zephyr platforms #5032
Description
Describe the bug
IPC error when SOF kernel modules unload after playback on most Zephyr platforms.
This issue has happened in recent daily test results since 11/24/2021.
To Reproduce
play the audio and then unload SOF modules, e.g.
TPLG=/lib/firmware/intel/sof-tplg/sof-hda-generic-4ch.tplg MODEL=WHL_UPEXT_HDA_ZEPHYR ~/sof-test/test-case/check-kmod-load-unload-after-playback.sh
Reproduction Rate
Not 100%, but can be reproduced in the first iteration on most Zephyr platforms.
Environment
Kernel Branch: topic/sof-dev
Kernel Commit: thesofproject/linux@d5c4c30a
SOF Branch: main
SOF Commit: f41010d3868d
Zephyr Branch: main
Zephyr Commit: zephyrproject-rtos/zephyr@f8f2936dbac3
platforms: Zephyr-based platforms, like APL_UP2_NOCODEC_ZEPHYR, TGLH_RVP_NOCODEC_ZEPHYR, WHL_UPEXT_HDA_ZEPHYR...
Screenshots or console output
Take WHL_UPEXT_HDA_ZEPHYR as an example:
[dmesg]
[ 6126.749284] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x30110000: GLB_TPLG_MSG: PIPE_FREE
[ 6126.749379] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 6126.749399] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 6126.750077] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx succeeded: 0x30110000: GLB_TPLG_MSG: PIPE_FREE
[ 6126.750091] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: widget PIPELINE.9.HDA6.OUT freed
[ 6126.750261] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: close stream 5 dir 0
[ 6126.750402] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 6126.750448] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 6126.751423] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 6126.751462] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 6127.093836] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x90040000: GLB_TRACE_MSG: FILTER_UPDATE
[ 6127.094070] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx error for 0x90040000 (msg/reply size: 60/12): -22
[ 6127.094079] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: fail in sof_ipc_trace_update_filter -22
[ 6127.098105] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 6127.098139] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 6127.098402] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 6127.098454] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 6127.260544] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x90040000: GLB_TRACE_MSG: FILTER_UPDATE
[ 6127.260771] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx error for 0x90040000 (msg/reply size: 60/12): -22
[ 6127.260781] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: fail in sof_ipc_trace_update_filter -22
[ 6127.264810] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 6127.264843] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[sof-logger]
[ 15712546.406890] ( 300.416656) c0 ipc src/ipc/ipc3/handler.c:1576 INFO ipc: new cmd 0x30110000
[ 15712561.250639] ( 14.843749) c0 ipc src/ipc/ipc3/handler.c:1358 INFO ipc: comp 62 -> free
[ 15712573.646472] ( 12.395833) c0 pipe 9.62 ......./pipeline-graph.c:194 INFO pipeline_free()
[ 16143167.639778] ( 430594.000000) c0 ipc src/ipc/ipc3/handler.c:1576 INFO ipc: new cmd 0x90040000
[ 16143180.400194] ( 12.760416) c0 ipc src/ipc/ipc3/handler.c:912 INFO ipc: debug cmd 0x40000
[ 16143192.691860] ( 12.291666) c0 ipc src/ipc/ipc3/handler.c:882 INFO ipc: trace_filter_update received, size 2 elems
[ 16143200.660610] ( 7.968750) c0 ipc src/ipc/ipc3/handler.c:894 ERROR trace_filter_update failed for UUID key 0x1FFFA6C0, comp -1.-1 and log level 3
[ 16351543.308581] ( 208342.640625) c0 ipc src/ipc/ipc3/handler.c:1576 INFO ipc: new cmd 0x90040000
[ 16351551.068998] ( 7.760417) c0 ipc src/ipc/ipc3/handler.c:912 INFO ipc: debug cmd 0x40000
[ 16351558.412747] ( 7.343750) c0 ipc src/ipc/ipc3/handler.c:882 INFO ipc: trace_filter_update received, size 2 elems
[ 16351566.381497] ( 7.968750) c0 ipc src/ipc/ipc3/handler.c:894 ERROR trace_filter_update failed for UUID key 0x1FFFA6C0, comp -1.-1 and log level 3
[ 16637477.568053] ( 285911.187500) c0 zll-schedule src/schedule/zephyr_ll.c:132 INFO ll task 0x9e0751b0 agent-work avg 79, max 386
[ 16637506.109718] ( 28.541666) c0 zll-schedule ......../zephyr_domain.c:89 INFO ll timer avg 1032, max 3732, overruns 0
[console]
Hardware PCM card 0 'sof-hda-dsp' device 0 subdevice 0
Its setup is:
stream : PLAYBACK
access : RW_INTERLEAVED
format : S16_LE
subformat : STD
channels : 2
rate : 48000
exact rate : 48000 (48000/1)
msbits : 16
buffer_size : 16384
period_size : 4096
period_time : 85333
tstamp_mode : NONE
tstamp_type : MONOTONIC
period_step : 1
avail_min : 4096
period_event : 0
start_threshold : 16384
stop_threshold : 16384
silence_threshold: 0
silence_size : 0
boundary : 4611686018427387904
appl_ptr : 0
hw_ptr : 0
2021-11-23 23:08:47 UTC Sub-Test: [REMOTE_INFO] ===== Testing: (Round: 1/1) (PCM: HDMI1 [hw:0,3]) (Loop: 1/1) =====
2021-11-23 23:08:47 UTC Sub-Test: [REMOTE_COMMAND] aplay -Dhw:0,3 -r 48000 -c 2 -f S16_LE -d 3 /dev/zero -v -q
Hardware PCM card 0 'sof-hda-dsp' device 3 subdevice 0
Its setup is:
stream : PLAYBACK
access : RW_INTERLEAVED
format : S16_LE
subformat : STD
channels : 2
rate : 48000
exact rate : 48000 (48000/1)
msbits : 16
buffer_size : 16384
period_size : 4096
period_time : 85333
tstamp_mode : NONE
tstamp_type : MONOTONIC
period_step : 1
avail_min : 4096
period_event : 0
start_threshold : 16384
stop_threshold : 16384
silence_threshold: 0
silence_size : 0
boundary : 4611686018427387904
appl_ptr : 0
hw_ptr : 0
2021-11-23 23:08:50 UTC Sub-Test: [REMOTE_INFO] ===== Testing: (Round: 1/1) (PCM: HDMI2 [hw:0,4]) (Loop: 1/1) =====
2021-11-23 23:08:50 UTC Sub-Test: [REMOTE_COMMAND] aplay -Dhw:0,4 -r 48000 -c 2 -f S16_LE -d 3 /dev/zero -v -q
Hardware PCM card 0 'sof-hda-dsp' device 4 subdevice 0
Its setup is:
stream : PLAYBACK
access : RW_INTERLEAVED
format : S16_LE
subformat : STD
channels : 2
rate : 48000
exact rate : 48000 (48000/1)
msbits : 16
buffer_size : 16384
period_size : 4096
period_time : 85333
tstamp_mode : NONE
tstamp_type : MONOTONIC
period_step : 1
avail_min : 4096
period_event : 0
start_threshold : 16384
stop_threshold : 16384
silence_threshold: 0
silence_size : 0
boundary : 4611686018427387904
appl_ptr : 0
hw_ptr : 0
2021-11-23 23:08:53 UTC Sub-Test: [REMOTE_INFO] ===== Testing: (Round: 1/1) (PCM: HDMI3 [hw:0,5]) (Loop: 1/1) =====
2021-11-23 23:08:53 UTC Sub-Test: [REMOTE_COMMAND] aplay -Dhw:0,5 -r 48000 -c 2 -f S16_LE -d 3 /dev/zero -v -q
Hardware PCM card 0 'sof-hda-dsp' device 5 subdevice 0
Its setup is:
stream : PLAYBACK
access : RW_INTERLEAVED
format : S16_LE
subformat : STD
channels : 2
rate : 48000
exact rate : 48000 (48000/1)
msbits : 16
buffer_size : 16384
period_size : 4096
period_time : 85333
tstamp_mode : NONE
tstamp_type : MONOTONIC
period_step : 1
avail_min : 4096
period_event : 0
start_threshold : 16384
stop_threshold : 16384
silence_threshold: 0
silence_size : 0
boundary : 4611686018427387904
appl_ptr : 0
hw_ptr : 0
declare -- cmd="journalctl_cmd --since=@1637708919"
2021-11-23 23:08:58 UTC Sub-Test: [REMOTE_INFO] pkill -TERM sof-logger
Terminated
2021-11-23 23:08:59 UTC Sub-Test: [REMOTE_INFO] nlines=491 /home/ubuntu/sof-test/logs/check-kmod-load-unload-after-playback/2021-11-23-23:08:43-25038/slogger.txt
2021-11-23 23:08:59 UTC Sub-Test: [REMOTE_INFO] Test Result: PASS!
2021-11-23 23:08:59 UTC [REMOTE_INFO] ===== Starting iteration 1 of 5 =====
2021-11-23 23:08:59 UTC Sub-Test: [REMOTE_INFO] ===== Starting iteration 1 of 1 =====
2021-11-23 23:08:59 UTC Sub-Test: [REMOTE_INFO] wait dsp power status to become suspended
2021-11-23 23:08:59 UTC Sub-Test: [REMOTE_INFO] run kmod/sof-kmod-remove.sh
WARNING: running as root is not supported
RMMOD snd_usb_audio
SKIP snd_hda_intel not loaded
RMMOD snd_sof_pci_intel_tng
RMMOD snd_sof_pci_intel_apl
RMMOD snd_sof_pci_intel_cnl
RMMOD snd_sof_pci_intel_icl
RMMOD snd_sof_pci_intel_tgl
RMMOD snd_sof_acpi_intel_byt
RMMOD snd_sof_acpi_intel_bdw
RMMOD snd_sof_intel_hda_common
RMMOD snd_sof_acpi
RMMOD snd_sof_pci
RMMOD snd_sof_intel_atom
SKIP snd_soc_catpt not loaded
SKIP snd_intel_sst_acpi not loaded
SKIP snd_intel_sst_core not loaded
SKIP snd_soc_sst_atom_hifi2_platform not loaded
SKIP snd_soc_skl not loaded
SKIP snd_sof_intel_byt not loaded
SKIP snd_sof_intel_bdw not loaded
SKIP snd_sof_intel_hda_common not loaded
RMMOD snd_sof_intel_hda
SKIP snd_sof_intel_ipc not loaded
RMMOD snd_sof_xtensa_dsp
RMMOD snd_soc_acpi_intel_match
SKIP snd_soc_sof_rt5682 not loaded
SKIP snd_soc_sof_da7219_max98373 not loaded
SKIP snd_soc_sst_bdw_rt5677_mach not loaded
SKIP snd_soc_sst_broadwell not loaded
SKIP snd_soc_sst_bxt_da7219_max98357a not loaded
SKIP snd_soc_sst_sof_pcm512x not loaded
SKIP snd_soc_sst_bxt_rt298 not loaded
SKIP snd_soc_sst_sof_wm8804 not loaded
SKIP snd_soc_sst_byt_cht_da7213 not loaded
SKIP snd_soc_sst_byt_cht_es8316 not loaded
SKIP snd_soc_sst_bytcr_rt5640 not loaded
SKIP snd_soc_sst_bytcr_rt5651 not loaded
SKIP snd_soc_sst_cht_bsw_max98090_ti not loaded
SKIP snd_soc_sst_cht_bsw_nau8824 not loaded
SKIP snd_soc_sst_cht_bsw_rt5645 not loaded
SKIP snd_soc_sst_cht_bsw_rt5672 not loaded
SKIP snd_soc_sst_glk_rt5682_max98357a not loaded
SKIP snd_soc_cml_rt1011_rt5682 not loaded
RMMOD snd_soc_skl_hda_dsp
SKIP snd_soc_sdw_rt700 not loaded
SKIP snd_soc_sdw_rt711_rt1308_rt715 not loaded
SKIP snd_soc_sof_sdw not loaded
SKIP snd_soc_ehl_rt5660 not loaded
RMMOD snd_soc_intel_hda_dsp_common
SKIP snd_soc_intel_sof_maxim_common not loaded
RMMOD snd_sof_probes
SKIP snd_sof_ipc_test not loaded
RMMOD snd_sof_ipc_flood_test
RMMOD snd_sof_ipc_msg_injector
SKIP snd_sof_dma_trace not loaded
SKIP snd_sof_nocodec not loaded
RMMOD snd_sof
SKIP snd_sof_nocodec not loaded
RMMOD snd_sof_utils
RMMOD snd_soc_da7213
RMMOD snd_soc_da7219
RMMOD snd_soc_pcm512x_i2c
RMMOD snd_soc_pcm512x
SKIP snd_soc_rt274 not loaded
RMMOD snd_soc_rt286
RMMOD snd_soc_rt298
RMMOD snd_soc_rt700
RMMOD snd_soc_rt711
RMMOD snd_soc_rt1308
RMMOD snd_soc_rt1308_sdw
RMMOD snd_soc_rt715
SKIP snd_soc_rt711_sdca not loaded
SKIP snd_soc_rt1316_sdw not loaded
SKIP snd_soc_rt715_sdca not loaded
SKIP snd_soc_sdw_mockup not loaded
RMMOD snd_soc_rt1011
RMMOD snd_soc_rt5640
RMMOD snd_soc_rt5645
RMMOD snd_soc_rt5651
RMMOD snd_soc_rt5660
RMMOD snd_soc_rt5670
RMMOD snd_soc_rt5677
RMMOD snd_soc_rt5677_spi
RMMOD snd_soc_rt5682_sdw
RMMOD snd_soc_rt5682_i2c
RMMOD snd_soc_rt5682
SKIP snd_soc_rt5682s not loaded
RMMOD snd_soc_rl6231
RMMOD snd_soc_rl6347a
RMMOD snd_soc_wm8804_i2c
RMMOD snd_soc_wm8804
RMMOD snd_soc_max98090
SKIP snd_soc_ts3a227e not loaded
RMMOD snd_soc_max98357a
RMMOD snd_soc_max98373_sdw
RMMOD snd_soc_max98373_i2c
RMMOD snd_soc_max98373
RMMOD snd_soc_hdac_hda
RMMOD snd_soc_hdac_hdmi
RMMOD snd_hda_codec_hdmi
RMMOD snd_soc_dmic
RMMOD snd_hda_codec_realtek
RMMOD snd_hda_codec_generic
RMMOD snd_soc_acpi
RMMOD snd_hda_ext_core
RMMOD snd_intel_dspcfg
SKIP soundwire_intel_init not loaded
RMMOD soundwire_intel
RMMOD soundwire_cadence
RMMOD soundwire_generic_allocation
RMMOD regmap_sdw
SKIP regmap_sdw_mbq not loaded
RMMOD soundwire_bus
RMMOD snd_intel_sdw_acpi
RMMOD snd_soc_core
RMMOD snd_hda_codec
RMMOD snd_hda_core
RMMOD snd_hwdep
RMMOD snd_compress
SKIP snd_pcm_dmaengine not loaded
RMMOD snd_pcm
2021-11-23 23:09:02 UTC Sub-Test: [REMOTE_INFO] checking for general errors after kmod unload with sof-kernel-log-check tool
declare -- cmd="journalctl_cmd --since=@1637708934"
2021-11-23 23:09:02 UTC [ERROR] Caught kernel log error
===========================>>
[ 6127.094070] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx error for 0x90040000 (msg/reply size: 60/12): -22
[ 6127.094079] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: fail in sof_ipc_trace_update_filter -22
[ 6127.260771] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx error for 0x90040000 (msg/reply size: 60/12): -22
[ 6127.260781] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: error: fail in sof_ipc_trace_update_filter -22
<<===========================