kern/116310: [patch] prevent junk lines in log on SMP

[Sergey Matveychuk]

>Number:         116310
>Category:       kern
>Synopsis:       [patch] prevent junk lines in log on SMP
>Confidential:   no
>Severity:       non-critical
>Priority:       low
>Responsible:    freebsd-bugs
>State:          open
>Quarter:        
>Keywords:       
>Date-Required:
>Class:          sw-bug
>Submitter-Id:   current-users
>Arrival-Date:   Wed Sep 12 16:20:00 GMT 2007
>Closed-Date:
>Last-Modified:
>Originator:     Sergey Matveychuk
>Release:        6.2-STABLE
>Organization:
Yandex company
>Environment:
FreeBSD xxx.yandex.net 6.2-STABLE FreeBSD 6.2-STABLE #23: Tue Jun 19 13:55:31 MSD 2007     root at raker.yandex.net:/usr/obj/usr/src/sys/CORE-RTR-RELENG_6  i386

>Description:
When kernel processes write in log by log() function, you can see a junk lines on SMP machines. It happens because of log() function makes no locks for logs.

We got many such lines because of lot of messages from ipfw.

An example:

Aug  1 23:38:35 bernoulli kernel: a
Aug  1 23:38:36 bernoulli kernel: <<110>i1p10f>wi:pf w: 99551100  DDeenny y TCTP
C P2 0120.213.1.2835.17.9:8154.6791 :2114360. 121803..218090..52099:5.95082:5 90
o2u tou tv viiaa  vlvaln5a2n75
Aug  1 23:38:36 bernoulli kernel: 27
Aug  1 23:39:28 bernoulli kernel: <110<>i1p10f>wi:p fw3: 52 3De5n2y  DeUnyD PU 8
D7P.2 580.72.532.52500.:25133.28 508:1737.2 580.7.225530.2.5255:3.125358: 13in7
 viian  evim1a
Aug  1 23:39:28 bernoulli kernel:
Aug  1 23:39:32 bernoulli kernel: fw
Aug  1 23:40:03 bernoulli kernel: <<1110>10i>pifpwf: w: 352 3D5e2n yD eUnDyP  U8
D7P. 28570..225504..225540.:215308: 87.1237 8570.25.4250..2255:514.25358 :137i n
i nv ivai ae mem11
Aug  1 23:40:03 bernoulli kernel:
Aug  1 23:40:07 bernoulli kernel: <<111010>i>ipfw:pf w: 3523 52D eDney nyU DUDPP
  8877.2.5205.0.225544.2.25500::113837 8 87.72.502.5250.42.52455.:215358 :1i3n7
 vini av ieam 1
Aug  1 23:40:07 bernoulli kernel: em
Aug  1 23:40:11 bernoulli kernel: <<1110>1i0p>fwip:fw:  3532 D5en2 yDeny  UUDDPP
  8877..225500..225544..225500::113378  8877..225500..225544..225555::113378  in
 ivn viiaa  em1e

>How-To-Repeat:

>Fix:
The patch add a mutex to lock logs in kernel threads.

Patch attached with submission follows:

--- sys/kern/subr_log.c.orig	Wed Aug 22 11:10:28 2007
+++ sys/kern/subr_log.c	Wed Aug 22 11:16:55 2007
@@ -82,6 +82,7 @@
 } logsoftc;
 
 int	log_open;			/* also used in log() */
+struct	mtx log_mtx;
 
 /* Times per second to check for a pending syslog wakeup. */
 static int	log_wakeups_per_second = 5;
@@ -94,6 +95,7 @@
 {
 	if (log_open)
 		return (EBUSY);
+	mtx_init(&log_mtx, "log mutex", NULL, MTX_DEF);
 	log_open = 1;
 	callout_init(&logsoftc.sc_callout, 0);
 	fsetown(td->td_proc->p_pid, &logsoftc.sc_sigio);	/* signal process only */
@@ -112,6 +114,7 @@
 {
 
 	log_open = 0;
+	mtx_destroy(&log_mtx);
 	callout_stop(&logsoftc.sc_callout);
 	logsoftc.sc_state = 0;
 	funsetown(&logsoftc.sc_sigio);
--- sys/kern/subr_prf.c.orig	Wed Aug 22 11:08:23 2007
+++ sys/kern/subr_prf.c	Wed Aug 22 14:14:47 2007
@@ -86,6 +86,7 @@
 };
 
 extern	int log_open;
+extern	struct mtx log_mtx;
 
 static void  msglogchar(int c, int pri);
 static void  putchar(int ch, void *arg);
@@ -231,6 +232,8 @@
 	va_list ap;
 	struct putchar_arg pca;
 
+	if(log_open)
+		mtx_lock(&log_mtx);
 	pca.tty = NULL;
 	pca.pri = level;
 	pca.flags = log_open ? TOLOG : TOCONS;
@@ -240,6 +243,8 @@
 	va_end(ap);
 
 	msgbuftrigger = 1;
+	if(log_open)
+		mtx_unlock(&log_mtx);
 }
 
 #define CONSCHUNK 128


>Release-Note:
>Audit-Trail:
>Unformatted: