Kernel drops fewer messages in sendsyslog(2), adapt syslogd(8)

tests.  Kernel stashes logs temporarily, test it.  Fix some races
in existing tests.

13 files changed, 300 insertions, 15 deletions

diff --git a/regress/usr.sbin/syslogd/Client.pm b/regress/usr.sbin/syslogd/Client.pm
index 74fb839de73..de880329336 100644
--- a/regress/usr.sbin/syslogd/Client.pm
+++ b/regress/usr.sbin/syslogd/Client.pm
@@ -1,4 +1,4 @@
-#	$OpenBSD: Client.pm,v 1.14 2020/11/06 03:26:18 bluhm Exp $
+#	$OpenBSD: Client.pm,v 1.15 2021/03/09 15:16:28 bluhm Exp $
 
 # Copyright (c) 2010-2020 Alexander Bluhm <bluhm@openbsd.org>
 #
@@ -45,6 +45,12 @@ sub new {
 sub child {
 	my $self = shift;
 
+	if ($self->{early}) {
+		my @sudo = $ENV{SUDO} ? $ENV{SUDO} : "env";
+		my @flush = (@sudo, "./logflush");
+		system(@flush);
+	}
+
 	# TLS 1.3 writes multiple messages without acknowledgement.
 	# If the other side closes early, we want broken pipe error.
 	$SIG{PIPE} = 'IGNORE' if defined($self->{connectdomain}) &&
diff --git a/regress/usr.sbin/syslogd/LICENSE b/regress/usr.sbin/syslogd/LICENSE
index d4acc003a67..7de0873e44a 100644
--- a/regress/usr.sbin/syslogd/LICENSE
+++ b/regress/usr.sbin/syslogd/LICENSE
@@ -1,4 +1,4 @@
-Copyright (c) 2010-2020 Alexander Bluhm <bluhm@openbsd.org>
+Copyright (c) 2010-2021 Alexander Bluhm <bluhm@openbsd.org>
 
 Permission to use, copy, modify, and distribute this software for any
 purpose with or without fee is hereby granted, provided that the above
diff --git a/regress/usr.sbin/syslogd/Makefile b/regress/usr.sbin/syslogd/Makefile
index 05342ef44ea..eb59d8d813d 100644
--- a/regress/usr.sbin/syslogd/Makefile
+++ b/regress/usr.sbin/syslogd/Makefile
@@ -1,4 +1,4 @@
-#	$OpenBSD: Makefile,v 1.31 2020/12/17 00:51:13 bluhm Exp $
+#	$OpenBSD: Makefile,v 1.32 2021/03/09 15:16:28 bluhm Exp $
 
 # The following ports must be installed for the regression tests:
 # p5-IO-Socket-INET6	object interface for AF_INET and AF_INET6 domain sockets
@@ -27,7 +27,7 @@ regress:
 
 # Automatically generate regress targets from test cases in directory.
 
-PROGS =			ttylog
+PROGS =			ttylog logflush
 PERLS =			Client.pm Proc.pm RSyslogd.pm Server.pm \
 			Syslogc.pm   Syslogd.pm funcs.pl syslogd.pl
 ARGS !=			cd ${.CURDIR} && ls args-*.pl
@@ -144,7 +144,7 @@ ${REGRESS_TARGETS:M*empty*}: empty
 ${REGRESS_TARGETS:M*toobig*}: toobig
 ${REGRESS_TARGETS:M*fake*}: fake-ca.crt
 ${REGRESS_TARGETS:M*sendsyslog*}: sys/syscall.ph
-${REGRESS_TARGETS}: ttylog
+${REGRESS_TARGETS}: ttylog logflush
 
 # make perl syntax check for all args files
 
diff --git a/regress/usr.sbin/syslogd/Syslogd.pm b/regress/usr.sbin/syslogd/Syslogd.pm
index 101f5e5a2bb..e0823b7f5ef 100644
--- a/regress/usr.sbin/syslogd/Syslogd.pm
+++ b/regress/usr.sbin/syslogd/Syslogd.pm
@@ -1,4 +1,4 @@
-#	$OpenBSD: Syslogd.pm,v 1.25 2020/07/24 22:12:00 bluhm Exp $
+#	$OpenBSD: Syslogd.pm,v 1.26 2021/03/09 15:16:28 bluhm Exp $
 
 # Copyright (c) 2010-2020 Alexander Bluhm <bluhm@openbsd.org>
 # Copyright (c) 2014 Florian Riehm <mail@friehm.de>
@@ -184,6 +184,12 @@ sub child {
 	}
 	print STDERR "syslogd not running\n";
 
+	unless (${$self->{client}}->{early}) {
+		my @flush = (@sudo, "./logflush");
+		system(@flush)
+		    and die "Command '@flush' failed: $?";
+	}
+
 	chdir $self->{chdir}
 	    or die ref($self), " chdir '$self->{chdir}' failed: $!"
 	    if $self->{chdir};
diff --git a/regress/usr.sbin/syslogd/args-dropped-filesystem.pl b/regress/usr.sbin/syslogd/args-dropped-filesystem.pl
index ca487d4afff..bb244ded872 100644
--- a/regress/usr.sbin/syslogd/args-dropped-filesystem.pl
+++ b/regress/usr.sbin/syslogd/args-dropped-filesystem.pl
@@ -37,7 +37,7 @@ our %args = (
 		or die ref($self), " first log not in syslogd log";
 	    undef $!;
 	    for (my $i = 0; $i < 100000; $i++) {
-		syswrite($big, "regress syslogd file system full\n", 33)
+		syswrite($big, "regress syslogd file system full\n")
 		    or last;
 	    }
 	    $!{ENOSPC}
diff --git a/regress/usr.sbin/syslogd/args-dropped-sighup-filesystem.pl b/regress/usr.sbin/syslogd/args-dropped-sighup-filesystem.pl
index dd5fe098d1b..2a39b92b8d5 100644
--- a/regress/usr.sbin/syslogd/args-dropped-sighup-filesystem.pl
+++ b/regress/usr.sbin/syslogd/args-dropped-sighup-filesystem.pl
@@ -37,13 +37,14 @@ our %args = (
 		or die ref($self), " first log not in syslogd log";
 	    undef $!;
 	    for (my $i = 0; $i < 100000; $i++) {
-		syswrite($big, "regress syslogd file system full\n", 33)
+		syswrite($big, "regress syslogd file system full\n")
 		    or last;
 	    }
 	    $!{ENOSPC}
 		or die ref($self), " fill $fsbig failed: $!";
 	    # a single message still fits, write 4 KB logs to reach next block
 	    write_lines($self, 100, 70);
+	    write_lines($self, 9, 1);
 	    ${$self->{syslogd}}->loggrep(qr/write to file .* $errors/, 10)
 		or die ref($self), " write to file error not in syslogd log";
 	    close($big);
diff --git a/regress/usr.sbin/syslogd/args-dropped-sigterm-filesystem.pl b/regress/usr.sbin/syslogd/args-dropped-sigterm-filesystem.pl
index d2229c5b157..77cf0387f5f 100644
--- a/regress/usr.sbin/syslogd/args-dropped-sigterm-filesystem.pl
+++ b/regress/usr.sbin/syslogd/args-dropped-sigterm-filesystem.pl
@@ -37,13 +37,14 @@ our %args = (
 		or die ref($self), " first log not in syslogd log";
 	    undef $!;
 	    for (my $i = 0; $i < 100000; $i++) {
-		syswrite($big, "regress syslogd file system full\n", 33)
+		syswrite($big, "regress syslogd file system full\n")
 		    or last;
 	    }
 	    $!{ENOSPC}
 		or die ref($self), " fill $fsbig failed: $!";
 	    # a single message still fits, write 4 KB logs to reach next block
 	    write_lines($self, 100, 70);
+	    write_lines($self, 9, 1);
 	    ${$self->{syslogd}}->loggrep(qr/write to file .* $errors/, 10)
 		or die ref($self), " write to file error not in syslogd log";
 	    close($big);
diff --git a/regress/usr.sbin/syslogd/args-privsep.pl b/regress/usr.sbin/syslogd/args-privsep.pl
index a53fd476e6d..e2f047be735 100644
--- a/regress/usr.sbin/syslogd/args-privsep.pl
+++ b/regress/usr.sbin/syslogd/args-privsep.pl
@@ -18,7 +18,7 @@ our %args = (
 	nouser => 1,
 	loggrep => {
 	    qr/ -F / => 0,
-	    qr/ -d / => 1,
+	    qr/ -d / => '>=1',
 	    qr/\[priv\]: fork\+exec done/ => 1,
 	},
 	fstat => {
diff --git a/regress/usr.sbin/syslogd/args-sendsyslog-dropped.pl b/regress/usr.sbin/syslogd/args-sendsyslog-dropped.pl
index 40291e2ac9a..80af471a009 100644
--- a/regress/usr.sbin/syslogd/args-sendsyslog-dropped.pl
+++ b/regress/usr.sbin/syslogd/args-sendsyslog-dropped.pl
@@ -10,20 +10,25 @@ use strict;
 use warnings;
 use Errno ':POSIX';
 
+use constant LOGSTASH_SIZE => 100;
+
 my $errno = ENOTCONN;
 my $kerngrep = qr/sendsyslog: dropped \d+ messages?, error $errno, pid \d+$/;
 
 our %args = (
     client => {
 	early => 1,
-	func => sub { write_between2logs(shift, sub {
+	func => sub {
 	    my $self = shift;
-	    ${$self->{syslogd}}->loggrep(qr/syslogd: started/, 5)
-		or die ref($self), " syslogd started not in syslogd.log";
+	    write_message($self, "stash $_") foreach (1..LOGSTASH_SIZE);
+	    write_between2logs($self, sub {
+		my $self = shift;
+		${$self->{syslogd}}->loggrep(qr/syslogd: started/, 5)
+		    or die ref($self), " syslogd started not in syslogd.log";
 	})},
 	ktrace => {
-	    qr/CALL  sendsyslog\(/ => '>=2',
-	    qr/RET   sendsyslog -1 errno $errno / => '>=1',
+	    qr/CALL  sendsyslog\(/ => '>=103',
+	    qr/RET   sendsyslog -1 errno $errno / => 101,
 	},
     },
     syslogd => {
@@ -35,15 +40,19 @@ our %args = (
     },
     server => {
 	loggrep => {
+	    qr/syslogd\[\d+\]: start/ => 1,
 	    get_firstlog() => 0,
 	    $kerngrep => 1,
+	    qr/syslogd\[\d+\]: running/ => 1,
 	    get_testgrep() => 1,
 	},
     },
     file => {
 	loggrep => {
+	    qr/syslogd\[\d+\]: start/ => 1,
 	    get_firstlog() => 0,
 	    $kerngrep => 1,
+	    qr/syslogd\[\d+\]: running/ => 1,
 	    get_testgrep() => 1,
 	},
     },
diff --git a/regress/usr.sbin/syslogd/args-sendsyslog-fault.pl b/regress/usr.sbin/syslogd/args-sendsyslog-fault.pl
new file mode 100644
index 00000000000..6386ff2d173
--- /dev/null
+++ b/regress/usr.sbin/syslogd/args-sendsyslog-fault.pl
@@ -0,0 +1,59 @@
+# The client fails to use sendsyslog syscall due to bad address.
+# The client writes one message wiht sendsyslog.
+# The syslogd passes it via UDP to the loghost.
+# The server receives the message on its UDP socket.
+# Find the message in client, file, pipe, syslogd, server log.
+# Create a ktrace dump of the client and check that sendsyslog(2) failed.
+# Check that there is no kernel dropped message.
+
+use strict;
+use warnings;
+use Errno ':POSIX';
+require 'sys/syscall.ph';
+
+my $errno = EFAULT;
+$! = $errno;
+my $error = $!;
+my $kerngrep = qr/sendsyslog: dropped \d+ messages?/;
+
+our %args = (
+    client => {
+	connect => { domain => "sendsyslog" },
+	func => sub {
+	    my $self = shift;
+	    # bad system call, NULL pointer as message
+	    syscall(&SYS_sendsyslog, 0, 42, 0) != -1
+		or warn ref($self), " sendsyslog NULL failed: $!";
+	    write_log($self);
+	},
+	ktrace => {
+	    qr/CALL  sendsyslog\(/ => 3,
+	    qr/RET   sendsyslog -1 errno $errno / => 1,
+	},
+	loggrep => {
+	    get_firstlog() => 0,
+	    qr/Client sendsyslog NULL failed: $error/ => 1,
+	    get_testgrep() => 1,
+	},
+    },
+    syslogd => {
+	loggrep => {
+	    qr/msg $kerngrep/ => 0,
+	    get_testgrep() => 1,
+	},
+    },
+    server => {
+	loggrep => {
+	    $kerngrep => 0,
+	    get_testgrep() => 1,
+	},
+    },
+    file => {
+	loggrep => {
+	    $kerngrep => 0,
+	    get_testgrep() => 1,
+	},
+    },
+);
+
+1;
diff --git a/regress/usr.sbin/syslogd/args-sendsyslog-logstash.pl b/regress/usr.sbin/syslogd/args-sendsyslog-logstash.pl
new file mode 100644
index 00000000000..0f090ea813a
--- /dev/null
+++ b/regress/usr.sbin/syslogd/args-sendsyslog-logstash.pl
@@ -0,0 +1,66 @@
+# Run client before starting syslogd.
+# The client writes 101 messages to kernel log stash.
+# The client writes one message before and one after syslogd is started.
+# The kernel writes a sendsyslog(2) error message to the log socket.
+# Start syslogd, it reads the error and the second message from the log socket.
+# Find the kernel error message in file, syslogd, server log.
+# Check that the first message got lost.
+# Check that at least 80 messages were stashed in kernel.
+# Check that the 101th message was lost.
+
+use strict;
+use warnings;
+
+use constant LOGSTASH_SIZE => 100;
+
+our %args = (
+    client => {
+	early => 1,
+	func => sub {
+	    my $self = shift;
+	    write_message($self, "stash $_") foreach (0..LOGSTASH_SIZE);
+	    write_between2logs($self, sub {
+		my $self = shift;
+		${$self->{syslogd}}->loggrep(qr/syslogd: started/, 5)
+		    or die ref($self), " syslogd started not in syslogd.log";
+	})},
+    },
+    syslogd => {
+	loggrep => {
+	    qr/syslogd\[\d+\]: start/ => 1,
+	    get_firstlog() => 0,
+	    qr/syslogd-regress\[\d+\]: stash 0/ => 1,
+	    qr/syslogd-regress\[\d+\]: stash 80/ => 1,
+	    qr/syslogd-regress\[\d+\]: stash 100/ => 0,
+	    qr/sendsyslog: dropped \d+ messages?/ => 1,
+	    qr/syslogd\[\d+\]: running/ => 1,
+	    get_testgrep() => 1,
+	},
+    },
+    server => {
+	loggrep => {
+	    qr/syslogd\[\d+\]: start/ => 1,
+	    get_firstlog() => 0,
+	    qr/syslogd-regress\[\d+\]: stash 0/ => 1,
+	    qr/syslogd-regress\[\d+\]: stash 80/ => 1,
+	    qr/syslogd-regress\[\d+\]: stash 100/ => 0,
+	    qr/sendsyslog: dropped \d+ messages?/ => 1,
+	    qr/syslogd\[\d+\]: running/ => 1,
+	    get_testgrep() => 1,
+	},
+    },
+    file => {
+	loggrep => {
+	    qr/syslogd\[\d+\]: start/ => 1,
+	    get_firstlog() => 0,
+	    qr/syslogd-regress\[\d+\]: stash 0/ => 1,
+	    qr/syslogd-regress\[\d+\]: stash 80/ => 1,
+	    qr/syslogd-regress\[\d+\]: stash 100/ => 0,
+	    qr/sendsyslog: dropped \d+ messages?/ => 1,
+	    qr/syslogd\[\d+\]: running/ => 1,
+	    get_testgrep() => 1,
+	},
+    },
+);
+
+1;
diff --git a/regress/usr.sbin/syslogd/args-sendsyslog-nostash.pl b/regress/usr.sbin/syslogd/args-sendsyslog-nostash.pl
new file mode 100644
index 00000000000..c02c10ce8bc
--- /dev/null
+++ b/regress/usr.sbin/syslogd/args-sendsyslog-nostash.pl
@@ -0,0 +1,70 @@
+# Run client before starting syslogd.
+# The client tries to fill up the kernel stash with invalid messages.
+# The client writes one message before and one after syslogd is started.
+# Start syslogd, it reads the second message from the log socket.
+# Find the log message in file, syslogd, server log.
+# Check that the first message got lost.
+# Create a ktrace dump of the client and check that sendsyslog(2) has failed.
+# Check that kernel did not write sendsyslog(2) error message to log socket.
+
+use strict;
+use warnings;
+use Errno ':POSIX';
+require 'sys/syscall.ph';
+
+use constant LOGSTASH_SIZE => 100;
+
+my $errno = ENOTCONN;
+$! = $errno;
+my $error = $!;
+my $kerngrep = qr/sendsyslog: dropped \d+ messages?/;
+
+our %args = (
+    client => {
+	early => 1,
+	func => sub {
+	    my $self = shift;
+	    foreach (0..LOGSTASH_SIZE) {
+		# bad system call, NULL pointer as message
+		syscall(&SYS_sendsyslog, 0, 42, 0) != -1
+		    or warn ref($self), " sendsyslog NULL failed: $!";
+	    }
+	    write_between2logs($self, sub {
+		my $self = shift;
+		${$self->{syslogd}}->loggrep(qr/syslogd: started/, 5)
+		    or die ref($self), " syslogd started not in syslogd.log";
+	})},
+	ktrace => {
+	    qr/CALL  sendsyslog\(/ => '>=103',
+	    qr/RET   sendsyslog -1 errno $errno / => 102,
+	},
+	loggrep => {
+	    get_firstlog() => 1,
+	    qr/Client sendsyslog NULL failed: $error/ => 101,
+	    get_testgrep() => 1,
+	},
+    },
+    syslogd => {
+	loggrep => {
+	    get_firstlog() => 1,
+	    qr/msg $kerngrep/ => 0,
+	    get_testgrep() => 1,
+	},
+    },
+    server => {
+	loggrep => {
+	    get_firstlog() => 1,
+	    $kerngrep => 0,
+	    get_testgrep() => 1,
+	},
+    },
+    file => {
+	loggrep => {
+	    get_firstlog() => 1,
+	    $kerngrep => 0,
+	    get_testgrep() => 1,
+	},
+    },
+);
+
+1;
diff --git a/regress/usr.sbin/syslogd/logflush.c b/regress/usr.sbin/syslogd/logflush.c
new file mode 100644
index 00000000000..e4772eb171d
--- /dev/null
+++ b/regress/usr.sbin/syslogd/logflush.c
@@ -0,0 +1,67 @@
+/*	$OpenBSD: logflush.c,v 1.1 2021/03/09 15:16:28 bluhm Exp $	*/
+
+/*
+ * Copyright (c) 2021 Alexander Bluhm <bluhm@openbsd.org>
+ *
+ * Permission to use, copy, modify, and distribute this software for any
+ * purpose with or without fee is hereby granted, provided that the above
+ * copyright notice and this permission notice appear in all copies.
+ *
+ * THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES
+ * WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF
+ * MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR
+ * ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES
+ * WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN
+ * ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF
+ * OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE.
+ */
+
+#include <sys/ioctl.h>
+#include <sys/socket.h>
+
+#include <err.h>
+#include <fcntl.h>
+#include <paths.h>
+#include <stdarg.h>
+#include <stdio.h>
+#include <stdlib.h>
+#include <syslog.h>
+#include <unistd.h>
+
+__dead void
+usage()
+{
+	fprintf(stderr, "usage: %s\n", getprogname());
+	exit(2);
+}
+
+int
+main(int argc, char *argv[])
+{
+	int pair[2], klog, val;
+
+	if (argc != 1)
+		usage();
+
+	if (socketpair(AF_UNIX, SOCK_DGRAM, PF_UNSPEC, pair) == -1)
+		err(1, "socketpair");
+
+	val = 1<<20;
+	if (setsockopt(pair[0], SOL_SOCKET, SO_RCVBUF, &val, sizeof(val)) == -1)
+		err(1, "setsockopt SO_RCVBUF");
+	if (setsockopt(pair[1], SOL_SOCKET, SO_SNDBUF, &val, sizeof(val)) == -1)
+		err(1, "setsockopt SO_SNDBUF");
+
+	if ((klog = open(_PATH_KLOG, O_RDONLY, 0)) == -1)
+		err(1, "open %s", _PATH_KLOG);
+	/* Use /dev/klog to register sendsyslog(2) receiver. */
+	if (ioctl(klog, LIOCSFD, &pair[1]) == -1)
+		err(1, "ioctl klog LIOCSFD sendsyslog");
+	close(pair[1]);
+
+	/* Send message via libc, flushes log stash in kernel. */
+	openlog("syslogd-regress", LOG_PID, LOG_SYSLOG);
+	syslog(LOG_DEBUG, "logflush");
+
+	return 0;
+}