Skip to content

Kernel error scanning with journalctl (no dmesg) #292

Open
Open
Kernel error scanning with journalctl (no dmesg)#292
Labels
P2Critical bugs or normal featuresarea:logsLog and results collection, storage, etc.good first issueGood for newcomerstype:enhancementNew framework feature or request

Description

@fredoh9
fredoh9
opened on Jul 20, 2020

Marc suggested to switch to journalctl while reviewing #290

Current we grep for negative keywords, if it hit any then return error. These are current keywords for error.

err_str="error|failed|timed out|panic|oops"

dmesg | grep -E "$err_str" | grep -vE "$ignore_str"

Later we should drop such "screen scraping" and use something more robust like journalctl --dmesg --priority err with no false positive (for instance a debug message with one of these keywords) and no false negative (e.g. ERR:)

Links:

Activity

  1. fredoh9 commented on Jul 20, 2020

    @fredoh9
    fredoh9
    on Jul 20, 2020
    ContributorAuthor

    PR is already available.
    #262

  2. fredoh9
    self-assigned this
    on Jul 20, 2020

  3. xiulipan commented on Jan 26, 2021

    @xiulipan
    xiulipan
    on Jan 26, 2021
    Contributor

    I think this is already done by #529 @fredoh9 Please confirm and close.

  4. xiulipan
    added
    state:ping-for-closeWill be closed if submitter is not responsive
    on Jan 26, 2021

  5. fredoh9 commented on Feb 25, 2021

    @fredoh9
    fredoh9
    on Feb 25, 2021
    ContributorAuthor

    yes, thank you!

  6. fredoh9
    closed this as completedon Feb 25, 2021
  7. marc-hb
    added
    area:non-audio FailureFalse positives: failing when we don't want to
    on Oct 15, 2021

  8. marc-hb commented on Jun 30, 2022

    @marc-hb
    marc-hb
    on Jun 30, 2022
    Collaborator

    I'm re-opening this because we're still using dmesg to capture kernel logs in test reports, example: thesofproject/linux#3731 (comment)

    dmesg has number of issues:

    • it's a ring buffer so it may be incomplete
    • It's not available after a reboot
    • ktime timestamps are relatively useless because difficult to relate to user space
    • It's missing the hostname
    • no way to combine with user space logs if/when desired
  9. marc-hb
    added
    type:enhancementNew framework feature or request
    good first issueGood for newcomers
    P2Critical bugs or normal features
    area:journalctl
    and removed
    area:non-audio FailureFalse positives: failing when we don't want to
    state:ping-for-closeWill be closed if submitter is not responsive
    on Jun 30, 2022
  10. marc-hb
    reopened this on Jul 6, 2022

  11. ujfalusi commented on Jul 6, 2022

    @ujfalusi
    ujfalusi
    on Jul 6, 2022
    Contributor

    @marc-hb, what is wrong with dmesg --level=err to filter the prints?
    We still need to filter SOF erros (likely) and for the reports we need to context around the errors (plus the full dmesg)

  12. marc-hb commented on Jul 6, 2022

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

    what is wrong with dmesg --level=err to filter the prints?

    Everything I listed above? :-)

    We still need to filter SOF erros (likely)

    Please prove me wrong but so far I haven't found any dmesg feature that journalctl does not have (and of course either can be piped to grep the same)

    https://www.bing.com/images/search?q=journalctl+cheat+sheet

  13. ujfalusi commented on Jul 6, 2022

    @ujfalusi
    ujfalusi
    on Jul 6, 2022
    Contributor

    @marc-hb, sure, journalctl is an OS while dmesg is a command line tool from util-linux.

    it's a ring buffer so it may be incomplete

    and journalctl takes the kernel log from the same ring buffer...

    It's not available after a reboot

    journalctl saves the logs to somewhere, so any syslog tools (/var/log/kernel.log.* in my machines)

    ktime timestamps are relatively useless because difficult to relate to user space

    dmesg --time-format ctime
    I think the issue is that the timestamps are hard to relate to the firmware stamps.

    It's missing the hostname

    Hrm true, but I usually know where I have run it.

    no way to combine with user space logs if/when desired

    dmesg -u

    If you think journalctl will give us better CI reports, I'm all for it, don't get me wrong.
    But running the tests on my own machines are getting harder and harder.
    I'll remain:

    $ journalctl
zsh: command not found: journalctl

  14. marc-hb commented on Jul 7, 2022

    @marc-hb
    marc-hb
    on Jul 7, 2022
    Collaborator

    and journalctl takes the kernel log from the same ring buffer...

    I don't understand sorry. I just ran both dmesg and journal -k one test device that has been running some sof-test with verbose sof logs:

    root@up2:~# dmesg | wc -l
2908
root@up2:~# journalctl -k | wc -l
14600

    I bet you'll observe the same thing with /var/log/whatever

    dmesg --time-format ctime

    I just tried this and I found a 72 seconds gap with journalctl -k, any idea why? Suspend/resume?

    After a LOT of time spent troubleshooting NTP issues, I have 100% confidence in journalctl timestamps, of course as long as NTP is working #908)

    Hrm true, but I usually know where I have run it.

    "works4me" ? :-)

    dmesg -u

    This is new to me. I tried it and the output was very surprising: it seems to have only systemd logs, no other user space logs and almost no kernel logs.

    If you think journalctl will give us better CI reports, I'm all for it, don't get me wrong.

    Yes for the reasons listed above.

    sof-test has already a very strong dependency on journalctl (see old comments above) so there's no reason to stop short and keep using dmesg in just one sof-test place bar all the others.

    zsh: command not found: journalctl

    I'm sorry but we have barely bandwidth to validate only one distribution right now (without even pulseaudio / pipewire...), a growing backlog and like it or not journalctl is definitely the standard. As long as your logging solution has an equivalent to journalctl's --since option then it should be possible to implement some abstraction layer, please send patches! This will also help with:

    I think the issue is that the timestamps are hard to relate to the firmware stamps.

    That's a very good point. The fw timestamp is typically initialized from ktime but I suspect it can then diverge depending on D3 , innacurate frequency guess in sof-logger and what not? If you find a way to have BOTH ktime and wall clock in captured logs then I'm all for it but as long as we can't easily relate to FW timestamps then it's better to match at least user space logs.

    BTW what is the simplest way to read ktime from a shell? I tried a Python one-liner in 46dadd0 but I'm afraid it's not reliable :-(

  15. marc-hb
    changed the title [-]Kernel error scanning with journalctl[/-] [+]Kernel error scanning with journalctl (no dmesg)[/+] on Jul 8, 2022

  16. marc-hb commented on Nov 9, 2022

    @marc-hb
    marc-hb
    on Nov 9, 2022
    Collaborator

    BTW I recently found that Ubuntu 22 still uses rsyslogd in addition to journald. Weird.

  17. marc-hb
    unassigned
    fredoh9
    on Jun 23, 2023
  18. marc-hb
    added
    area:logsLog and results collection, storage, etc.
    and removed
    area:kernel logging
    on Aug 1, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    P2Critical bugs or normal featuresarea:logsLog and results collection, storage, etc.good first issueGood for newcomerstype:enhancementNew framework feature or request

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions