From owner-freebsd-stable@freebsd.org Wed Jun 14 14:12:44 2017 Return-Path: Delivered-To: freebsd-stable@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 55881D8EAFE for ; Wed, 14 Jun 2017 14:12:44 +0000 (UTC) (envelope-from kostikbel@gmail.com) Received: from kib.kiev.ua (kib.kiev.ua [IPv6:2001:470:d5e7:1::1]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (Client did not present a certificate) by mx1.freebsd.org (Postfix) with ESMTPS id EA92464DA8; Wed, 14 Jun 2017 14:12:43 +0000 (UTC) (envelope-from kostikbel@gmail.com) Received: from tom.home (kib@localhost [127.0.0.1]) by kib.kiev.ua (8.15.2/8.15.2) with ESMTPS id v5EECcn9072462 (version=TLSv1.2 cipher=DHE-RSA-AES256-GCM-SHA384 bits=256 verify=NO); Wed, 14 Jun 2017 17:12:38 +0300 (EEST) (envelope-from kostikbel@gmail.com) DKIM-Filter: OpenDKIM Filter v2.10.3 kib.kiev.ua v5EECcn9072462 Received: (from kostik@localhost) by tom.home (8.15.2/8.15.2/Submit) id v5EECc5F072461; Wed, 14 Jun 2017 17:12:38 +0300 (EEST) (envelope-from kostikbel@gmail.com) X-Authentication-Warning: tom.home: kostik set sender to kostikbel@gmail.com using -f Date: Wed, 14 Jun 2017 17:12:38 +0300 From: Konstantin Belousov To: Eugene Grosbein Cc: FreeBSD Stable , Gleb Smirnoff Subject: Re: syslog() thread unsafety Message-ID: <20170614141238.GM2088@kib.kiev.ua> References: <59413EF0.20608@grosbein.net> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <59413EF0.20608@grosbein.net> User-Agent: Mutt/1.8.2 (2017-04-18) X-Spam-Status: No, score=-2.0 required=5.0 tests=ALL_TRUSTED,BAYES_00, DKIM_ADSP_CUSTOM_MED,FREEMAIL_FROM,NML_ADSP_CUSTOM_MED autolearn=no autolearn_force=no version=3.4.1 X-Spam-Checker-Version: SpamAssassin 3.4.1 (2015-04-28) on tom.home X-BeenThere: freebsd-stable@freebsd.org X-Mailman-Version: 2.1.23 Precedence: list List-Id: Production branch of FreeBSD source code List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 14 Jun 2017 14:12:44 -0000 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); }