Skip to content

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

New issue
New issue
Closed
Closed
[BUG] weird logs in check-sof-logger.sh#709
Assignees
marc-hbaiChaoSONG
Labels
area:logsLog and results collection, storage, etc.type:bugSomething doesn't work as expected

Description

@plbossart
plbossart
opened on Jun 16, 2021

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

Activity

  1. plbossart
    added
    type:bugSomething doesn't work as expected
    on Jun 16, 2021

  2. lgirdwood commented on Jun 16, 2021

    @lgirdwood
    lgirdwood
    on Jun 16, 2021
    Member

    @marc-hb fyi - any comments ?

  3. lgirdwood
    assigned
    aiChaoSONG
    on Jun 16, 2021

  4. lgirdwood commented on Jun 16, 2021

    @lgirdwood
    lgirdwood
    on Jun 16, 2021
    Member

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

  5. plbossart
    changed the title [-][BUG][/-] [+][BUG] weird logs in check-sof-logger.sh[/+] on Jun 16, 2021
  6. aiChaoSONG
    assigned
    marc-hb
    on Jun 17, 2021

  7. marc-hb commented on Jun 17, 2021

    @marc-hb
    marc-hb
    on Jun 17, 2021
    Collaborator

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

  8. marc-hb commented on Jun 19, 2021

    @marc-hb
    marc-hb
    on Jun 19, 2021
    Collaborator

    Tweaked a bit in (unrelated) bug fix #711

  9. marc-hb commented on Jun 21, 2021

    @marc-hb
    marc-hb
    on Jun 21, 2021
    Collaborator

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

  10. plbossart commented on Jun 22, 2021

    @plbossart
    plbossart
    on Jun 22, 2021
    MemberAuthor

    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.

  11. marc-hb commented on Jun 22, 2021

    @marc-hb
    marc-hb
    on Jun 22, 2021
    Collaborator

    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

  12. marc-hb commented on Jul 3, 2021

    @marc-hb
    marc-hb
    on Jul 3, 2021
    Collaborator

    @plbossart ping?

  13. marc-hb
    added
    area:logsLog and results collection, storage, etc.
    on Jul 3, 2021

  14. plbossart commented on Jul 6, 2021

    @plbossart
    plbossart
    on Jul 6, 2021
    MemberAuthor

    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

  15. marc-hb commented on Jul 6, 2021

    @marc-hb
    marc-hb
    on Jul 6, 2021
    Collaborator

    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!

  16. plbossart commented on Jul 6, 2021

    @plbossart
    plbossart
    on Jul 6, 2021
    MemberAuthor

    ok, thanks @marc-hb let's close then

  17. plbossart
    closed this as completedon Jul 6, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

area:logsLog and results collection, storage, etc.type:bugSomething doesn't work as expected

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions