Kernel messages not logged to /var/log/kern.log

Confirmed by Martin Pitt as well.

<pitti> mdz: hm, "sudo tail -f /proc/kmsg" doesn't report anything either (tried with some modprobe)
<pitti> itz kernel bug?

I used this to reliably and conveniently produce kernel messages and verify that dmesg has new stuff:

$ sudo dmesg -c
$ sudo /etc/init.d/apparmor restart
Reloading AppArmor profiles : done.
$ sudo dmesg -c
[68804.887693] type=1505 audit(1218098412.816:494): operation="profile_replace" name="/usr/share/gdm/guest-session/Xsession" name2="default" pid=27662
[68805.155782] type=1505 audit(1218098413.084:495): operation="profile_replace" name="/usr/lib/cups/backend/cups-pdf" name2="default" pid=27667
[68805.156318] type=1505 audit(1218098413.084:496): operation="profile_replace" name="/usr/sbin/cupsd" name2="default" pid=27667

I started this in the background before:

sudo /etc/init.d/klogd stop
sudo tail -f /proc/kmsg

no output from the latter

printk looks correct to me:

$ cat /proc/sys/kernel/printk
4 4 1 7

I've reproduced this. Working through the motions...

The most recent message (in /var/log/kern.log.0) on my system is:

Jul 11 09:16:49 mizar kernel: Kernel log daemon terminating.

and I was running 2.6.26-2.6 at that time, so this has been broken for quite a while.

After more investigation, it seems that tail -f is not the right way to reproduce this. Using cat or dd shows that messages are actually getting out of /proc/kmsg. Strace shows that klogd is actually reading them, and is doing a sendto() to send them to syslog.

However, the problem is that they are not being sent to /var/log/kern.log, presumably because they are being sent as klogd.* and syslog is looking for kern.*. You can see the messages in /var/log/syslog, so it's definite that they are getting there.

Reverting back to klogd.

klogd.c is still using "kernel":
                openlog("kernel", 0, LOG_KERN);

but the messages are ending up with "klogd":

mizar:[/tmp/sysklogd-1.5] grep kernel: /var/log/syslog
zsh: exit 1 grep kernel: /var/log/syslog
mizar:[/tmp/sysklogd-1.5] grep klogd: /var/log/syslog
Aug 15 09:54:55 mizar klogd: [253172.357916] usb 2-1.3: USB disconnect, address 4
Aug 15 09:54:55 mizar klogd: [253172.364002] cannot submit datapipe for urb 0, error -19: no device
Aug 15 09:55:43 mizar klogd: [253220.720528] Marking TSC unstable due to: cpufreq changes.
Aug 15 09:55:44 mizar klogd: [253221.032029] Clocksource tsc unstable (delta = -202362927 ns)
mizar:[/tmp/sysklogd-1.5]

This bug was fixed in the package sysklogd - 1.5-2ubuntu6

---------------
sysklogd (1.5-2ubuntu6) intrepid; urgency=low

  * Makefile: disable FORTIFY_SOURCE for klogd, otherwise the protection
    macros redirect the calls improperly (LP: #255635).

 -- Kees Cook <email address hidden> Fri, 29 Aug 2008 16:50:29 -0700

confirming the success of the fix in Intrepid, thank you :)

Removing the Debian bug watch; this was actually a different (Ubuntu-specific) bug