klogd dies, possible emit_log_char() vs do_syslog(..READ..) race.

klogd dies, possible emit_log_char() vs do_syslog(..READ..) race.

[Peter Chubb]

Hi,

   Since mid May, my klogd has been turning into a 100% CPU hog at
   regular intervals.  Turns out that sometimes reads from /proc/kmsg
   return with zero bytes read --- pointing to a race between
   do_syslog(SYSLOG_ACTION_READ...) and emit_log_char().
   (In Debian, klogd is invoked with a dd frontend, as
      dd if=/proc/kmsg of=/var/run/klogd bs=1
   where /var/run/klogd is a named pipe; this dd dies when it reads
   zero bytes).

   There's history in the  Debian bug tracker,
   http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=308580 

   I tried an obvious and very ugly band-aid (appended) and the
   problem went away. 

   It seems to me that log_buf_end must be wrapping and be a little
   less than log_buf_start, then when emit_log_char() updates
   log_buf_end it can become equal, causing do_syslog() to return zero
   bytes read.  This'd have to happen between the
   wait_event_interruptible() and the taking of logbuf_lock in
   do_syslog().

   I can't see how this can happen though.  emit_log_char() should
   reset log_start so it can not happen.
   


diff --git a/kernel/printk.c b/kernel/printk.c
index 37dff34..0e44138 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -358,6 +358,7 @@ int do_syslog(int type, char __user *buf, int len, bool from_file)
 			error = -EFAULT;
 			goto out;
 		}
+	again:
 		error = wait_event_interruptible(log_wait,
 							(log_start - log_end));
 		if (error)
@@ -377,6 +378,8 @@ int do_syslog(int type, char __user *buf, int len, bool from_file)
 		spin_unlock_irq(&logbuf_lock);
 		if (!error)
 			error = i;
+		if (error == 0)
+			goto again;
 		break;
 	/* Read/clear last kernel messages */
 	case SYSLOG_ACTION_READ_CLEAR:


--
Dr Peter Chubb  http://www.gelato.unsw.edu.au  peterc AT gelato.unsw.edu.au
http://www.ertos.nicta.com.au           ERTOS within National ICT Australia

Re: klogd dies, possible emit_log_char() vs do_syslog(..READ..) race.

[Peter Zijlstra]

On Tue, 2011-07-26 at 11:08 +1000, Peter Chubb wrote:
> Hi,
> 
>    Since mid May, my klogd has been turning into a 100% CPU hog at
>    regular intervals.  Turns out that sometimes reads from /proc/kmsg
>    return with zero bytes read --- pointing to a race between
>    do_syslog(SYSLOG_ACTION_READ...) and emit_log_char().
>    (In Debian, klogd is invoked with a dd frontend, as
>       dd if=/proc/kmsg of=/var/run/klogd bs=1
>    where /var/run/klogd is a named pipe; this dd dies when it reads
>    zero bytes).

Well I suppose that's a bug anyway since if someone managed to have
multiple consumers of the data you'll get into that same situation,
therefore using dd might not be the sanest thing to do.

Suppose someone does cat /proc/kmsg > /dev/null, just for kicks ;-)

>    There's history in the  Debian bug tracker,
>    http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=308580 
> 
>    I tried an obvious and very ugly band-aid (appended) and the
>    problem went away. 
> 
>    It seems to me that log_buf_end must be wrapping and be a little
>    less than log_buf_start, then when emit_log_char() updates
>    log_buf_end it can become equal, causing do_syslog() to return zero
>    bytes read.  This'd have to happen between the
>    wait_event_interruptible() and the taking of logbuf_lock in
>    do_syslog().
> 
>    I can't see how this can happen though.  emit_log_char() should
>    reset log_start so it can not happen.

Well there is a distinct lack of serialization between the log_start,
log_end usage in wait_event_interruptible() and emit_log_char().

>From what I can see one has to hold the logbuf_lock to get a stable
reading, so if the code in SYSLOG_ACTION_READ requires this for proper
functioning its buggy.

That said, this is the very first time I ever looked at that code ;-)

Does something like the (completely untested) patch below also cure
things?

---
 kernel/printk.c |   16 +++++++++++++---
 1 files changed, 13 insertions(+), 3 deletions(-)

diff --git a/kernel/printk.c b/kernel/printk.c
index 37dff34..25907df 100644
--- a/kernel/printk.c
+++ b/kernel/printk.c
@@ -327,6 +327,17 @@ static int check_syslog_permissions(int type, bool from_file)
 	return 0;
 }
 
+static unsigned int log_size(void)
+{
+	unsigned int size;
+
+	spin_lock_irq(&logbuf_lock);
+	size = log_end - log_start;
+	spin_unlock_irq(&logbuf_lock);
+
+	return size;
+}
+
 int do_syslog(int type, char __user *buf, int len, bool from_file)
 {
 	unsigned i, j, limit, count;
@@ -358,8 +369,7 @@ int do_syslog(int type, char __user *buf, int len, bool from_file)
 			error = -EFAULT;
 			goto out;
 		}
-		error = wait_event_interruptible(log_wait,
-							(log_start - log_end));
+		error = wait_event_interruptible(log_wait, log_size());
 		if (error)
 			goto out;
 		i = 0;
@@ -467,7 +477,7 @@ int do_syslog(int type, char __user *buf, int len, bool from_file)
 		break;
 	/* Number of chars in the log buffer */
 	case SYSLOG_ACTION_SIZE_UNREAD:
-		error = log_end - log_start;
+		error = log_size();
 		break;
 	/* Size of the log buffer */
 	case SYSLOG_ACTION_SIZE_BUFFER:

Re: klogd dies, possible emit_log_char() vs do_syslog(..READ..) race.

[Peter Chubb]

>>>>> "Peter" == Peter Zijlstra <peterz@infradead.org> writes:

Peter> On Tue, 2011-07-26 at 11:08 +1000, Peter Chubb wrote:
>> Hi,
>> 
>> Since mid May, my klogd has been turning into a 100% CPU hog at
>> regular intervals.  Turns out that sometimes reads from /proc/kmsg
>> return with zero bytes read --- pointing to a race between
>> do_syslog(SYSLOG_ACTION_READ...) and emit_log_char().  (In Debian,
>> klogd is invoked with a dd frontend, as dd if=/proc/kmsg
>> of=/var/run/klogd bs=1 where /var/run/klogd is a named pipe; this
>> dd dies when it reads zero bytes).

Peter> Well I suppose that's a bug anyway since if someone managed to
Peter> have multiple consumers of the data you'll get into that same
Peter> situation, therefore using dd might not be the sanest thing to
Peter> do.

Indeed -- and this *is* the case on my system (somehow, rsyslogd and
klogd were both installed).

Peter> Suppose someone does cat /proc/kmsg > /dev/null, just for kicks
Peter> ;-)

They'd have to be privileged in some way to do that.

Peter> Well there is a distinct lack of serialization between the
Peter> log_start, log_end usage in wait_event_interruptible() and
Peter> emit_log_char().

Peter> From what I can see one has to hold the logbuf_lock to get a
Peter> stable reading, so if the code in SYSLOG_ACTION_READ requires
Peter> this for proper functioning its buggy.

You don't need a stable reading -- you just need to be assured that
there's something there to read.  And if there are multiple readers
all bets are off -- in the (usual) single reader case, the count of
things in the buffer should only increase, not decrease, during the race.

Peter> That said, this is the very first time I ever looked at that
Peter> code ;-)

Yes there's no maintainer listed for kernel/printk.c --- I emailed you
because you were the last to touch something in that file, so I
thought that the code should be in your head at least a little bit :-)

Peter> Does something like the (completely untested) patch below also
Peter> cure things?

Nope.  There's still room for something to happen between the wakeup
and the test.  I'm beginning to think my ugly band-aid is the correct patch!

--
Dr Peter Chubb  http://www.gelato.unsw.edu.au  peterc AT gelato.unsw.edu.au
http://www.ertos.nicta.com.au           ERTOS within National ICT Australia