syslogd pipelines losing messages

[Felix Hernandez-Campos]

Hi,

I've been using syslogd to monitor a few hundred hosts, and I
encountered an interesting problem, which seems to be explained by a
bug in syslogd. In my work, I'm using a slow Pentium II host running
FreeBSD 4.10 to collect syslog messages that arrive at a rate of at
most a couple hundred messages per second. A large percentage of these
messages is useless and I filter them out with grep using a syslog
pipeline, i.e.,/etc/syslog.conf reads

local0.*        | exec grep -v DUPLEX_MISMATCH >> /usr/home2/wap_syslog_local0

Given the moderate arrival rate and that the machine is only used for
this purpose, I would not expect any losses of syslog messages. After
I disabled DNS lookups (syslogd -n), syslogd's CPU usage is very small
(1%), and grep's one is even smaller. However, I observe a large
number of "resource temporarily unavailable" messages in
/var/log/messages. Furthermore, I also noticed that each of these
errors also implies a restart of the grep process (which worried me).

I tracked this down to the failure of a writev call in syslogd. This
is the relevant part of the code (see writev in second "if"
statement):

fprintlog(struct filed *f, int flags, const char *msg) {
…
	case F_PIPE:
		dprintf(" %s\n", f->f_un.f_pipe.f_pname);
		v->iov_base = lf;
		v->iov_len = 1;
		if (f->f_un.f_pipe.f_pid == 0) {
			if ((f->f_file = p_open(f->f_un.f_pipe.f_pname,
						&f->f_un.f_pipe.f_pid)) < 0) {
				f->f_type = F_UNUSED;
				logerror(f->f_un.f_pipe.f_pname);
				break;
			}
		}
		if (writev(f->f_file, iov, 7) < 0) {
			int e = errno;
			(void)close(f->f_file);
			if (f->f_un.f_pipe.f_pid > 0)
				deadq_enter(f->f_un.f_pipe.f_pid,
					    f->f_un.f_pipe.f_pname);
			f->f_un.f_pipe.f_pid = 0;
			errno = e;
			logerror(f->f_un.f_pipe.f_pname);
		}
		break;

For some reason, the pipeline is often not writeable and writev fails
with errno EWOULDBLOCK (f_file is opened in non-blocking mode). After
writev fails, the message is quietly discarded, and the pipeline is
closed. This means that the process reading the pipeline (grep) does
finish its work gracefully, but one message is completely lost. The
next message goes through the first "if" statement in the "switch",
which creates a new pipeline reader. Interestingly, if I add code
inside the second "if" statement to give grep a chance to complete,
e.g.,

                        if (e == EWOULDBLOCK) {
                                usleep(1);
                                if (writev(f->f_file, iov, 7) >= 0) {
                                        logerror("IT WORKED!");
                                        break;
                                }
                        }

the writev call always works. I'm not familiar with the pipeline
implementation, but I would guess the reader is locking the pipeline,
and sometimes syslogd ends up running in the middle of the read
operation, so writev fails. The usleep call gives the pipeline reader
a chance to finish, so the second writev call works fine every time
after my change. My solution is just a proof of concept that solves my
problem, but I wonder whether someone in this list can suggest a
better solution, which should go into the source tree. The simplest
one would be to make f_file blocking, but there was a good reason for
making it non-blocking in the first place, as stated in the code

p_open(const char *prog, pid_t *rpid) {
…
	/*
	 * Avoid blocking on a hung pipe.  With O_NONBLOCK, we are
	 * supposed to get an EWOULDBLOCK on writev(2), which is
	 * caught by the logic above anyway, which will in turn close
	 * the pipe, and fork a new logging subprocess if necessary.
	 * The stale subprocess will be killed some time later unless
	 * it terminated itself due to closing its input pipe (so we
	 * get rid of really dead puppies).
	 */
	if (fcntl(pfd[1], F_SETFL, O_NONBLOCK) == -1) {…}

Anyway, I think I did all the homework, and I just need someone to
suggest an elegant solution rather than my usleep (is there a
yield-type syscall?). I'm more than willing to try out your ideas in
our environment and prepare the patch when something good comes up.

Best regards,
Felix Hernandez-Campos