[RFC] use journalctl for kernel log #468

xiulipan · 2020-10-23T11:48:31Z

Try to use journalctl to read kernel log from system.
Use UNIX style timestamp to split kernel logs from test case to test case.
Print same format like dmesg in journalctl kernel log.
Update all test case used to relay on demsg logs

marc-hb · 2020-10-24T04:25:07Z

Previous attempts (and previous mistakes) in #263 and #354

"Those who ignore history are doomed to repeat it"

PS: I did NOT look at this newer attempt yet

xiulipan · 2020-10-26T02:32:16Z

@marc-hb Yep, I reviewed both #263 and #354 and some patch is cherry-pick from previous work.
Still trying to find a clear way to get the log collection feature work with journalctl.

test-case/verify-sof-firmware-load.sh

tools/sof-get-default-tplg.sh

tools/sof-kernel-log-check.sh

Directly use journalctl in the testcase to avoid kernel log missing issues. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

use journalctl by default for any kernel log reader usage. Also add header for the file. Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com> Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

Add path for the sof-dump-status.py to avoid error: sof-dump-status.py: command not found Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

use journalctl to get kernl logs. use timestamp to split logs for each test case. replace all test case to use the timestamp Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com> Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

Add common error logs from systemd, initramfs, atkbd, i801_smbus, ata3, genirq, DMAR, dw_dmac, proc_thermal, SDWm, touch pad Those error level logs did not break functionality of the DUTs. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

…iteration remove the redundant kernel log check for all case. enable kernel log check for each iteration. also do some clean up for this script Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

…teration remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

…tion remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

…eration remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

try to flush and sync journalctl to avoid empty logs. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

ranj063 · 2020-10-29T00:19:54Z

test-case/check-pause-resume.sh

-    # sof-kernel-log-check script parameter number is 0/Non-Number will force check from dmesg
-    sof-kernel-log-check.sh 0 || die "Catch error in dmesg"
+    # check kernel log for each iteration to catch issues
+    sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP || die "Catch error in kernel log"


Caught error instead of Catch error

ranj063 · 2020-10-29T00:20:15Z

test-case/check-ipc-flood.sh


-    sof-kernel-log-check.sh 0 || die "Catched error in dmesg"
+    # check kernel log for each iteration to catch issues
+    sof-kernel-log-check.sh $KERNEL_LAST_TIMESTAMP || die "Catch error in kernel log"


same comment here. lets fix it everywhere

marc-hb

This is fixing an extremely critical feature so this must be broken down in smaller pull requests and merged progressively = "continuous" integration. This is especially important considering the regular stream of other, unrelated CI changes and issues will not stop and will still need to be investigated and addressed at the same time. I mean we cannot stop everyone else (including you!) from making other CI fixes and improvements while performing this critical change. We also need the ability to quickly revert the last PR if anything goes wrong - and from past experience a number of things will go wrong.

As long as you use the -k flags you do not need to modify the ignore_str at the same time. The last thing we want is to change the implementation and the ignore_str at the same time. So let's forget about any ignore_str changes for now.
The --priority flag must also be postponed.
The first PR to submit is the PR that renames func_lib_setup_kernel_last_line to func_lib_setup_kernel_last_timestamp and KERNEL_LAST_LINE to KERNEL_LAST_TIMESTAMP without making any real code change. That will first get a lot of changed lines out of the way with no risk. The name will not match the old implementation for the transition period but we don't care.
The second PR to submit is quoting all the instances of $KERNEL_LAST_TIMESTAMP and then wait a day or two to make sure everything still works.
Then we can start flipping the switch with high impact but small number of lines PR.

Most importantly: what sort of (fake) errors did you test this with? Testing a change like this requires at least two throw-away PRs:

one throw-away PR with strategically placed fake errors + old code
a second throw-away PR with the exact same fake errors + the new code

The test results for both must be exactly the same.

marc-hb · 2020-10-29T00:29:34Z

test-case/check-ipc-flood.sh

 for i in $(seq 1 $loop_cnt)
 do
+    # cleanup dmesg buffer for each iteration
+    sudo dmesg -c > /dev/null


Is this still required?

xiulipan · 2020-10-29T02:02:10Z

@marc-hb Thanks for the tips, I am also think about how to spilt the patches. Please help to check my plan:

replace LINE with TIMESTAMP, log check with no --priority but still with err_str
quoting clean up for the $KERNEL_LAST_TIMESTAMP
remove err_str and use --priority, add new ignore_str
clean up test case to remove duplicate kernel log check.

some discussion I want to have here:

What priority level we want to track here? @plbossart @ranj063 In this RFC, I have tried --priority=err Is this enough? Will warning be overkill?
verify-sof-firmware-load.sh seems still have issue even with sudo journalctl --sync --flush, I could not tell what happened to it
and we still got a fail https://sof-ci.01.org/softestpr/PR468/build344/devicetest/ on BSW. I will try to fallback to dmesg for this test.

Keep this PR for testing and I will start with task 1.

xiulipan · 2020-11-02T08:45:13Z

close with latest part 1 PR #480

marc-hb · 2020-11-05T00:15:48Z

Please help to check my plan:

Much finer-grained, much better!

For such a "core" change like this we really need "Totally Continuous" Integration: small, well tested changes, quick reviews, and then at least a couple days careful observation between merged PRs. See my request in #480.
One day observation is enough after non-functional changes like renames, more days needed to observe more impactful changes.

What priority level we want to track here? @plbossart @ranj063 In this RFC, I have tried --priority=err Is this enough? Will warning be overkill?

We can talk about changing levels and filtering last, after everything else is in place. Then we should involve many more people. For now the priority is to switch to journalctl while preserving everything else exactly the same - and then find and fix everything that broke with just that before even tweaking the filtering.

marc-hb · 2020-11-05T00:23:29Z

verify-sof-firmware-load.sh seems still have issue

Still now after fixing all clock and timezone issues?

even with sudo journalctl --sync --flush, I could not tell what happened to it

These options make absolutely no difference except if you use them a split second before of system crash or sudden power loss. We are not really dealing with crashes anyway so don't use them, they're just confusing.

and we still got a fail https://sof-ci.01.org/softestpr/PR468/build344/devicetest/ on BSW.

BSW has been experiencing a lot of storage issues (see internal issue 539 + links), could that be the cause?

I will try to fallback to dmesg for this test.

Please no, that sounds brittle and complex. Let's understand what the real issue is first and/or temporarily disable BSW in the mean time.

xiulipan requested a review from a team as a code owner October 23, 2020 11:48

xiulipan mentioned this pull request Oct 26, 2020

lib: hijack: use journalctl command to dump kernel information #263

Closed

xiulipan force-pushed the pr/journalctl branch 2 times, most recently from b690742 to 6787f71 Compare October 26, 2020 12:14

ranj063 reviewed Oct 26, 2020

View reviewed changes

test-case/verify-sof-firmware-load.sh Outdated Show resolved Hide resolved

ranj063 reviewed Oct 26, 2020

View reviewed changes

test-case/verify-sof-firmware-load.sh Outdated Show resolved Hide resolved

ranj063 reviewed Oct 26, 2020

View reviewed changes

tools/sof-get-default-tplg.sh Outdated Show resolved Hide resolved

ranj063 reviewed Oct 26, 2020

View reviewed changes

tools/sof-kernel-log-check.sh Outdated Show resolved Hide resolved

xiulipan force-pushed the pr/journalctl branch from 6787f71 to 3763fbc Compare October 28, 2020 04:09

xiulipan added 4 commits October 28, 2020 05:30

test: verify-sof-firmware-load: use journalctl to get kernel logs

9828d66

Directly use journalctl in the testcase to avoid kernel log missing issues. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

tools: sof-kernel-log-check: fix script direct run

0d8bd70

Add path for the sof-dump-status.py to avoid error: sof-dump-status.py: command not found Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

xiulipan force-pushed the pr/journalctl branch 2 times, most recently from 6f7c349 to 8d567e1 Compare October 28, 2020 07:22

xiulipan added 11 commits October 28, 2020 08:29

test-case: check-pause-resume: check kernel log in each iteration

d4de517

remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

test-case: check-runtime-pm-status: check kernel log in each iteration

e12e5ee

remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

test-case: check-ipc-flood: check kernel log in each iteration

0a02227

remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

test-case: check-suspend-resume: check kernel log in each iteration

2fffcb7

remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

test-case: check-suspend-resume-with-audio: check kernel log in each …

d3b2714

…iteration remove the redundant kernel log check for all case. enable kernel log check for each iteration. also do some clean up for this script Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

test-case: check-runtime-pm-double-active: check kernel log in each i…

62a95c6

…teration remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

test-case: multiple-pause-resume: check kernel log in each iteration

8db6f8c

remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

test-case: multiple-pipeline-playback: check kernel log in each itera…

40b6cb8

…tion remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

test-case: multiple-pipeline-capture: check kernel log in each iteration

62c98eb

remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

test-case: simultaneous-playback-capture: check kernel log in each it…

91e4116

…eration remove the redundant kernel log check for all case. enable kernel log check for each iteration. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

xiulipan force-pushed the pr/journalctl branch from 8d567e1 to 91e4116 Compare October 28, 2020 08:30

test: verify-sof-firmware-load: flush and sync journalctl logs

43c3ca6

try to flush and sync journalctl to avoid empty logs. Signed-off-by: Pan Xiuli <xiuli.pan@linux.intel.com>

xiulipan changed the title ~~[RFC] use journalctl for kernel log~~ [WIP] use journalctl for kernel log Oct 28, 2020

ranj063 reviewed Oct 29, 2020

View reviewed changes

marc-hb requested changes Oct 29, 2020

View reviewed changes

xiulipan changed the title ~~[WIP] use journalctl for kernel log~~ [RFC] use journalctl for kernel log Oct 29, 2020

xiulipan closed this Nov 2, 2020

xiulipan mentioned this pull request Nov 18, 2020

use journalctl as default kernel log reader #509

Closed

[RFC] use journalctl for kernel log #468

[RFC] use journalctl for kernel log #468

Uh oh!

Conversation

xiulipan commented Oct 23, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

marc-hb commented Oct 24, 2020

Uh oh!

xiulipan commented Oct 26, 2020

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

ranj063 Oct 29, 2020

Choose a reason for hiding this comment

Uh oh!

ranj063 Oct 29, 2020

Choose a reason for hiding this comment

Uh oh!

marc-hb left a comment

Choose a reason for hiding this comment

Uh oh!

marc-hb Oct 29, 2020

Choose a reason for hiding this comment

Uh oh!

xiulipan commented Oct 29, 2020

Uh oh!

xiulipan commented Nov 2, 2020

Uh oh!

marc-hb commented Nov 5, 2020

Uh oh!

marc-hb commented Nov 5, 2020

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

xiulipan commented Oct 23, 2020 •

edited

Loading