Date: Wed, 14 Jun 2017 17:12:38 +0300 From: Konstantin Belousov <kostikbel@gmail.com> To: Eugene Grosbein <eugen@grosbein.net> Cc: FreeBSD Stable <freebsd-stable@FreeBSD.org>, Gleb Smirnoff <glebius@FreeBSD.org> Subject: Re: syslog() thread unsafety Message-ID: <20170614141238.GM2088@kib.kiev.ua> In-Reply-To: <59413EF0.20608@grosbein.net> References: <59413EF0.20608@grosbein.net>
next in thread | previous in thread | raw e-mail | index | archive | help
On Wed, Jun 14, 2017 at 08:49:36PM +0700, Eugene Grosbein wrote:
> Hi!
>
> Our [v]syslog() implementation in src/lib/libc/gen/syslog.c
> tries to be thread-safe and uses "syslog_mutex".
>
> It may lock this mutex then call blocking system calls like sendto().
> If a thread owning this mutex is pthread_cancel()'d in process,
> the mutex stays UMUTEX_CONTESTED and every other thread calling [v]syslog() deadlocks.
>
> I can reproduce this with net/mpd5 daemon reliably within some seconds
> from the beginning of my stress test involving RADIUS so mpd5 runs multi-threaded.
>
> I've tried to wrap every mpd5's [v]syslog() call around with
> pthread_setcancelstate(PTHREAD_CANCEL_DISABLE, &oldstate) and
> pthread_setcancelstate(oldstate, NULL) statements and this eliminates the problem
> but that's not a solution in any way.
>
> This problem seems to be root cause of multiple complaints
> about mpd5 being unstable under FreeBSD 9.x+ version (PR: 186114, 214482).
If the issue is that mpd5 cancels logging thread, and this leaves the
mutex in the locked state, the right solution is to establish a cleanup
handler around the locked region. Note that this can only work if the
cancellation is in deferred mode, async mode is unsafe by definition.
Try something like this, untested even a minimal bit.
diff --git a/lib/libc/gen/syslog.c b/lib/libc/gen/syslog.c
index dfca67360fa..2c390efe95e 100644
--- a/lib/libc/gen/syslog.c
+++ b/lib/libc/gen/syslog.c
@@ -129,8 +129,8 @@ syslog(int pri, const char *fmt, ...)
va_end(ap);
}
-void
-vsyslog(int pri, const char *fmt, va_list ap)
+static void
+vsyslog1(int pri, const char *fmt, va_list ap)
{
int cnt;
char ch, *p;
@@ -151,13 +151,9 @@ vsyslog(int pri, const char *fmt, va_list ap)
saved_errno = errno;
- THREAD_LOCK();
-
/* Check priority against setlogmask values. */
- if (!(LOG_MASK(LOG_PRI(pri)) & LogMask)) {
- THREAD_UNLOCK();
+ if (!(LOG_MASK(LOG_PRI(pri)) & LogMask))
return;
- }
/* Set default facility if none specified. */
if ((pri & LOG_FACMASK) == 0)
@@ -167,10 +163,8 @@ vsyslog(int pri, const char *fmt, va_list ap)
tbuf_cookie.base = tbuf;
tbuf_cookie.left = sizeof(tbuf);
fp = fwopen(&tbuf_cookie, writehook);
- if (fp == NULL) {
- THREAD_UNLOCK();
+ if (fp == NULL)
return;
- }
/* Build the message. */
(void)time(&now);
@@ -200,7 +194,6 @@ vsyslog(int pri, const char *fmt, va_list ap)
fmt_fp = fwopen(&fmt_cookie, writehook);
if (fmt_fp == NULL) {
fclose(fp);
- THREAD_UNLOCK();
return;
}
@@ -285,10 +278,8 @@ vsyslog(int pri, const char *fmt, va_list ap)
*/
disconnectlog();
connectlog();
- if (send(LogFile, tbuf, cnt, 0) >= 0) {
- THREAD_UNLOCK();
+ if (send(LogFile, tbuf, cnt, 0) >= 0)
return;
- }
/*
* if the resend failed, fall through to
* possible scenario 2
@@ -303,15 +294,11 @@ vsyslog(int pri, const char *fmt, va_list ap)
if (status == CONNPRIV)
break;
_usleep(1);
- if (send(LogFile, tbuf, cnt, 0) >= 0) {
- THREAD_UNLOCK();
+ if (send(LogFile, tbuf, cnt, 0) >= 0)
return;
- }
}
- } else {
- THREAD_UNLOCK();
+ } else
return;
- }
/*
* Output the message to the console; try not to block
@@ -333,10 +320,25 @@ vsyslog(int pri, const char *fmt, va_list ap)
(void)_writev(fd, iov, 2);
(void)_close(fd);
}
+}
+
+static void
+syslog_cancel_cleanup(void *arg __unused)
+{
THREAD_UNLOCK();
}
+void
+vsyslog(int pri, const char *fmt, va_list ap)
+{
+
+ THREAD_LOCK();
+ pthread_cleanup_push(syslog_cancel_cleanup, NULL);
+ vsyslog1(pri, fmt, ap);
+ pthread_cleanup_pop(1);
+}
+
/* Should be called with mutex acquired */
static void
disconnectlog(void)
@@ -423,9 +425,11 @@ openlog_unlocked(const char *ident, int logstat, int logfac)
void
openlog(const char *ident, int logstat, int logfac)
{
+
THREAD_LOCK();
+ pthread_cleanup_push(syslog_cancel_cleanup, NULL);
openlog_unlocked(ident, logstat, logfac);
- THREAD_UNLOCK();
+ pthread_cleanup_pop(1);
}
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20170614141238.GM2088>