[BUG] SKIP the DMA trace corruption might hide the failure

[miRoox]

Describe the bug
If there is an error that happened before, the error might be hidden by the ignorant of the Zephyr DMA trace corruption #895.

To Reproduce

TPLG=/lib/firmware/intel/sof-tplg/sof-adl-max98390-rt5682.tplg MODEL=ADLP_GMB_I2S_ZEPHYR ~/sof-test/test-case/multiple-pause-resume.sh -r 50

Expected behavior
Report FAIL once the case failed even if the sof-logger was already dead.

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@68b76766e8ba
   • SOF: thesofproject/sof@b36db45a7da7
   • SOF-TEST: 287a6b9
2. Test report ID (if you find it from test report)
   • ID: 12389
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: TPLG=/lib/firmware/intel/sof-tplg/sof-adl-max98390-rt5682.tplg MODEL=ADLP_GMB_I2S_ZEPHYR ~/sof-test/test-case/multiple-pause-resume.sh -r 50

Screenshots or console output

[ 3689.304564] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx timed out for 0x60070000 (msg/reply size: 12/12)
[ 3689.304621] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[ 3689.304651] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: hda irq intsts 0x00000000 intlctl 0xc0000081 rirb 00
[ 3689.304669] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 3689.304694] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 3689.304707] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------
[ 3689.304719] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[ 3689.304730] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: IPC timeout
[ 3689.304742] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state: SOF_FW_BOOT_COMPLETE (6)
[ 3689.304767] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: status: fw entered - code 00000005
[ 3689.304908] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: unexpected fault 0x00000000 trace 0x00004000
[ 3689.304923] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 3689.304944] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
[ 3689.304969] kernel:  HDMI4: ASoC: trigger FE cmd: 4 failed: -110
<<===========================
2022-05-08 23:37:08 UTC [REMOTE_ERROR] pause resume PID 21532 had non-zero exit status
2022-05-08 23:37:08 UTC [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2022-05-08 23:37:08 UTC [REMOTE_ERROR]  die()  @  /home/ubuntu/sof-test/test-case/../case-lib/lib.sh
2022-05-08 23:37:08 UTC [REMOTE_ERROR]  main()  @  /home/ubuntu/sof-test/test-case/multiple-pause-resume.sh:191
2022-05-08 23:37:08 UTC [REMOTE_INFO] Starting /usr/local/bin/sof-logger -l /etc/sof/sof-adl.ldc -o /home/ubuntu/sof-test/logs/multiple-pause-resume/2022-05-08-23:32:44-15563/etrace.txt
2022-05-08 23:37:11 UTC [REMOTE_INFO] pkill -TERM sof-logger
2022-05-08 23:37:11 UTC [REMOTE_ERROR] sof-logger was already dead
2022-05-08 23:37:12 UTC [REMOTE_ERROR] Downgrading test failure to SKIP because of known
2022-05-08 23:37:12 UTC [REMOTE_ERROR] issue https://github.com/thesofproject/sof/issues/5352
https://github.com/thesofproject/sof/issues/5352
2022-05-08 23:37:13 UTC [REMOTE_INFO] nlines=3 /home/ubuntu/sof-test/logs/multiple-pause-resume/2022-05-08-23:32:44-15563/etrace.txt
2022-05-08 23:37:13 UTC [REMOTE_INFO] Test Result: SKIP!

[marc-hb]

Maybe re-ordering the checks can fix this. Not sure.

[marc-hb]

Thanks @miRoox for the bug report. Here's the simplest way to reproduce this issue:

diff --git a/case-lib/hijack.sh b/case-lib/hijack.sh
index e1d120903111..71886ce296a9 100644
--- a/case-lib/hijack.sh
+++ b/case-lib/hijack.sh
@@ -58,6 +58,7 @@ function func_exit_handler()
         # We need this to avoid the confusion of a "Terminated" message
         # without context.
         dlogi "pkill -TERM $loggerBin"
+        sudo pkill -TERM "$loggerBin"
         sudo pkill -TERM "$loggerBin" || {
             dloge "sof-logger was already dead"
             if is_zephyr; then
diff --git a/test-case/check-playback.sh b/test-case/check-playback.sh
index 94eb84ddbf31..a40c95f9ee06 100755
--- a/test-case/check-playback.sh
+++ b/test-case/check-playback.sh
@@ -99,6 +99,7 @@ do
                     die "aplay on PCM $dev failed at $i/$loop_cnt."
                 }
             done
+            fake_kern_error "DRIVER ID: FAKE error $0 PID $$ $round"
         done
     done
 done

[keqiaozhang]

I just happened to observe this issue on TGLU_UP_HDA_ZEPHYR.
https://sof-ci.sh.intel.com/#/result/planresultdetail/13293?model=TGLU_UP_HDA_ZEPHYR&testcase=check-capture-all-formats
https://sof-ci.sh.intel.com/#/result/planresultdetail/13293?model=TGLU_UP_HDA_ZEPHYR&testcase=check-capture-100sec

These tests were run, but ended as SKIP.
If I disable the sof-logger by "export SOF_LOGGING=none", the tests will be passed.

[marc-hb]

I don't understand why this was re-opened sorry. DMA corruption happened in these runs, so the correct status is FAIL. We agreed to downgrade this FAIL to SKIP because it is a (surprisingly) known and WONTFIX issue but downgrading to PASS does not make sense to me.

If I disable the sof-logger by "export SOF_LOGGING=none", the tests will be passed.

This is hiding and ignoring DMA corruption. Decreasing test coverage increases PASS rate but it also decreases quality. If it's not tested then it does not work, see recent example with sof probes.

Also, the SKIP currently happens only when there is DMA corruption whereas SOF_LOGGING=none would lose all logs across all Zephyr testing. How do you find and fix bugs without logs?

[miRoox]

These tests were run, but ended as SKIP.
If I disable the sof-logger by "export SOF_LOGGING=none", the tests will be passed.

So there is no real error hidden by downgrading the DMA corruption, I don't think it's about this issue.