rsyslogd sometimes doesn't write the initial bits of dmesg to /var/log/syslog

Question

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.

Answer 1

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

3. Load the added rules so it takes effect.

$ augenrules --load

4. Reboot the system.
5. Read the auditd logs to see what tried to access /proc/kmsg.

$ ausearch -k proc_kmsg --interpret

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