standards/72394: [PATCH] syslog is not thread-safe

[Dan Nelson]

>Number:         72394
>Category:       standards
>Synopsis:       [PATCH] syslog is not thread-safe
>Confidential:   no
>Severity:       non-critical
>Priority:       low
>Responsible:    freebsd-standards
>State:          open
>Quarter:        
>Keywords:       
>Date-Required:
>Class:          sw-bug
>Submitter-Id:   current-users
>Arrival-Date:   Wed Oct 06 17:30:26 GMT 2004
>Closed-Date:
>Last-Modified:
>Originator:     Dan Nelson
>Release:        FreeBSD 5.3-BETA7 i386
>Organization:
The Allant Group, Inc.
>Environment:
System: FreeBSD dan.emsphone.com 5.3-BETA7 FreeBSD 5.3-BETA7 #361: Tue Oct 5 16:17:41 CDT 2004 zsh at dan.emsphone.com:/usr/src/sys/i386/compile/DANSMP i386


	
>Description:
	

The syslog functions are not in the list of thread-unsafe functions at
http://www.opengroup.org/onlinepubs/009695399/functions/xsh_chap02_09.html#tag_02_09_01
, so they are supposed to be safe.  The log fd is not locked, though,
so simultanteous calls to openlog/syslog/closelog may result in lost
entries or lost fds.

>How-To-Repeat:
	

Compile this with kse or thr threads, run it, and count how many log
entries end up in /var/log/messages.  You may end up with missing
lines, or kernel messages saying "unp_connect(): lost race to another
thread".  The closelog() forces an openlog() on the next call to
syslog().  A more likely failure case would be if someone bounced
syslogd, which will force every process with an open log fd to reopen
it.  If openlog/closelog is never called from within a thread and the
fd stays open, syslog() itself is already thread-safe.

#include <pthread.h>
#include <syslog.h>
#include <stdarg.h>

void *logit(void *arg)
{
	char *threadnum = arg;
	int i;
	for (i = 0; i < 100; i++)
	{
		syslog(LOG_WARNING, "I'm thread %s, log entry %03d", threadnum, i+1);
		closelog();
	}
	return 0;
}

int main(void)
{
	pthread_t t1, t2;
	pthread_create(&t1, NULL, &logit, "1");
	pthread_create(&t2, NULL, &logit, "2");
	pthread_join(t1, NULL);
	pthread_join(t2, NULL);
	syslog(LOG_WARNING, "Done");
	return 0;
}


>Fix:

	

Index: lib/libc/gen/syslog.c
===================================================================
RCS file: /home/ncvs/src/lib/libc/gen/syslog.c,v
retrieving revision 1.30
diff -u -p -r1.30 syslog.c
--- lib/libc/gen/syslog.c	10 May 2004 17:12:52 -0000	1.30
+++ lib/libc/gen/syslog.c	6 Oct 2004 17:05:42 -0000
@@ -48,6 +48,7 @@ __FBSDID("$FreeBSD: src/lib/libc/gen/sys
 #include <errno.h>
 #include <fcntl.h>
 #include <paths.h>
+#include <pthread.h>
 #include <stdio.h>
 #include <stdlib.h>
 #include <string.h>
@@ -62,10 +63,20 @@ __FBSDID("$FreeBSD: src/lib/libc/gen/sys
 static int	LogFile = -1;		/* fd for log */
 static int	connected;		/* have done connect */
 static int	opened;			/* have done openlog() */
-static int	LogStat = 0;		/* status bits, set by openlog() */
+static int	LogStat;		/* status bits, set by openlog() */
 static const char *LogTag = NULL;	/* string to tag the entry with */
 static int	LogFacility = LOG_USER;	/* default facility code */
 static int	LogMask = 0xff;		/* mask of priorities to be logged */
+static pthread_mutex_t	syslog_mutex = PTHREAD_MUTEX_INITIALIZER;
+
+#define	THREAD_LOCK() \
+	do { \
+		if (__isthreaded) _pthread_mutex_lock(&syslog_mutex); \
+	} while(0)
+#define	THREAD_UNLOCK()	\
+	do { \
+		if (__isthreaded) _pthread_mutex_unlock(&syslog_mutex); \
+	} while(0)
 
 static void	disconnectlog(void); /* disconnect from syslogd */
 static void	connectlog(void);	/* (re)connect to syslogd */
@@ -141,11 +152,15 @@ vsyslog(pri, fmt, ap)
 		pri &= LOG_PRIMASK|LOG_FACMASK;
 	}
 
+	saved_errno = errno;
+
+	THREAD_LOCK();
+
 	/* Check priority against setlogmask values. */
-	if (!(LOG_MASK(LOG_PRI(pri)) & LogMask))
+	if (!(LOG_MASK(LOG_PRI(pri)) & LogMask)) {
+		THREAD_UNLOCK();
 		return;
-
-	saved_errno = errno;
+	}
 
 	/* Set default facility if none specified. */
 	if ((pri & LOG_FACMASK) == 0)
@@ -155,8 +170,10 @@ vsyslog(pri, fmt, ap)
 	tbuf_cookie.base = tbuf;
 	tbuf_cookie.left = sizeof(tbuf);
 	fp = fwopen(&tbuf_cookie, writehook);
-	if (fp == NULL)
+	if (fp == NULL) {
+		THREAD_UNLOCK();
 		return;
+	}
 
 	/* Build the message. */
 	(void)time(&now);
@@ -186,6 +203,7 @@ vsyslog(pri, fmt, ap)
 		fmt_fp = fwopen(&fmt_cookie, writehook);
 		if (fmt_fp == NULL) {
 			fclose(fp);
+			THREAD_UNLOCK();
 			return;
 		}
 
@@ -243,8 +261,10 @@ vsyslog(pri, fmt, ap)
 	if (!opened)
 		openlog(LogTag, LogStat | LOG_NDELAY, 0);
 	connectlog();
-	if (send(LogFile, tbuf, cnt, 0) >= 0)
+	if (send(LogFile, tbuf, cnt, 0) >= 0) {
+		THREAD_UNLOCK();
 		return;
+	}
 
 	/*
 	 * If the send() failed, the odds are syslogd was restarted.
@@ -252,8 +272,10 @@ vsyslog(pri, fmt, ap)
 	 */
 	disconnectlog();
 	connectlog();
-	if (send(LogFile, tbuf, cnt, 0) >= 0)
+	if (send(LogFile, tbuf, cnt, 0) >= 0) {
+		THREAD_UNLOCK();
 		return;
+	}
 
 	/*
 	 * Output the message to the console; try not to block
@@ -274,6 +296,7 @@ vsyslog(pri, fmt, ap)
 		(void)_writev(fd, iov, 2);
 		(void)_close(fd);
 	}
+	THREAD_UNLOCK();
 }
 static void
 disconnectlog()
@@ -332,6 +355,7 @@ openlog(ident, logstat, logfac)
 	const char *ident;
 	int logstat, logfac;
 {
+	THREAD_LOCK();
 	if (ident != NULL)
 		LogTag = ident;
 	LogStat = logstat;
@@ -342,15 +366,18 @@ openlog(ident, logstat, logfac)
 		connectlog();
 
 	opened = 1;	/* ident and facility has been set */
+	THREAD_UNLOCK();
 }
 
 void
 closelog()
 {
+	THREAD_LOCK();
 	(void)_close(LogFile);
 	LogFile = -1;
 	LogTag = NULL;
 	connected = 0;
+	THREAD_UNLOCK();
 }
 
 /* setlogmask -- set the log mask level */
@@ -360,8 +387,10 @@ setlogmask(pmask)
 {
 	int omask;
 
+	THREAD_LOCK();
 	omask = LogMask;
 	if (pmask != 0)
 		LogMask = pmask;
+	THREAD_UNLOCK();
 	return (omask);
 }

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