[BUG] check-capture/check-playback cascading failures after pcm_read connection time out

[greg-intel]

Describe the bug
check-capture-100times ran, but hit a time out during one of the loops.
This caused a variety of preceding check-playback/check-capture/check-signal/multiple-pipeline tests to fail.

To Reproduce
TPLG=/lib/firmware/intel/avs-tplg/sof-adl-nocodec.tplg MODEL=ADLP_RVP_NOCODEC_IPC4ZPH SOF_TEST_INTERVAL=5 ~/sof-test/test-case/check-capture.sh -d 1 -l 100 -r 1
And get unlucky.

Reproduction Rate
Happens infrequently. One device it occurred on was sh-adlp-rvp-nocodec-05

Expected behavior
The expectation would be that check-capture wouldn't time out, and if it DID, it wouldn't cause a corruption in configuration that caused multiple other "unrelated" tests to fail.

Impact
Currently an annoyance.

Environment
Start Time: 2023-07-13 10:28:36 UTC
End Time: 2023-07-13 13:26:48 UTC
Kernel Branch: topic/sof-dev
Kernel Commit: 60236396e99c storage: 60236396e99c
SOF Branch: main
SOF Commit: 479c7942abb4 storage: 479c7942abb4
Zephyr Commit:
zephyr-v3.4.0-496-g431108d89e17
2) Name of the topology file
* Topology: TPLG=/lib/firmware/intel/avs-tplg/sof-adl-nocodec.tplg
3) Name of the platform(s) on which the bug is observed.
* Platform: ADLP_RVP_NOCODEC_IPC4ZPH

Screenshots or console output
check-capture-100times.sh:
(/result/planresultdetail/28997?model=ADLP_RVP_NOCODEC_IPC4ZPH&testcase=check-capture-100times)

arecord: pcm_read:2221: read error: Connection timed out
2023-07-13 11:07:25 UTC [REMOTE_ERROR] arecord on PCM hw:0,27 failed at 25/100.
2023-07-13 11:07:25 UTC [REMOTE_INFO] Starting func_exit_handler(1)
2023-07-13 11:07:25 UTC [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2023-07-13 11:07:25 UTC [REMOTE_ERROR]  die()  @  /home/ubuntu/sof-test/test-case/../case-lib/lib.sh
2023-07-13 11:07:25 UTC [REMOTE_ERROR]  main()  @  /home/ubuntu/sof-test/test-case/check-capture.sh:100
2023-07-13 11:07:25 UTC [REMOTE_INFO] pkill -TERM -f mtrace-reader.py
2023-07-13 11:07:25 UTC [REMOTE_INFO] nlines=42572 /home/ubuntu/sof-test/logs/check-capture/2023-07-13-10:59:56-6873/mtrace.txt
2023-07-13 11:07:25 UTC [REMOTE_INFO] ktime=2054 sof-test PID=6295: ending
2023-07-13 11:07:26 UTC [REMOTE_INFO] Test Result: FAIL!

check-capture-100times - dmesg:

[ 2050.227114] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to set final state 4 for all pipelines
[ 2050.227128] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
[ 2050.227145] kernel:  DMIC SFX1: ASoC: trigger FE cmd: 1 failed: -110
... snipped ...
[ 2050.731575] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to set final state 2 for all pipelines
... snipped ...
[ 2051.234649] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to unbind modules module-copier.14.2:0 -> gain.19.1:0
... snipped ...
[ 2051.738688] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to free pipeline widget pipeline.14
... snipped ...
[ 2053.250616] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to free pipeline widget pipeline.18
[ 2053.250632] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to free connected widgets
[ 2053.250656] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_free on 0000:00:1f.3: -110

check-playback-50rounds (next test):

aplay: set_params:1416: Unable to install hw params:
ACCESS:  RW_INTERLEAVED
FORMAT:  S16_LE
SUBFORMAT:  STD
SAMPLE_BITS: 16
FRAME_BITS: 32
CHANNELS: 2
RATE: 48000
PERIOD_TIME: (85333 85334)
PERIOD_SIZE: 4096
PERIOD_BYTES: 16384
PERIODS: 4
BUFFER_TIME: (341333 341334)
BUFFER_SIZE: 16384
BUFFER_BYTES: 65536
TICK_TIME: 0
2023-07-13 11:07:48 UTC [REMOTE_ERROR] aplay on PCM hw:0,0 failed at 1/1.
2023-07-13 11:07:48 UTC [REMOTE_INFO] Starting func_exit_handler(1)
2023-07-13 11:07:48 UTC [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
2023-07-13 11:07:48 UTC [REMOTE_ERROR]  die()  @  /home/ubuntu/sof-test/test-case/../case-lib/lib.sh
2023-07-13 11:07:48 UTC [REMOTE_ERROR]  main()  @  /home/ubuntu/sof-test/test-case/check-playback.sh:98
2023-07-13 11:07:48 UTC [REMOTE_INFO] pkill -TERM -f mtrace-reader.py
2023-07-13 11:07:48 UTC [REMOTE_INFO] nlines=1 /home/ubuntu/sof-test/logs/check-playback/2023-07-13-11:07:46-21586/mtrace.txt
2023-07-13 11:07:48 UTC [REMOTE_ERROR] Empty logfile
2023-07-13 11:07:48 UTC [REMOTE_INFO] ktime=2076 sof-test PID=8385: ending
2023-07-13 11:07:48 UTC [REMOTE_INFO] Test Result: FAIL!

check-playback-50rounds - dmesg:

[ 2076.193367] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[ 2076.193420] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: failed to create module pipeline.1
[ 2076.193431] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: Failed to set up connected widgets
[ 2076.193448] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed widget list set up for pcm 0 dir 0
[ 2076.193456] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_hw_params on 0000:00:1f.3: -110
[ 2076.193500] kernel:  Port0: ASoC: error at __soc_pcm_hw_params on Port0: -110
[ 2076.193516] kernel:  Port0: ASoC: error at dpcm_fe_dai_hw_params on Port0: -110

check-capture-100times.dmesg.txt
check-capture-100times.txt
check-playback=50rounds.txt
check-playback-50rounds.dmesg.txt

[fredoh9]

This happened again
Intel internal daily test link: planresultdetail/29388?model=TGLU_RVP_NOCODEC_IPC4ZPH&testcase=check-capture-100times

[mengdonglin]

@fredoh9 @keqiaozhang FYI. This feature hasn't been observed in last 2 weeks (ww31, ww32) while it happed almost everyday in ww30, not observed in ww29.

@alex-cri @lgirdwood I think we can monitor this issue but it should not a blocker for v2.7. I moved it to v2.8

[keqiaozhang]

No productions in CI for a month, closing this bug.