[BUG] Green failure on check-suspend-resume-without-audio

[miRoox]

Describe the bug
The kernel error during reloading the audio module won't be reported. It hides thesofproject/sof#5733.

To Reproduce

TPLG=/lib/firmware/intel/sof-tplg/sof-adl-max98390-rt5682.tplg MODEL=ADLP_GMB_I2S_ZEPHYR ~/sof-test/test-case/check-suspend-resume.sh -l 1 -u

Expected behavior
The test result should be FAIL if there is an error in the kernel log.

Detail Info

1. Branch name and commit hash of the 3 repositories: sof (firmware/topology), linux (kernel driver) and sof-test (test case)
   • Kernel: thesofproject/linux@63cecc81ad57
   • SOF: thesofproject/sof@95d6499ad6b4
   • SOF-TEST: 4c324a4
2. Test report ID (if you find it from test report)
   • ID: 13515
3. Test DUT Model (or a brief discribtion about the device)
   • MODEL: ADLP_GMB_I2S_ZEPHYR
4. Test TPLG
   • TPLG: sof-adl-max98390-rt5682.tplg
5. Test case (what test script and how you run it)
   • TESTCASE: check-suspend-resume.sh -l 1 -u

Screenshots or console output

console output

2022-06-23 23:32:01 UTC [REMOTE_INFO] Check for the kernel log status
declare -- cmd="journalctl_cmd --since=@1656027108"
2022-06-23 23:32:02 UTC [REMOTE_INFO] Check for wakeup_count and suspend_stats
MODPROBE	snd_soc_da7213		 
MODPROBE	snd_soc_da7219		 
MODPROBE	snd_soc_pcm512x_i2c		 
MODPROBE	snd_soc_wm8804_i2c		 
SKIP    	snd_soc_rt274 	(not in tree)
MODPROBE	snd_soc_rt286		 
MODPROBE	snd_soc_rt298		 
MODPROBE	snd_soc_rt700		 
MODPROBE	snd_soc_rt711		 
MODPROBE	snd_soc_rt1308		 
MODPROBE	snd_soc_rt1308_sdw		 
MODPROBE	snd_soc_rt715		 
MODPROBE	snd_soc_rt711_sdca		 
MODPROBE	snd_soc_rt1316_sdw		 
MODPROBE	snd_soc_rt715_sdca		 
MODPROBE	snd_soc_sdw_mockup		 
MODPROBE	snd_soc_rt1011		 
MODPROBE	snd_soc_rt5640		 
MODPROBE	snd_soc_rt5645		 
MODPROBE	snd_soc_rt5651		 
MODPROBE	snd_soc_rt5660		 
MODPROBE	snd_soc_rt5670		 
MODPROBE	snd_soc_rt5677		 
MODPROBE	snd_soc_rt5677_spi		 
MODPROBE	snd_soc_rt5682_i2c		 
MODPROBE	snd_soc_rt5682_sdw		 
MODPROBE	snd_soc_max98090		 
MODPROBE	snd_soc_ts3a227e		 
MODPROBE	snd_soc_max98357a		 
MODPROBE	snd_soc_max98373_sdw		 
MODPROBE	snd_soc_max98373_i2c		 
MODPROBE	snd_soc_max98390		 
MODPROBE	snd_soc_es8316		 
SKIP    	snd_soc_es8326 	(not in tree)
MODPROBE	snd_sof_acpi		 
MODPROBE	snd_sof_acpi_intel_byt		 
MODPROBE	snd_sof_acpi_intel_bdw		 
MODPROBE	snd_sof_pci		 
MODPROBE	snd_sof_pci_intel_tng		 
MODPROBE	snd_sof_pci_intel_skl		 
MODPROBE	snd_sof_pci_intel_apl		 
MODPROBE	snd_sof_pci_intel_cnl		 
MODPROBE	snd_sof_pci_intel_icl		 
MODPROBE	snd_sof_pci_intel_tgl		 
MODPROBE	snd_sof_pci_intel_mtl		 
MODPROBE	snd_usb_audio		 
declare -- cmd="journalctl_cmd --since=@1656027108"
2022-06-23 23:32:03 UTC [REMOTE_INFO] ktime=254 sof-test PID=14623: ending
+ timeout -s CONT 7 sudo sync

real	0m0.020s
user	0m0.003s
sys	0m0.004s
+ timeout -s CONT 5 dd if=/dev/zero of=/home/ubuntu/HD_TEST_DELETE_ME bs=1M count=100 conv=fsync
100+0 records in
100+0 records out
104857600 bytes (105 MB, 100 MiB) copied, 0.180333 s, 581 MB/s
+ timeout -s CONT 7 sudo sync

real	0m0.019s
user	0m0.005s
sys	0m0.009s
2022-06-23 23:32:03 UTC [REMOTE_INFO] Test Result: PASS!

dmesg

[  360.904592] kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x90030000: GLB_TRACE_MSG: DMA_PARAMS_EXT
[  361.405470] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x90030000 (msg/reply size: 80/12)
[  361.405477] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: preventing DSP entering D3 state to preserve context
[  361.405479] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[  361.405496] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
[  361.405498] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[  361.405506] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  361.405508] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[  361.405509] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[  361.405510] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[  361.405511] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (6)
[  361.405516] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: status: fw entered - code 00000005
[  361.405729] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: unexpected fault 0x00000000 trace 0x00004000
[  361.405731] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[  361.405733] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: can't set params for DMA for trace -110
[  361.405756] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to initialize firmware tracing -110
[  361.405958] kernel: snd_sof:sof_machine_register: sof-audio-pci-intel-tgl 0000:00:1f.3: created machine adl_max98390_rt5682
[  361.406243] kernel: snd_sof_pci:sof_pci_probe_complete: sof-audio-pci-intel-tgl 0000:00:1f.3: Completing SOF PCI probe
[  361.410300] kernel: rt5682s i2c-RTL5682:00: Using default DAI clk names: rt5682-dai-wclk, rt5682-dai-bclk

[marc-hb]

Thanks @miRoox , this was observed in test run 13515?model=ADLP_GMB_I2S_ZEPHYR&testcase=check-suspend-resume-without-audio-20

[marc-hb]

The problem is simple: the test finished a very short moment before the kernel error. This can be found when looking at journalctl. Please avoid dmesg in bug reports because it has too many problems: not persistent across reboots, disconnected from user space logs, ktime timestamps instead of wall clock...

Another issue I found when looking at this is that the ktime=254 sof-test coming from Python can unfortunately not be trusted :-( One more reason to avoid dmesg.

Jun 23 23:32:02 sh-adlp-gmb-i2s-02 kernel: snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x80]=0x40000 successful
Jun 23 23:32:02 sh-adlp-gmb-i2s-02 kernel: snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x80]=0x40000 successful
Jun 23 23:32:02 sh-adlp-gmb-i2s-02 kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-tgl 0000:00:1f.3: period_bytes:0x0
Jun 23 23:32:02 sh-adlp-gmb-i2s-02 kernel: snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-tgl 0000:00:1f.3: periods:1
Jun 23 23:32:02 sh-adlp-gmb-i2s-02 kernel: snd_sof:ipc3_dtrace_enable: sof-audio-pci-intel-tgl 0000:00:1f.3: stream_tag: 1
Jun 23 23:32:02 sh-adlp-gmb-i2s-02 kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x90030000: GLB_TRACE_MSG: DMA_PARAMS_EXT
  ...
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 ubuntu[16628]: ktime=254 sof-test PID=14623: ending
  ...
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 sudo[16642]:   ubuntu : TTY=unknown ; PWD=/home/ubuntu ; USER=root ; COMMAND=/usr/bin/sync
  ...
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x90030000 (msg/reply size: 80/12)
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: preventing DSP entering D3 state to preserve context
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (6)
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: status: fw entered - code 00000005
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: unexpected fault 0x00000000 trace 0x00004000
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: can't set params for DMA for trace -110
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to initialize firmware tracing -110
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 kernel: snd_sof:sof_machine_register: sof-audio-pci-intel-tgl 0000:00:1f.3: created machine adl_max98390_rt5682
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 kernel: snd_sof_pci:sof_pci_probe_complete: sof-audio-pci-intel-tgl 0000:00:1f.3: Completing SOF PCI probe
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 kernel: rt5682s i2c-RTL5682:00: Using default DAI clk names: rt5682-dai-wclk, rt5682-dai-bclk
Jun 23 23:32:03 sh-adlp-gmb-i2s-02 sudo[16651]:   ubuntu : TTY=unknown ; PWD=/home/ubuntu ; USER=root ; COMMAND=/usr/bin/sync

[marc-hb]

This happened because this is designed as a suspend-resume test, not a suspend-resume-and-make-sure-the-driver-reloads-OK test. In fact both reload tests DID fail in the same run and correctly report the reload failure so I'm not sure there's anything to do here. At least nothing to do urgently.

@plbossart what do you think, should we add a short delay at the end of the test?

[marc-hb]

At least nothing to do urgently.

The next test also caught some errors so this test was green but surrounded by a lot of red :-)

For completeness also keep in mind we have a small "atomicity" design issue with our kernel checkpoints:
#918 (comment)

[plbossart]

@plbossart what do you think, should we add a short delay at the end of the test?

isn't there a delay already after each of the resume and load steps - which presumably are reused from existing tests?
Not sure where you want to add this delay?

But no objections either, this is not urgent or time-critical

[marc-hb]

There's no delay after sof_insert.sh because it's not a test in itself.

I'm suggesting to add a small delay at the end of check-suspend-resume.sh --unload-drivers, right between the call to sof_insert.sh and the kernel logs check.

The problem of course is we never know how long firmware takes to load - up to 10 seconds. So even better, we could poll exactly like in commit 6b7a826 (test check-kmod-load-unload.sh). It's only a couple lines of code.

[marc-hb]

Unless someone has a recommendation I will close this as wontfix. This is a real issue but I don't think it's worth spending time addressing because enough other, more focused tests are failing.

[marc-hb]

Please re-open if you disagree.