From owner-freebsd-bugs@FreeBSD.ORG Thu Jan 27 02:30:19 2005 Return-Path: Delivered-To: freebsd-bugs@hub.freebsd.org Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id A785E16A4CE for ; Thu, 27 Jan 2005 02:30:19 +0000 (GMT) Received: from freefall.freebsd.org (freefall.freebsd.org [216.136.204.21]) by mx1.FreeBSD.org (Postfix) with ESMTP id 6829143D45 for ; Thu, 27 Jan 2005 02:30:19 +0000 (GMT) (envelope-from gnats@FreeBSD.org) Received: from freefall.freebsd.org (gnats@localhost [127.0.0.1]) by freefall.freebsd.org (8.13.1/8.13.1) with ESMTP id j0R2UJK8060203 for ; Thu, 27 Jan 2005 02:30:19 GMT (envelope-from gnats@freefall.freebsd.org) Received: (from gnats@localhost) by freefall.freebsd.org (8.13.1/8.13.1/Submit) id j0R2UJMQ060202; Thu, 27 Jan 2005 02:30:19 GMT (envelope-from gnats) Resent-Date: Thu, 27 Jan 2005 02:30:19 GMT Resent-Message-Id: <200501270230.j0R2UJMQ060202@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, Felix Hernandez Campos Received: from mx1.FreeBSD.org (mx1.freebsd.org [216.136.204.125]) by hub.freebsd.org (Postfix) with ESMTP id 45B1C16A4CE for ; Thu, 27 Jan 2005 02:29:57 +0000 (GMT) Received: from maryann.cs.unc.edu (maryann.cs.unc.edu [152.2.137.17]) by mx1.FreeBSD.org (Postfix) with ESMTP id 9080543D41 for ; Thu, 27 Jan 2005 02:29:56 +0000 (GMT) (envelope-from fhernand@maryann.cs.unc.edu) Received: from maryann.cs.unc.edu (localhost.cs.unc.edu [127.0.0.1]) by maryann.cs.unc.edu (8.12.11/8.12.11) with ESMTP id j0R2TreE008679 for ; Wed, 26 Jan 2005 21:29:53 -0500 (EST) (envelope-from fhernand@maryann.cs.unc.edu) Received: (from root@localhost) by maryann.cs.unc.edu (8.12.11/8.12.11/Submit) id j0R2Tq0N008678; Wed, 26 Jan 2005 21:29:52 -0500 (EST) (envelope-from fhernand) Message-Id: <200501270229.j0R2Tq0N008678@maryann.cs.unc.edu> Date: Wed, 26 Jan 2005 21:29:52 -0500 (EST) From: Felix Hernandez Campos To: FreeBSD-gnats-submit@FreeBSD.org X-Send-Pr-Version: 3.113 Subject: bin/76736: syslogd pipelines losing messages X-BeenThere: freebsd-bugs@freebsd.org X-Mailman-Version: 2.1.1 Precedence: list Reply-To: Felix Hernandez Campos List-Id: Bug reports List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Thu, 27 Jan 2005 02:30:19 -0000 >Number: 76736 >Category: bin >Synopsis: syslogd pipelines losing messages >Confidential: no >Severity: non-critical >Priority: medium >Responsible: freebsd-bugs >State: open >Quarter: >Keywords: >Date-Required: >Class: sw-bug >Submitter-Id: current-users >Arrival-Date: Thu Jan 27 02:30:18 GMT 2005 >Closed-Date: >Last-Modified: >Originator: Felix Hernandez Campos >Release: FreeBSD 4.10-RELEASE i386 >Organization: University of North Carolina >Environment: System: FreeBSD maryann.cs.unc.edu 4.10-RELEASE FreeBSD 4.10-RELEASE #0: Tue May 25 22:47:12 GMT 2004 root@perseus.cse.buffalo.edu:/usr/obj/usr/src/sys/GENERIC i386 >Description: Syslogd supports logging subprocesses that communicate with the daemon using pipelines, e.g., in /etc/syslog.conf local0.* | exec grep -v DUPLEX >> /root/log If the arrival rate of syslog messages is high enough (above 100 per second), syslogd may try to write to the pipeline too fast. The symptom of this problem is a line like Jan 22 16:48:57 maryann syslogd: exec grep -v DUPLEX >> /root/log: Resource temporarily unavailable in /var/log/messages. The cause of the problem is the use of non-blocking writes by syslogd, which will fail when the pipe is full. In this case, the file descriptor of the pipe is closed, and the syslog message quietly discarded. See http://lists.freebsd.org/pipermail/freebsd-hackers/2005-January/009921.html for further details. >How-To-Repeat: Configure a syslog pipeline in one of the local facilities (see above) and write a program that submits numbered syslog messages to the same facility. You should see “resource temporarily unavailable” in /var/log/messages, and gaps in the sequence of logged messages. In my environment, syslog messages come from a large number of hosts, so it may be that network buffering aggravates (or even creates) this problem. >Fix: The solution is to check whether the pipeline is full, and if so give the logging subprocess a chance to empty the pipeline. This has to be implemented in a way that still protects syslogd against hung logging subprocesses. The following patch worked well in my environment. I also tried it against CURRENT (syslogd version 1.140) and the patch worked fine. *** syslogd.c.1.59.2.28 Wed Jan 26 18:30:28 2005 --- syslogd.c Wed Jan 26 18:51:21 2005 *************** *** 103,108 **** --- 103,109 ---- #include #include #include + #include #include #include #include *************** *** 1153,1158 **** --- 1154,1167 ---- } if (writev(f->f_file, iov, 7) < 0) { int e = errno; + if (e == EWOULDBLOCK) { + /* Pipe may just be full, so give logging + * subprocess a chance to empty the pipe + * before assuming that the subprocess hung */ + sched_yield(); + if (writev(f->f_file, iov, 7) >= 0) + break; + } (void)close(f->f_file); if (f->f_un.f_pipe.f_pid > 0) deadq_enter(f->f_un.f_pipe.f_pid, >Release-Note: >Audit-Trail: >Unformatted: