[BUG] weird logs in check-sof-logger.sh

[plbossart]

Describe the bug

Tests on APL_NOCODEC show this:

+ /root/sof-test/test-case/check-sof-logger.sh


2021-06-16 19:30:47 UTC Sub-Test: [INFO] ::END data


2021-06-16 19:30:47 UTC Sub-Test: [INFO] Log etrace BEG::
 TIMESTAMP      (us)           DELTA  C# COMPONENT          LOCATION                      CONTENT	ktime=49.685s  @  2021-06-16 14:30:47 -0500 CDT
[    22776253.105] (           0.000) c0 dma-trace             src/trace/dma-trace.c:343  ERROR FW ABI 0x3012001 DBG ABI 0x5003000 tag v1.8-rc1-209-g444f9a2a5969 src hash 0xb7b0cb60 (ldc hash 0xb7b0cb60)

		 --- negative DELTA = -17538225.761 us: wrap, IPC_TRACE, other? ---

[     5238027.344] (           0.000) c0 wait                         src/lib/wait.c:46   ERROR poll timeout reg 32840 mask 63 val 0 us 937
Skipped 8108 bytes after the last statement.
2021-06-16 19:30:47 UTC Sub-Test: [INFO] ::END etrace


2021-06-16 19:30:47 UTC Sub-Test: [INFO] Log error BEG::
2021-06-16 19:30:47 UTC Sub-Test: [INFO] ::END error


2021-06-16 19:30:47 UTC Sub-Test: [INFO] Log etrace_stderr BEG::
2021-06-16 19:30:47 UTC Sub-Test: [INFO] ::END etrace_stderr
2021-06-16 19:30:47 UTC Sub-Test: [INFO] Test Result: PASS!

it's rather unclear what all these BEG:: and ::END things are, and why a negative timing is a PASS.

To Reproduce

root@plb-UP-APL01:~# TPLG=/lib/firmware/intel/sof-tgpl/sof-apl-nocodec.tplg ~/sof-test/test-case/run-all-tests.sh -l1

Expected behavior

human-readable logs and clear pass/fail indications

Detail Info

1. Branch name and commit hash of the 3 repositories: sof (firmware/topology), linux (kernel driver) and sof-test (test case)
   • Kernel: 56ab165beb0d744624fd2ee47c75b40ae13d24cd
   • SOF: 444f9a2a596992115a67e0f727a49388db38c237
   • SOF-TEST: d73423f

[lgirdwood]

@marc-hb fyi - any comments ?

[lgirdwood]

@aiChaoSONG please re-assign if this belongs to someone else.

[marc-hb]

There are a couple valid reasons for a negative DELTA, at least: buffer wrap and IPC TRACE configuration from the kernel. The logger does not have enough information to tell whether the negative DELTA is a problem or not.

The BEG:: and END:: are just "greppable" start and end markers, feel free to suggest better names. They used to be <<< and >>> which broke the HTML page...

[marc-hb]

Tweaked a bit in (unrelated) bug fix #711

[marc-hb]

@plbossart is everything clearer? If not then what is not yet and and if yes any suggestion?

[plbossart]

I have zero understanding of what those BEG:: and END:: labels are supposed to be used for. This is already an extracted view of the dmesg/trace/etrace files.

[marc-hb]

The 4 log files (stdout, stderr) x (trace x etrace) are inlined in the main output tab, in addition to being provided on separate tabs. BEG means "start of inlined log file" and END means "end of inlined log file" They're just start and end markers. They have been there since forever but I recently changed them from >>>> and <<<< to BEG:: and END:: because the former corrupted the HTML output.

It may be a bit clearer now because they should never be empty any more, more recent example:
https://sof-ci.01.org/sofpr/PR4379/build9434/devicetest/?model=TGLH_RVP_HDA&testcase=check-sof-logger

[marc-hb]

@plbossart ping?

[plbossart]

I can understand markers, but if there is no information then what's the point?

The following does not tell me anything useful.

2021-06-16 19:30:47 UTC Sub-Test: [INFO] Log error BEG::
2021-06-16 19:30:47 UTC Sub-Test: [INFO] ::END error


2021-06-16 19:30:47 UTC Sub-Test: [INFO] Log etrace_stderr BEG::
2021-06-16 19:30:47 UTC Sub-Test: [INFO] ::END etrace_stderr

[marc-hb]

I made some changes, the space between the markers is not empty any more. More recent example:
https://sof-ci.01.org/linuxpr/PR3010/build5933/devicetest/

2021-06-24 21:53:42 UTC [REMOTE_INFO] Log file logger.etrace.txt BEG::
 TIMESTAMP      (us)           DELTA  C# COMPONENT          LOCATION                      CONTENT	ktime=102.926s  @  2021-06-24 21:53:42 +0000 UTC
[     9728041.280] (           0.000) c0 dma-trace             src/trace/dma-trace.c:343  ERROR FW ABI 0x3013000 DBG ABI 0x5003000 tag v1.8-rc1-236-g86c9a037e212 src hash 0x6560584a (ldc hash 0x6560584a)
Skipped 8144 bytes after the last statement.
2021-06-24 21:53:42 UTC [REMOTE_INFO] ::END log file logger.etrace.txt


2021-06-24 21:53:42 UTC [REMOTE_INFO] Log file logger.error.txt BEG::
GOOD: logger.error.txt was empty, no stderr output from that sof-logger instance
2021-06-24 21:53:42 UTC [REMOTE_INFO] ::END log file logger.error.txt


2021-06-24 21:53:42 UTC [REMOTE_INFO] Log file logger.etrace_stderr.txt BEG::
GOOD: logger.etrace_stderr.txt was empty, no stderr output from that sof-logger instance
2021-06-24 21:53:42 UTC [REMOTE_INFO] ::END log file logger.etrace_stderr.txt
2021-06-24 21:53:42 UTC [REMOTE_INFO] Test Result: PASS!