From owner-freebsd-bugs@FreeBSD.ORG Wed Sep 12 16:20:01 2007 Return-Path: Delivered-To: freebsd-bugs@hub.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 9996916A469 for ; Wed, 12 Sep 2007 16:20:01 +0000 (UTC) (envelope-from gnats@FreeBSD.org) Received: from freefall.freebsd.org (freefall.freebsd.org [IPv6:2001:4f8:fff6::28]) by mx1.freebsd.org (Postfix) with ESMTP id 5CB4213C47E for ; Wed, 12 Sep 2007 16:20:01 +0000 (UTC) (envelope-from gnats@FreeBSD.org) Received: from freefall.freebsd.org (gnats@localhost [127.0.0.1]) by freefall.freebsd.org (8.14.1/8.14.1) with ESMTP id l8CGK15r012693 for ; Wed, 12 Sep 2007 16:20:01 GMT (envelope-from gnats@freefall.freebsd.org) Received: (from gnats@localhost) by freefall.freebsd.org (8.14.1/8.14.1/Submit) id l8CGK1Ft012692; Wed, 12 Sep 2007 16:20:01 GMT (envelope-from gnats) Resent-Date: Wed, 12 Sep 2007 16:20:01 GMT Resent-Message-Id: <200709121620.l8CGK1Ft012692@freefall.freebsd.org> Resent-From: FreeBSD-gnats-submit@FreeBSD.org (GNATS Filer) Resent-To: freebsd-bugs@FreeBSD.org Resent-Reply-To: FreeBSD-gnats-submit@FreeBSD.org, Sergey Matveychuk Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:4f8:fff6::34]) by hub.freebsd.org (Postfix) with ESMTP id 88CE416A41B for ; Wed, 12 Sep 2007 16:18:24 +0000 (UTC) (envelope-from nobody@FreeBSD.org) Received: from www.freebsd.org (www.freebsd.org [IPv6:2001:4f8:fff6::21]) by mx1.freebsd.org (Postfix) with ESMTP id 5C15813C468 for ; Wed, 12 Sep 2007 16:18:24 +0000 (UTC) (envelope-from nobody@FreeBSD.org) Received: from www.freebsd.org (localhost [127.0.0.1]) by www.freebsd.org (8.14.1/8.14.1) with ESMTP id l8CGIO6n066705 for ; Wed, 12 Sep 2007 16:18:24 GMT (envelope-from nobody@www.freebsd.org) Received: (from nobody@localhost) by www.freebsd.org (8.14.1/8.14.1/Submit) id l8CGIOD5066704; Wed, 12 Sep 2007 16:18:24 GMT (envelope-from nobody) Message-Id: <200709121618.l8CGIOD5066704@www.freebsd.org> Date: Wed, 12 Sep 2007 16:18:24 GMT From: Sergey Matveychuk To: freebsd-gnats-submit@FreeBSD.org X-Send-Pr-Version: www-3.1 Cc: Subject: kern/116310: [patch] prevent junk lines in log on SMP X-BeenThere: freebsd-bugs@freebsd.org X-Mailman-Version: 2.1.5 Precedence: list List-Id: Bug reports List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 12 Sep 2007 16:20:01 -0000 >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@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: