From 5fc6fc53eed51b106058ed08dbfbec744f12aebd Mon Sep 17 00:00:00 2001 From: bluhm Date: Tue, 9 Mar 2021 15:08:23 +0000 Subject: [PATCH] Early daemons like dhcpleased(8), slaacd(8), unwind(8), resolvd(8) are started before syslogd(8). This resulted in ugly sendsyslog(2) dropped logs and the real message was lost. Create a temporary stash for log messages within the kernel. It has a limited size of 100 messages, and each message is truncated to 8192 bytes. When the stash is exhausted, the well-known dropped message is generated with a counter. After syslogd(8) has setup everything, it sends a debug line through libc to flush the kernel stash. Then syslogd receives all messages from the kernel before the usual logs. OK deraadt@ visa@ --- lib/libc/sys/sendsyslog.2 | 10 +- sys/kern/subr_log.c | 182 +++++++++++++++++++++++++++++++------ sys/sys/malloc.h | 6 +- usr.sbin/syslogd/syslogd.c | 6 +- 4 files changed, 168 insertions(+), 36 deletions(-) diff --git a/lib/libc/sys/sendsyslog.2 b/lib/libc/sys/sendsyslog.2 index 278a4f99cd7..b1bd25a4f5c 100644 --- a/lib/libc/sys/sendsyslog.2 +++ b/lib/libc/sys/sendsyslog.2 @@ -1,4 +1,4 @@ -.\" $OpenBSD: sendsyslog.2,v 1.12 2020/11/05 16:04:39 jmc Exp $ +.\" $OpenBSD: sendsyslog.2,v 1.13 2021/03/09 15:08:23 bluhm Exp $ .\" .\" Copyright (c) 2017 Alexander Bluhm .\" Copyright (c) 2014 Theo de Raadt @@ -15,7 +15,7 @@ .\" ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF .\" OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. .\" -.Dd $Mdocdate: November 5 2020 $ +.Dd $Mdocdate: March 9 2021 $ .Dt SENDSYSLOG 2 .Os .Sh NAME @@ -51,10 +51,12 @@ This is used internally by so that messages can be sent during difficult situations. If sending to .Xr syslogd 8 -fails, dropped messages are counted. +fails, up to 100 messages are stashed in the kernel. +After that, dropped messages are counted. When .Xr syslogd 8 -works again, a warning with the counter and error number is logged. +works again, before the next message, stashed messages and possibly +a warning with the drop counter, error number, and pid is logged. .Pp To receive messages from the kernel, .Xr syslogd 8 diff --git a/sys/kern/subr_log.c b/sys/kern/subr_log.c index 1ff754ab19d..26418a3e19a 100644 --- a/sys/kern/subr_log.c +++ b/sys/kern/subr_log.c @@ -1,4 +1,4 @@ -/* $OpenBSD: subr_log.c,v 1.72 2021/02/08 08:18:45 mpi Exp $ */ +/* $OpenBSD: subr_log.c,v 1.73 2021/03/09 15:08:23 bluhm Exp $ */ /* $NetBSD: subr_log.c,v 1.11 1996/03/30 22:24:44 christos Exp $ */ /* @@ -454,6 +454,149 @@ logioctl(dev_t dev, u_long com, caddr_t data, int flag, struct proc *p) return (0); } +/* + * If syslogd is not running, temporarily store a limited amount of messages + * in kernel. After log stash is full, drop messages and count them. When + * syslogd is available again, next log message will flush the stashed + * messages and insert a message with drop count. Calls to malloc(9) and + * copyin(9) may sleep, protect data structures with rwlock. + */ + +#define LOGSTASH_SIZE 100 +struct logstash_message { + char *lgs_buffer; + size_t lgs_size; +} logstash_messages[LOGSTASH_SIZE]; + +struct logstash_message *logstash_in = &logstash_messages[0]; +struct logstash_message *logstash_out = &logstash_messages[0]; + +struct rwlock logstash_rwlock = RWLOCK_INITIALIZER("logstash"); + +int logstash_dropped, logstash_error, logstash_pid; + +int logstash_insert(const char *, size_t, int, pid_t); +void logstash_remove(void); +int logstash_sendsyslog(struct proc *); + +static inline int +logstash_full(void) +{ + rw_assert_anylock(&logstash_rwlock); + + return logstash_out->lgs_buffer != NULL && + logstash_in == logstash_out; +} + +static inline void +logstash_increment(struct logstash_message **msg) +{ + rw_assert_wrlock(&logstash_rwlock); + + KASSERT((*msg) >= &logstash_messages[0]); + KASSERT((*msg) < &logstash_messages[LOGSTASH_SIZE]); + if ((*msg) == &logstash_messages[LOGSTASH_SIZE - 1]) + (*msg) = &logstash_messages[0]; + else + (*msg)++; +} + +int +logstash_insert(const char *buf, size_t nbyte, int logerror, pid_t pid) +{ + int error; + + rw_enter_write(&logstash_rwlock); + + if (logstash_full()) { + if (logstash_dropped == 0) { + logstash_error = logerror; + logstash_pid = pid; + } + logstash_dropped++; + + rw_exit(&logstash_rwlock); + return (0); + } + + logstash_in->lgs_buffer = malloc(nbyte, M_LOG, M_WAITOK); + error = copyin(buf, logstash_in->lgs_buffer, nbyte); + if (error) { + free(logstash_in->lgs_buffer, M_LOG, nbyte); + logstash_in->lgs_buffer = NULL; + + rw_exit(&logstash_rwlock); + return (error); + } + logstash_in->lgs_size = nbyte; + logstash_increment(&logstash_in); + + rw_exit(&logstash_rwlock); + return (0); +} + +void +logstash_remove(void) +{ + rw_assert_wrlock(&logstash_rwlock); + + KASSERT(logstash_out->lgs_buffer != NULL); + free(logstash_out->lgs_buffer, M_LOG, logstash_out->lgs_size); + logstash_out->lgs_buffer = NULL; + logstash_increment(&logstash_out); + + /* Insert dropped message in sequence where messages were dropped. */ + if (logstash_dropped) { + size_t l, nbyte; + char buf[80]; + + l = snprintf(buf, sizeof(buf), + "<%d>sendsyslog: dropped %d message%s, error %d, pid %d", + LOG_KERN|LOG_WARNING, logstash_dropped, + logstash_dropped == 1 ? "" : "s", + logstash_error, logstash_pid); + logstash_dropped = 0; + logstash_error = 0; + logstash_pid = 0; + + /* Cannot fail, we have just freed a slot. */ + KASSERT(!logstash_full()); + nbyte = ulmin(l, sizeof(buf) - 1); + logstash_in->lgs_buffer = malloc(nbyte, M_LOG, M_WAITOK); + memcpy(logstash_in->lgs_buffer, buf, nbyte); + logstash_in->lgs_size = nbyte; + logstash_increment(&logstash_in); + } +} + +int +logstash_sendsyslog(struct proc *p) +{ + int error; + + rw_enter_write(&logstash_rwlock); + + while (logstash_out->lgs_buffer != NULL) { + error = dosendsyslog(p, logstash_out->lgs_buffer, + logstash_out->lgs_size, 0, UIO_SYSSPACE); + if (error) { + rw_exit(&logstash_rwlock); + return (error); + } + logstash_remove(); + } + + rw_exit(&logstash_rwlock); + return (0); +} + +/* + * Send syslog(3) message from userland to socketpair(2) created by syslogd(8). + * Store message in kernel log stash for later if syslogd(8) is not available + * or sending fails. Send to console if LOG_CONS is set and syslogd(8) socket + * does not exist. + */ + int sys_sendsyslog(struct proc *p, void *v, register_t *retval) { @@ -462,32 +605,18 @@ sys_sendsyslog(struct proc *p, void *v, register_t *retval) syscallarg(size_t) nbyte; syscallarg(int) flags; } */ *uap = v; + size_t nbyte; int error; - static int dropped_count, orig_error, orig_pid; - if (dropped_count) { - size_t l; - char buf[80]; + nbyte = SCARG(uap, nbyte); + if (nbyte > LOG_MAXLINE) + nbyte = LOG_MAXLINE; - l = snprintf(buf, sizeof(buf), - "<%d>sendsyslog: dropped %d message%s, error %d, pid %d", - LOG_KERN|LOG_WARNING, dropped_count, - dropped_count == 1 ? "" : "s", orig_error, orig_pid); - error = dosendsyslog(p, buf, ulmin(l, sizeof(buf) - 1), - 0, UIO_SYSSPACE); - if (error == 0) { - dropped_count = 0; - orig_error = 0; - orig_pid = 0; - } - } - error = dosendsyslog(p, SCARG(uap, buf), SCARG(uap, nbyte), - SCARG(uap, flags), UIO_USERSPACE); - if (error) { - dropped_count++; - orig_error = error; - orig_pid = p->p_p->ps_pid; - } + logstash_sendsyslog(p); + error = dosendsyslog(p, SCARG(uap, buf), nbyte, SCARG(uap, flags), + UIO_USERSPACE); + if (error && error != EFAULT) + logstash_insert(SCARG(uap, buf), nbyte, error, p->p_p->ps_pid); return (error); } @@ -505,9 +634,6 @@ dosendsyslog(struct proc *p, const char *buf, size_t nbyte, int flags, size_t i, len; int error; - if (nbyte > LOG_MAXLINE) - nbyte = LOG_MAXLINE; - /* Global variable syslogf may change during sleep, use local copy. */ fp = syslogf; if (fp) @@ -607,7 +733,7 @@ dosendsyslog(struct proc *p, const char *buf, size_t nbyte, int flags, #endif if (fp) FRELE(fp, p); - else + else if (error != EFAULT) error = ENOTCONN; return (error); } diff --git a/sys/sys/malloc.h b/sys/sys/malloc.h index 7db0284af2e..b5569903d66 100644 --- a/sys/sys/malloc.h +++ b/sys/sys/malloc.h @@ -1,4 +1,4 @@ -/* $OpenBSD: malloc.h,v 1.120 2021/02/23 13:50:16 jsg Exp $ */ +/* $OpenBSD: malloc.h,v 1.121 2021/03/09 15:08:23 bluhm Exp $ */ /* $NetBSD: malloc.h,v 1.39 1998/07/12 19:52:01 augustss Exp $ */ /* @@ -83,7 +83,7 @@ /* 21 - free */ #define M_NFSREQ 22 /* NFS request header */ #define M_NFSMNT 23 /* NFS mount structure */ -/* 24 - free */ +#define M_LOG 24 /* Messages in kernel log stash */ #define M_VNODE 25 /* Dynamically allocated vnodes */ #define M_CACHE 26 /* Dynamically allocated cache entries */ #define M_DQUOT 27 /* UFS quota entries */ @@ -208,7 +208,7 @@ NULL, \ "NFS req", /* 22 M_NFSREQ */ \ "NFS mount", /* 23 M_NFSMNT */ \ - NULL, \ + "log", /* 24 M_LOG */ \ "vnodes", /* 25 M_VNODE */ \ "namecache", /* 26 M_CACHE */ \ "UFS quota", /* 27 M_DQUOT */ \ diff --git a/usr.sbin/syslogd/syslogd.c b/usr.sbin/syslogd/syslogd.c index 9b324a61dfb..98c79c80b82 100644 --- a/usr.sbin/syslogd/syslogd.c +++ b/usr.sbin/syslogd/syslogd.c @@ -1,4 +1,4 @@ -/* $OpenBSD: syslogd.c,v 1.264 2020/09/14 20:36:01 bluhm Exp $ */ +/* $OpenBSD: syslogd.c,v 1.265 2021/03/09 15:08:23 bluhm Exp $ */ /* * Copyright (c) 2014-2017 Alexander Bluhm @@ -891,6 +891,10 @@ main(int argc, char *argv[]) if (sigprocmask(SIG_SETMASK, &sigmask, NULL) == -1) err(1, "sigprocmask unblock"); + /* Send message via libc, flushes log stash in kernel. */ + openlog("syslogd", LOG_PID, LOG_SYSLOG); + syslog(LOG_DEBUG, "running"); + event_dispatch(); /* NOTREACHED */ return (0); -- 2.20.1