Date: Wed, 26 Jan 2005 21:29:52 -0500 (EST) From: Felix Hernandez Campos <fhernand@cs.unc.edu> To: FreeBSD-gnats-submit@FreeBSD.org Subject: bin/76736: syslogd pipelines losing messages Message-ID: <200501270229.j0R2Tq0N008678@maryann.cs.unc.edu> Resent-Message-ID: <200501270230.j0R2UJMQ060202@freefall.freebsd.org>
next in thread | raw e-mail | index | archive | help
>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 <libutil.h> #include <limits.h> #include <paths.h> + #include <sched.h> #include <signal.h> #include <stdio.h> #include <stdlib.h> *************** *** 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:
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?200501270229.j0R2Tq0N008678>