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 k...@freebsd.org ___ freebsd-current@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-current To unsubscribe, send any mail to freebsd-current-unsubscr...@freebsd.org
Re: message buffer scrambling fix
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. Thanks, Ken ___ freebsd-current@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-current To unsubscribe, send any mail to freebsd-current-unsubscr...@freebsd.org ___ freebsd-current@freebsd.org mailing list http://lists.freebsd.org/mailman/listinfo/freebsd-current To unsubscribe, send any mail to freebsd-current-unsubscr...@freebsd.org
message buffer scrambling fix
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.
Thanks,
Ken
--
Kenneth Merry
k...@freebsd.org
Index: sys/kern/subr_msgbuf.c
===
--- sys/kern/subr_msgbuf.c (revision 222390)
+++ sys/kern/subr_msgbuf.c (working copy)
@@ -31,8 +31,16 @@
#include sys/param.h
#include sys/systm.h
+#include sys/lock.h
+#include sys/mutex.h
#include sys/msgbuf.h
+/*
+ * Maximum number conversion buffer length: uintmax_t in base 2, plus
+ * around the priority, and a terminating NUL.
+ */
+#defineMAXPRIBUF (sizeof(intmax_t) * NBBY + 3)
+
/* Read/write sequence numbers are modulo a multiple of the buffer size. */
#define SEQMOD(size) ((size) * 16)
@@ -51,6 +59,9 @@
mbp-msg_seqmod = SEQMOD(size);
msgbuf_clear(mbp);
mbp-msg_magic = MSG_MAGIC;
+ mbp-msg_lastpri = -1;
+ mbp-msg_needsnl = 0;
+ mtx_init(mbp-msg_lock, msgbuf, NULL, MTX_SPIN);
}
/*
@@ -80,6 +91,11 @@
}
msgbuf_clear(mbp);
}
+
+ mbp-msg_lastpri = -1;
+ /* Assume that the old message buffer didn't end in a newline. */
+ mbp-msg_needsnl = 1;
+ mtx_init(mbp-msg_lock, msgbuf, NULL, MTX_SPIN);
}
/*
@@ -110,28 +126,143 @@
}
/*
- * Append a character to a message buffer. This function can be
- * considered fully reentrant so long as the number of concurrent
- * callers is less than the number of characters in the buffer.
- * However, the message buffer is only guaranteed to be consistent
- * for reading when there are no callers in this function.
+ * Add a character into the message buffer, and update the checksum and
+ * sequence number.
+ *
+ * The caller should hold the message buffer spinlock.
*/
+static inline void
+msgbuf_do_addchar(struct msgbuf *mbp, u_int *seq, int c)
+{
+ u_int pos;
+
+ /* Make sure we properly wrap the sequence number. */
+ pos = MSGBUF_SEQ_TO_POS(mbp, *seq);
+
+ mbp-msg_cksum += (u_int)c -
+ (u_int)(u_char)mbp-msg_ptr[pos];
+
+ mbp-msg_ptr[pos] = c;
+
+ *seq = MSGBUF_SEQNORM(mbp, *seq + 1);
+}
+
+/*
+ * Append a character to a message buffer.
+ */
void
msgbuf_addchar(struct msgbuf *mbp, int c)
{
- u_int new_seq, pos, seq;
+ mtx_lock_spin(mbp-msg_lock);
- do {
- seq = mbp-msg_wseq;
- new_seq = MSGBUF_SEQNORM(mbp, seq + 1);
- } while (atomic_cmpset_rel_int(mbp-msg_wseq, seq, new_seq) == 0);
- pos = MSGBUF_SEQ_TO_POS(mbp, seq);
- atomic_add_int(mbp-msg_cksum, (u_int)(u_char)c -
- (u_int)(u_char)mbp-msg_ptr[pos]);
- mbp-msg_ptr[pos] = c;
+ msgbuf_do_addchar(mbp, mbp-msg_wseq, c);
+
+ mtx_unlock_spin(mbp-msg_lock);
}
/*
+ * Append a NUL-terminated string with a priority to a message
