Early daemons like dhcpleased(8), slaacd(8), unwind(8), resolvd(8)
authorbluhm <bluhm@openbsd.org>
Tue, 9 Mar 2021 15:08:23 +0000 (15:08 +0000)
committerbluhm <bluhm@openbsd.org>
Tue, 9 Mar 2021 15:08:23 +0000 (15:08 +0000)
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
sys/kern/subr_log.c
sys/sys/malloc.h
usr.sbin/syslogd/syslogd.c

index 278a4f9..b1bd25a 100644 (file)
@@ -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 <bluhm@openbsd.org>
 .\" 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
index 1ff754a..26418a3 100644 (file)
@@ -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);
 }
index 7db0284..b556990 100644 (file)
@@ -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 */
        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 */ \
index 9b324a6..98c79c8 100644 (file)
@@ -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 <bluhm@genua.de>
@@ -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);