Skip to content

Commit

Permalink
Early daemons like dhcpleased(8), slaacd(8), unwind(8), resolvd(8)
Browse files Browse the repository at this point in the history
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@
  • Loading branch information
bluhm committed Mar 9, 2021
1 parent 143af18 commit 5fc6fc5
Show file tree
Hide file tree
Showing 4 changed files with 168 additions and 36 deletions.
10 changes: 6 additions & 4 deletions lib/libc/sys/sendsyslog.2
Original file line number Diff line number Diff line change
@@ -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 <[email protected]>
.\" Copyright (c) 2014 Theo de Raadt
Expand All @@ -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
Expand Down Expand Up @@ -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
Expand Down
182 changes: 154 additions & 28 deletions sys/kern/subr_log.c
Original file line number Diff line number Diff line change
@@ -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 $ */

/*
Expand Down Expand Up @@ -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)
{
Expand All @@ -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);
}

Expand All @@ -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)
Expand Down Expand Up @@ -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);
}
6 changes: 3 additions & 3 deletions sys/sys/malloc.h
Original file line number Diff line number Diff line change
@@ -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 $ */

/*
Expand Down Expand Up @@ -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 */
Expand Down Expand Up @@ -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 */ \
Expand Down
6 changes: 5 additions & 1 deletion usr.sbin/syslogd/syslogd.c
Original file line number Diff line number Diff line change
@@ -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 <[email protected]>
Expand Down Expand Up @@ -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);
Expand Down

0 comments on commit 5fc6fc5

Please sign in to comment.