[BUG] Zephyr "mtrace" logs empty until the next reboot

[marc-hb]

Describe the bug

Zephyr "mtrace" logs have become suddenly and silently empty until the next reboot.

This happened in daily test 40387

To Reproduce

Could not reproduce.

Reproduction Rate

Seen only once for now. About 1/100 times

Expected behavior

Firmware logs are not totally empty.

Impact

No firmware logs

Environment

jf-mtlp-rvp-nocodec-5. Daily test 40387

Start Time: 2024-04-26 14:07:35 UTC
End Time: 2024-04-26 17:23:17 UTC

Linux Branch: topic/sof-dev
Linux Commit: f084b17039d5
KConfig Branch: master
KConfig Commit: a63502374811

SOF Commit: 278ecc5b74ad
Zephyr Commit: 24554363379d

Screenshots or console output

-rw-r--r-- 1 ubuntu ubuntu 100460 Apr 26 14:12 check-playback/2024-04-26-14:12:22-29836/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 133472 Apr 26 14:13 check-capture/2024-04-26-14:13:08-752/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 77080 Apr 26 14:20 check-playback/2024-04-26-14:14:03-32484/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 146320 Apr 26 14:32 check-capture/2024-04-26-14:20:53-27761/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 3222940 Apr 26 14:39 check-playback/2024-04-26-14:32:43-28751/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 6676072 Apr 26 14:52 check-capture/2024-04-26-14:39:54-25713/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 1616112 Apr 26 14:56 check-playback/2024-04-26-14:52:35-5326/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 2332176 Apr 26 15:00 check-capture/2024-04-26-14:56:24-21523/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 0 Apr 26 15:03 test-speaker/2024-04-26-15:03:00-2850/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 0 Apr 26 15:04 check-signal-stop-start/2024-04-26-15:04:24-12962/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 0 Apr 26 15:08 check-signal-stop-start/2024-04-26-15:08:12-31014/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 0 Apr 26 15:14 check-xrun-injection/2024-04-26-15:14:40-12735/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 0 Apr 26 15:15 check-xrun-injection/2024-04-26-15:15:24-17951/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 0 Apr 26 15:16 multiple-pipeline/2024-04-26-15:16:28-8050/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 0 Apr 26 15:22 multiple-pipeline/2024-04-26-15:22:42-26807/mtrace.txt

 ---- rebooted at 15:29 by CI ---

-rw-r--r-- 1 ubuntu ubuntu 1067236 Apr 26 15:36 simultaneous-playback-capture/2024-04-26-15:29:35-13597/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 3504596 Apr 26 15:42 multiple-pipeline/2024-04-26-15:36:12-14454/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 1944724 Apr 26 15:58 check-runtime-pm-status/2024-04-26-15:42:33-1210/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 9792 Apr 26 16:04 volume-basic-test/2024-04-26-16:04:27-19663/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 1146256 Apr 26 16:07 check-pause-resume/2024-04-26-16:04:53-26690/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 3046340 Apr 26 16:11 check-pause-resume/2024-04-26-16:07:22-1621/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 87337044 Apr 26 16:45 multiple-pause-resume/2024-04-26-16:11:25-15022/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 32128 Apr 26 16:45 check-alsabat/2024-04-26-16:45:27-13220/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 34624 Apr 26 16:46 check-alsabat/2024-04-26-16:46:11-31543/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 33032 Apr 26 16:47 check-alsabat/2024-04-26-16:46:55-8567/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 31700 Apr 26 16:47 check-alsabat/2024-04-26-16:47:39-29457/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 34460 Apr 26 16:48 check-alsabat/2024-04-26-16:48:23-15795/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 33128 Apr 26 16:49 check-alsabat/2024-04-26-16:49:07-4186/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 31796 Apr 26 16:50 check-alsabat/2024-04-26-16:49:51-15326/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 34552 Apr 26 16:50 check-alsabat/2024-04-26-16:50:35-3574/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 33224 Apr 26 16:51 check-alsabat/2024-04-26-16:51:19-24718/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 198832 Apr 26 17:08 check-suspend-resume-with-audio/2024-04-26-17:03:23-4793/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 401016 Apr 26 17:16 check-suspend-resume-with-audio/2024-04-26-17:08:53-16938/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 217600 Apr 26 18:35 test-speaker/2024-04-26-18:34:09-17183/mtrace.txt
-rw-r--r-- 1 ubuntu ubuntu 223 Apr 26 18:50 test-speaker/2024-04-26-18:50:17-29199/mtrace.txt

cc:

• Catch firmware errors reported in logs sof-test#1173
• [BUG] delayed mtrace collection linux#4618

[marc-hb]

Last passing test:

declare -- cmd="journalctl_cmd --since=@1714143379"
2024-04-26 15:02:47 UTC [REMOTE_INFO] Starting func_exit_handler(0)
2024-04-26 15:02:49 UTC [REMOTE_INFO] pkill -TERM -f mtrace-reader.py
2024-04-26 15:02:49 UTC [REMOTE_INFO] nlines=26841 /home/ubuntu/sof-test/logs/check-capture/2024-04-26-14:56:24-21523/mtrace.txt
+ grep -B 2 -A 1 -i --word-regexp -e ERR -e ERROR -e '' /home/ubuntu/sof-test/logs/check-capture/2024-04-26-14:56:24-21523/mtrace.txt
2024-04-26 15:02:52 UTC [REMOTE_INFO] ktime=3219 sof-test PID=13540: ending
2024-04-26 15:02:52 UTC [REMOTE_INFO] Test Result: PASS!

The 7 tests that ran after this all had an empty mtrace.txt.

They did not seem to fail for any other reason, everything else seems fine.

I haven't found any error or anything suspicious in any log; journalctl included. Anything specific one should be looking for? Some particular IPC?

No other device in the same run experienced anything similar and I haven't seen anything like this ever before.

There was apparently no "loose" mtrace-reader.py because mtrace.txt would not be empty in that case, it would have the error message described in:

• lib.sh: catch some mtrace-reader failures to start thanks to "OSError" sof-test#1183

This does not look like thesofproject/sof-test#1109 for the same reason: no error message?

After CI rebooted that device, mtrace seemed to work perfectly fine for the rest of the test run, see above.

Note the DSP "restores" from IMR on this system, it's not booting from scratch from D3.

[marc-hb]

Just happened again on jf-mtlp-rvp-sdw-6 in daily test 40524?model=MTLP_RVP_SDW&testcase=multiple-pipeline-capture-50

2024-05-01 14:51:26 UTC [REMOTE_INFO] Starting func_exit_handler(0)
2024-05-01 14:51:27 UTC [REMOTE_INFO] pkill -TERM -f mtrace-reader.py
2024-05-01 14:51:27 UTC [REMOTE_INFO] nlines=0 /home/ubuntu/sof-test/logs/multiple-pipeline/2024-05-01-14:45:23-4468/mtrace.txt
2024-05-01 14:51:27 UTC [REMOTE_ERROR] Empty logfile
+ grep -B 2 -A 1 -i --word-regexp -e ERR -e ERROR -e '' -e OSError /home/ubuntu/sof-test/logs/multiple-pipeline/2024-05-01-14:45:23-4468/mtrace.txt
2024-05-01 14:51:29 UTC [REMOTE_INFO] ktime=2776 sof-test PID=26273: ending
2024-05-01 14:51:29 UTC [REMOTE_INFO] Test Result: FAIL!

No other obvious error in the logs.

Final mtrace logs (from the previous test) copied below. Note the multiple "messages dropped" warnings.

Again this is a system with "IMR restore"

mtrace worked again after a complete Linux reboot.

[ 2043.205998] <inf> dma: dma_put: dma_put(), dma = 0x401028d0, sref = 0
[ 2044.570106] <inf> ipc: ipc_cmd: rx	: 0x11000006|0x0
[ 2044.570228] <inf> pipe: pipeline_new: pipeline new pipe_id 0 priority 0
[ 2044.571693] <inf> ipc: ipc_cmd: rx	: 0x40000004|0x306
[ 2044.572201] <inf> dai_intel_dmic: dai_dmic_probe: dmic_probe()
[ 2044.572361] <inf> dma: dma_get: dma_get() ID 0 sref = 1 busy channels 0
--- 1 messages dropped ---
[ 2044.572623] <inf> dai_intel_dmic: dai_dmic_set_config: dmic_set_config()
[ 2044.572685] <inf> dai_intel_dmic_nhlt: print_outcontrol: OUTCONTROL = 00390843
[ 2044.572731] <inf> dai_intel_dmic_nhlt: print_outcontrol: tie=0, sip=0, finit=0, fci=0
[ 2044.572778] <inf> dai_intel_dmic_nhlt: print_outcontrol: bfth=3, of=2, ipm=2, th=3
[ 2044.572826] <inf> dai_intel_dmic_nhlt: print_outcontrol: ipms1=0, ipms2=1, ipms3=0, ipms4=0
[ 2044.572873] <inf> dai_intel_dmic_nhlt: print_outcontrol: ipms_mode=1
[ 2044.572923] <inf> dai_intel_dmic_nhlt: dai_dmic_set_config_nhlt: OUTCONTROL0 = 02390843
[ 2044.572971] <inf> dai_intel_dmic_nhlt: print_outcontrol: OUTCONTROL = 00390843
[ 2044.573018] <inf> dai_intel_dmic_nhlt: print_outcontrol: tie=0, sip=0, finit=0, fci=0
--- 1 messages dropped ---
[ 2044.573110] <inf> dai_intel_dmic_nhlt: print_outcontrol: ipms1=0, ipms2=1, ipms3=0, ipms4=0
[ 2044.573156] <inf> dai_intel_dmic_nhlt: print_outcontrol: ipms_mode=1
[ 2044.573216] <inf> dai_intel_dmic_nhlt: dai_dmic_configure_coeff: fir_length_a = 101, fir_length_b = 247, packed = 0
--- 1 messages dropped ---
[ 2044.573443] <inf> dai_intel_dmic_nhlt: dai_nhlt_get_clock_div: pdm = 0, FIR_CONFIG = 0x00010064
[ 2044.573490] <inf> dai_intel_dmic_nhlt: dai_nhlt_get_clock_div: dai_index = 0, rate_div = 800, p_clkdiv = 16, p_mcic = 25, p_mfir = 2
--- 1 messages dropped ---
[ 2044.574648] <inf> ipc: ipc_cmd: rx	: 0x40000010|0xa
--- 2 messages dropped ---
[ 2044.574865] <inf> eq_iir: eq_iir_init: comp:0 0x10 eq_iir_init()
[ 2044.577023] <inf> ipc: ipc_cmd: rx	: 0x44000010|0x30000058
[ 2044.577143] <inf> eq_iir: eq_iir_set_config: comp:0 0x10 eq_iir_set_config()
[ 2044.578230] <inf> ipc: ipc_cmd: rx	: 0x40010004|0x15
[ 2044.579475] <inf> ipc: ipc_cmd: rx	: 0x11010004|0x0
[ 2044.579538] <inf> pipe: pipeline_new: pipeline new pipe_id 1 priority 0
[ 2044.581015] <inf> ipc: ipc_cmd: rx	: 0x40000006|0x10010
[ 2044.582298] <inf> ipc: ipc_cmd: rx	: 0x44000006|0x3c800034
[ 2044.583481] <inf> ipc: ipc_cmd: rx	: 0x44000006|0x30000018
[ 2044.585060] <inf> ipc: ipc_cmd: rx	: 0x40020004|0x10015
[ 2044.585426] <inf> dma: dma_get: dma_get() ID 0 sref = 1 busy channels 0

[marc-hb]

Observed again in daily test run 41268?model=MTLP_RVP_NOCODEC&testcase=test-speaker

[marc-hb]

and again in daily 42634?model=MTLP_RVP_SDW&testcase=check-alsabat-headset-playback-599

+ https://sof-ci.01.org/softestpr/PR931/build519/devicetest/index.html?model=MTLP_RVP_HDA&testcase=multiple-pause-resume-50

[marc-hb]

In this LNL example we lost BOTH mtrace and kernel logs:
https://sof-ci.01.org/linuxpr/PR5110/build4324/devicetest/index.html?model=LNLM_RVP_HDA&testcase=check-sof-logger
cc:

• [NOT FOR UPSTREAM] drm/xe/lnl: Drop force_probe requirement linux#5110 (comment)

[kv2019i]

No owner -> v2.12

[kv2019i]

No owner -> v2.13