> On 7 Mar 2021, at 02:17, Alexander Bluhm <alexander.bl...@gmx.net> wrote:
>
> Hi
>
> Early daemons like dhcpleased, slaacd, unwind, resolvd are started
> before syslogd. This results in ugly sendsyslog: dropped 1 message
> logs and the real message is lost.
>
> Changing the start order of syslogd and and network daemons is not
> feasible. A possible solution is a temporary buffer for log meassges
> in kernel.
>
> ok?
>
I wonder they were not buffered. But does it make sense to drop the
most recent messages?
> bluhm
>
> Index: sys/kern/subr_log.c
> ===================================================================
> RCS file: /data/mirror/openbsd/cvs/src/sys/kern/subr_log.c,v
> retrieving revision 1.72
> diff -u -p -r1.72 subr_log.c
> --- sys/kern/subr_log.c 8 Feb 2021 08:18:45 -0000 1.72
> +++ sys/kern/subr_log.c 5 Mar 2021 21:58:50 -0000
> @@ -454,6 +454,146 @@ logioctl(dev_t dev, u_long com, caddr_t
> 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_messages {
> + char *lgs_buffer;
> + size_t lgs_size;
> +} logstash_messages[LOGSTASH_SIZE];
> +
> +struct logstash_messages *logstash_in = &logstash_messages[0];
> +struct logstash_messages *logstash_out = &logstash_messages[0];
> +
> +struct rwlock logstash_rwlock = RWLOCK_INITIALIZER("logstash");
> +
> +int logstash_dropped, logstash_error, logstash_pid;
> +
> +void logstash_insert(const char *, size_t, int, pid_t);
> +void logstash_remove(void);
> +int logstash_sendsyslog(struct proc *);
> +
> +static inline int
> +logstash_empty(void)
> +{
> + rw_assert_anylock(&logstash_rwlock);
> +
> + return logstash_out->lgs_buffer == NULL;
> +}
> +
> +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_messages **msg)
> +{
> + rw_assert_wrlock(&logstash_rwlock);
> +
> + KASSERT((*msg) >= &logstash_messages[0]);
> + KASSERT((*msg) < &logstash_messages[LOGSTASH_SIZE]);
> + (*msg)++;
> + if ((*msg) == &logstash_messages[LOGSTASH_SIZE])
> + (*msg) = &logstash_messages[0];
> +}
> +
> +void
> +logstash_insert(const char *buf, size_t nbyte, int error, pid_t pid)
> +{
> + rw_enter_write(&logstash_rwlock);
> +
> + if (logstash_full()) {
> + if (logstash_dropped == 0) {
> + logstash_error = error;
> + logstash_pid = pid;
> + }
> + logstash_dropped++;
> +
> + rw_exit(&logstash_rwlock);
> + return;
> + }
> +
> + logstash_in->lgs_buffer = malloc(nbyte, M_LOG, M_WAITOK);
> + copyin(buf, logstash_in->lgs_buffer, nbyte);
> + logstash_in->lgs_size = nbyte;
> + logstash_increment(&logstash_in);
> +
> + rw_exit(&logstash_rwlock);
> +}
> +
> +void
> +logstash_remove(void)
> +{
> + rw_assert_wrlock(&logstash_rwlock);
> +
> + KASSERT(!logstash_empty());
> + 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 +602,18 @@ sys_sendsyslog(struct proc *p, void *v,
> 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)
> + logstash_insert(SCARG(uap, buf), nbyte, error, p->p_p->ps_pid);
> return (error);
> }
>
> @@ -504,9 +630,6 @@ dosendsyslog(struct proc *p, const char
> struct uio auio;
> 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;
> Index: sys/sys/malloc.h
> ===================================================================
> RCS file: /data/mirror/openbsd/cvs/src/sys/sys/malloc.h,v
> retrieving revision 1.120
> diff -u -p -r1.120 malloc.h
> --- sys/sys/malloc.h 23 Feb 2021 13:50:16 -0000 1.120
> +++ sys/sys/malloc.h 4 Mar 2021 23:11:04 -0000
> @@ -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 */ \
> Index: lib/libc/sys/sendsyslog.2
> ===================================================================
> RCS file: /data/mirror/openbsd/cvs/src/lib/libc/sys/sendsyslog.2,v
> retrieving revision 1.12
> diff -u -p -r1.12 sendsyslog.2
> --- lib/libc/sys/sendsyslog.2 5 Nov 2020 16:04:39 -0000 1.12
> +++ lib/libc/sys/sendsyslog.2 5 Mar 2021 19:15:10 -0000
> @@ -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: usr.sbin/syslogd/syslogd.c
> ===================================================================
> RCS file: /data/mirror/openbsd/cvs/src/usr.sbin/syslogd/syslogd.c,v
> retrieving revision 1.264
> diff -u -p -r1.264 syslogd.c
> --- usr.sbin/syslogd/syslogd.c 14 Sep 2020 20:36:01 -0000 1.264
> +++ usr.sbin/syslogd/syslogd.c 6 Mar 2021 09:27:52 -0000
> @@ -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);
>
