Bug 44211

Summary: /proc/kmsg does not (always) block for 1-byte reads (bisected)
Product: File System Reporter: Jukka Ollila (jiiksteri)
Component: OtherAssignee: fs_other
Status: RESOLVED CODE_FIX    
Severity: normal CC: alan, greg, jbeulich, kay
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 3.5-rc5+ Subsystem:
Regression: Yes Bisected commit-id:

Description Jukka Ollila 2012-07-03 16:30:59 UTC 
Hello.

I'm seeing strange behaviour with /proc/kmsg starting with commit

b56a39ac263e5b8cafedd551a49c2105e68b98c2 printk: return -EINVAL if the message len is bigger than the buf size

This has since been reverted by 6fda135c908d0f38a0167adcbd71094572e3059b and fixed differently with 116e90b23f74d303e8d607c7a7d54f60f14ab9f2 but the problem persists with current HEAD 9d4056aa9efa07015aa6da11ae2e72f22dc55c97

This is on a debian unstable userspace. Kernel logging is handled in two parts:

/bin/dd bs=1 if=/proc/kmsg of=/var/run/klogd/kmsg

which shovels /proc/kmsg into a fifo, that's read by klogd proper for producing the log files themselves:

/sbin/klogd -P /var/run/klogd/kmsg

The problem here is the dd part.

Given bs=1, it tries to do byte-size reads from /proc/kmsg. Starting at the commit referenced above, read(2) apparently immediately returns 0 instead of blocking. The dd process interprets this as EOF and exits. The klogd process on the reading end of the /var/run/klogd/kmsg fifo gets upset because the writer goes away and starts eating 100% CPU instead of, well, logging things.

If I drain /proc/kmsg into the fifo by hand (using cat(1)) and start klogd (with the dd and all) again, it strangely works.

There's an argument to be made that this is debian userspace being broken, but technically it's a kernel regression since it used to work. So I'm reporting it.

Apologies if I get the bug category wrong, I couldn't find anything appopriate for printk/logging related woes. But /proc is where I'm seeing this problem and it's a file system, sort of :)
Comment 1 Jukka Ollila 2012-07-03 22:37:16 UTC 
I hacked together a simple kernel module that just printk():s a message periodically and took a look at /proc/kmsg.

With

<6>[23715.200075] Hello2 (ffff88004a3b6488)

in /proc/kmsg, I can /bin/dd if=/proc/kmsg bs=44 just fine, 44 being the length of the message. That will block nicely and run seemingly forever. Or until someone logs something that's not 44 bytes.

Anything below bs=44 results in 0 bytes read, ie. EOF.

If I try with "Hello" instead of "Hello2", bs=43 works and so on.
Comment 2 Alan 2012-07-05 09:49:05 UTC 
Probably best to also email this to the mailing list (and Jan Beulich/GregKH) initially.

Alan
Comment 3 Jan Beulich 2012-07-05 11:53:35 UTC 
With the new one-message-at-a-time approach, I don't think reading single bytes works this way anymore: The entire message gets consumed, and returning just a single byte of it to user space would make it impossible to obtain the rest of the message. Please also Cc kay@vrfy.org (whom I can't Cc here as he doesn't appear to be known to bugzilla, yet whom I would like to check whether this my understanding is correct, as he did the underlying large re-write).
Comment 4 Kay Sievers 2012-07-08 12:39:20 UTC 
Patch posted:
  https://lkml.org/lkml/2012/7/7/118

Side note:
This will still not make dd bs=1 work reliably. It never was. The /proc/kmsg interface might always return 0 for read, not indicating EOF, but telling try-again. This was always the case, and dd was never safe to use here. You find years old bugs for this on the net.
Comment 5 Jukka Ollila 2012-07-08 19:42:44 UTC 
Before filing this I saw some reports that had issues with multiple readers, and as mentioned on lkml that would be tricky to get right on the kernel side. Or even figure out what could be correct and defined behaviour for multiple readers. So I'd imagine it's safe to ignore those.

But this is a single blocking reader. So unless the old code had cases where it would return 0 to a single blocking short read, the dd bs=1 _did_ work reliably :)

Not that I'm defending it. But multiple readers is a different case altogether.

Anyway, thanks for working on this :)
Comment 6 Kay Sievers 2012-07-08 23:38:03 UTC 
On Sun, Jul 8, 2012 at 9:42 PM,  <bugzilla-daemon@bugzilla.kernel.org> wrote:
> --- Comment #5 from Jukka Ollila <jiiksteri@gmail.com>  2012-07-08 19:42:44
> ---
> Before filing this I saw some reports that had issues with multiple readers,

Yss, it was always the case.

> and as mentioned on lkml that would be tricky to get right on the kernel
> side.

It's rather trivial, just quite some code to change.

> Or even figure out what could be correct and defined behaviour for multiple
> readers. So I'd imagine it's safe to ignore those.

It can't be fixed properly for multiple readers, it has kernel
internal global state, that is shared.

The new /dev/kmsg structured data/record interface supports as many
readers as wanted, and it also never keeps an kernel global state, and
never flushes the buffer. It can be read as many times as wanted.

> But this is a single blocking reader. So unless the old code had cases where
> it
> would return 0 to a single blocking short read, the dd bs=1 _did_ work
> reliably

It should be safe. But building system tools on the assumption that
nobody ever does "cat /proc/kmsg" is just crazy.

> Not that I'm defending it. But multiple readers is a different case
> altogether.

Yes, and no. But building such fragile with assumptions like "don't
touch it or it breaks" things is just wrong.

> Anyway, thanks for working on this :)

Sure, hope that will all work now.

Thanks!
Comment 7 Jukka Ollila 2012-07-15 13:03:30 UTC 
Marking this as resolved.

Kay's fix (eb02dac93708f581c99858a19162af8ca2b6bfcb) is in 3.5-rc7. The dd log shovel works again.