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

Activity

1. marc-hb

   added

   bugSomething isn't working as expectedSomething isn't working as expected

   on Apr 26, 2024
2. marc-hb commented on Apr 26, 2024

   

   marc-hb

   on Apr 26, 2024

   Last edited by marc-hb

   CollaboratorAuthor

   More actions

   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.
3. kv2019i

   added

   P2Critical bugs or normal featuresCritical bugs or normal features

   on Apr 30, 2024
4. marc-hb commented on May 1, 2024

   

   marc-hb

   on May 1, 2024

   CollaboratorAuthor

   More actions

   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
   
5. lgirdwood

   added this to the v2.10 milestone on May 3, 2024
6. marc-hb commented on May 20, 2024

   

   marc-hb

   on May 20, 2024

   CollaboratorAuthor

   More actions

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

   modified the milestones: v2.10, v2.11 on May 28, 2024
8. marc-hb commented on Jun 17, 2024

   

   marc-hb

   on Jun 17, 2024

   Last edited by marc-hb

   CollaboratorAuthor

   More actions

   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
9. marc-hb commented on Aug 8, 2024

   

   marc-hb

   on Aug 8, 2024

   CollaboratorAuthor

   More actions

   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)
10. kv2019i

    modified the milestones: v2.11, v2.12 on Sep 5, 2024
11. kv2019i commented on Sep 5, 2024

    

    kv2019i

    on Sep 5, 2024

    Collaborator

    More actions

    No owner -> v2.12
12. kv2019i commented on Jan 3, 2025

    

    kv2019i

    on Jan 3, 2025

    Collaborator

    More actions

    No owner -> v2.13
13. kv2019i

    modified the milestones: v2.12, v2.13 on Jan 3, 2025
14. kv2019i commented on Apr 23, 2025

    

    kv2019i

    on Apr 23, 2025

    Collaborator

    More actions

    No owner, moving to v2.14
15. kv2019i

    modified the milestones: v2.13, v2.14 on Apr 23, 2025
16. github-actions commented on Jul 24, 2025

    

    github-actionsBot

    on Jul 24, 2025 – with GitHub Actions

    More actions

    This issue has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this issue will automatically be closed in 14 days. Note, that you can always re-open a closed issue at any time.
17. github-actions

    added

    staleIssue/PR marked as stale and will be closed after 14 days if there is no activity.Issue/PR marked as stale and will be closed after 14 days if there is no activity.

    on Jul 24, 2025
18. github-actions

    closed this as not plannedon Aug 8, 2025