2

I have a Linux machine running Ubuntu 16.04.7 LTS that uses rsyslogd. My understanding of rsyslogd is that it rotates the content from the kernel ring buffer (ie, dmesg) to an on-disk file (ie, /var/log/syslog).

So nominally in /var/log/syslog, I expect see a "start" message from rsyslogd followed by kernel messages that I can later retrieve in dmesg. Notice how the first kernel message starts at a relative 0.0000s time.

$ cat /var/log/syslog
... 
rsyslogd: [origin software="rsyslogd" swVersion="8.16.0" x-pid="4970" x-info="http://www.rsyslog.com"] start
...
kernel: [    0.000000] Booting Linux on physical CPU 0x0

Sometimes, when I look at /var/log/syslog, I'd notice that the first kernel message starts as late as 40+ seconds:

$ cat /var/log/syslog
... 
rsyslogd: [origin software="rsyslogd" swVersion="8.16.0" x-pid="4970" x-info="http://www.rsyslog.com"] start
...
kernel: [   45.829155] IRQ6 no longer affine to CPU4

If I then immediately look at dmesg, I'd find the missing "Booting Linux on physical CPU 0x0" message.

$ dmesg | head -n1
kernel: [    0.000000] Booting Linux on physical CPU 0x0

All this makes me think that for some reason, rsyslogd occasionally encounters a race condition in which it doesn't log the first bits of kernel messages. But I have no idea how to go about troubleshooting this. I would love to get some pointers on how to get to the bottom of this problem.

Ken Lin
  • 153
  • This is a good explanation rsyslog and "kernel printk buffer", Indeed, most likely another app is reading /proc/kmsg before rsyslog does. This Question has some Answers with file monitoring ideas. In this case, the read of /proc/kmsg happens early in the boot process. 1. figure out a "read access monitor" recipe 2. Hack one of the first running service files to also launch your "read access monitor" recipe. 3. Post your recipe and the culprit process in an Answer here – JamesThomasMoon May 13 '23 at 04:40
  • 1
    Just so I understand, /proc/kmsg can only be read by one caller at a time. And you're suspecting that two callers may be accessing it simultaneously (ie, rsyslogd and some other process)? If so, if I update rsyslogd to read from /dev/kmsg (which supports parallel reads), I should expect the problem to go away? – Ken Lin May 16 '23 at 01:20
  • "/proc/kmsg can only be read by one caller at a time.". No. The contents of /proc/kmsg can only be read once. That read data within /proc/kmsg is then immediately deleted by the kernel. So whichever process reads /proc/kmsg first during bootup is the one that sees the kernel log messages it contains. Something else to try: If your rsyslog process reads from /proc/kmsg then try changing that to /dev/kmsg as recommended in the linked Answer. /dev/kmsg does not have "read once" behavior. – JamesThomasMoon May 20 '23 at 21:46
  • 1
    I figured it out, much credits to you! Going to leave breadcrumbs by answering my own question. Thanks for the help! – Ken Lin May 30 '23 at 23:28

1 Answers1

2

I was able to figure this out with the help of auditd, which tracks whenever a file of interest has been accessed. Long story short, I had rsyslog and logd both enabled, and they both want to read /proc/kmsg. However, as @JamesThomasMoon pointed out, /proc/kmsg is cleared after someone reads it. So depending on whether rsyslogd or logd gets to /proc/kmsg, my system sometimes has missing syslog.

Here's roughly the steps I took to figure this out...

  1. Install auditd using apt-get, as usual.
  2. Add an auditd rule called proc_kmsg that says "whenever someone reads /proc/kmsg, note it down".
$ cat /etc/audit/rules.d/foobar.rule
-w /proc/kmsg     -p r    -k proc_kmsg
  1. Load the added rules so it takes effect.
$ augenrules --load
  1. Reboot the system.
  2. Read the auditd logs to see what tried to access /proc/kmsg.
$ ausearch -k proc_kmsg --interpret
  1. In my case, I noticed a line that indicates /usr/sbin/rsyslogd attempted to read /proc/kmsg, and there's another line that indicates /sbin/logd is also trying to read /proc/kmsg. It was never my intention to enable both rsyslogd and logd, so I disabled logd accordingly and voila.
type=PROCTITLE msg=audit(05/30/23 18:10:50.266:28) : proctitle=/usr/sbin/rsyslogd -n

and

type=PROCTITLE msg=audit(05/30/23 18:10:50.846:32) : proctitle=/sbin/logd
Ken Lin
  • 153