Re: message buffer scrambling fix

On Sat, May 28, 2011 at 11:26:50 -0700, Julian Elischer wrote:
> On 5/27/11 3:45 PM, Kenneth D. Merry wrote:
> >Hey folks,
> >
> >I have attached some patches to the kernel message buffer code (this
> >affects dmesg(8) output as well as kernel messages that go to the syslog)
> >to address log scrambling.
> >
> >This fixes the same issue that 'options PRINTF_BUFR_SIZE=128' fixes for the
> >console.
> >
> >The problem is that you can have multiple kernel threads writing to the
> >message buffer at the same time, and so their characters will get
> >interleaved.  All of the characters will get in there, because they're
> >written with atomic operations, but the output might looked scrambled.
> >
> >So the fix is to use the same stack buffer that is used for the console
> >output (so the stack size doesn't increase), and use a spin lock instead of
> >atomic operations to insert the string into the message buffer.
> >
> >The result is that dmesg and syslog output should look the same as the
> >console output.  As long as individual kernel prints fit in the printf
> >buffer size, they will be put into the message buffer atomically.
> >
> >I also fixed a couple of other long-standing issues.  putcons() (in
> >subr_prf.c) was adding a carriage return before calling cnputs().  But
> >cnputs() calls cnputc(), which adds a carriage return before every newline.
> >So much of the console output (the part that came from putcons() at least)
> >had two carriage returns at the end.
> >
> >The other issue was that log_console() was inserting a newline for any
> >console write that didn't already have one at the end.  The issue with that
> >can be seen if you do a 'dmesg -a' and compare that to the console output.
> >
> >You'll see something like this on the console:
> >
> >Updating motd:.
> >
> >But this in dmesg -a:
> >
> >Updating motd:
> >.
> >
> >That is because "Updating motd:" is written first, log_console() appends a
> >newline, and then ".\n" is written.
> >
> >I added a loader tunable and sysctl to turn the old behavior back on
> >(kern.log_console_add_linefeed) if you want the old behavior, but I think
> >we should be able to safely remove it.
> >
> >Also, the new msgbuf_addstr() function allows the caller to optionally ask
> >for carriage returns to be stripped out.  However, in my testing I haven't
> >seen any carriage returns to strip.
> >
> >Let me know if you have any comments.  I'm planning to check this into head
> >next week.
> 
> looks good.. as long as we don't end up  with the behaviour that I 
> think I see on
> Linux (it's hard to tell sometimes) where the last message (the one 
> you really
> want to see) doesn't make it out.

Everything passed into the kernel printf() call should make it out to the
console, message buffer, etc. before the printf call completes.  The only
way that wouldn't happen is if spin locks break for some reason.

One thing I forgot to mention is that I think the PRINTF_BUFR_SIZE option
should be made non-optional.  Even on smaller embedded machines, I think we
should be able to afford the 128 bytes of stack space to keep messages from
getting scrambled.

Ken
-- 
Kenneth Merry
ken_at_FreeBSD.ORG