> On 8 Mar 2021, at 23:20, Alexander Bluhm <alexander.bl...@gmx.net> wrote:
>
> I hope to have addressed all issues.
>
> On Sun, Mar 07, 2021 at 11:50:24AM +0000, Visa Hankala wrote:
>> This copyin() can also result in copying the buffer from userspace twice.
>> This might not be a problem with log data though.
>
> Is double copyin a problem? I think error != EFAULT should catch
> all cases.
>
> On Mon, Mar 08, 2021 at 01:37:51AM +0300, Vitaliy Makkoveev wrote:
>> I wonder they were not buffered. But does it make sense to drop the
>> most recent messages?
>
> The oldest message should be kept. In my experience you get most
> information why logging started to fail from the first message.
> After that there are subsequent errors.
I have the opposite experience, the most recent data (include errors) has
the most priority, but no problem with this.
>
> new diff, ok?
>
This silently drops message if copyin() fails. Could we count them as
`logstash_dropped’ too?
> 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 8 Mar 2021 19:55:52 -0000
> @@ -454,6 +454,149 @@ 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_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,
> 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
> 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
> #endif
> if (fp)
> FRELE(fp, p);
> - else
> + else if (error != EFAULT)
> error = ENOTCONN;
> return (error);
> }
> 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);
>
