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

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

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 <[email protected]>
 #
@@ -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}) &&

regress/usr.sbin/syslogd/LICENSE

@@ -1,4 +1,4 @@
-Copyright (c) 2010-2020 Alexander Bluhm <[email protected]>
+Copyright (c) 2010-2021 Alexander Bluhm <[email protected]>
 
 Permission to use, copy, modify, and distribute this software for any
 purpose with or without fee is hereby granted, provided that the above

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
 

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 <[email protected]>
 # Copyright (c) 2014 Florian Riehm <[email protected]>
@@ -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};

regress/usr.sbin/syslogd/args-dropped-filesystem.pl

@@ -37,7 +37,7 @@
 		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}

regress/usr.sbin/syslogd/args-dropped-sighup-filesystem.pl

@@ -37,13 +37,14 @@
 		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);

regress/usr.sbin/syslogd/args-dropped-sigterm-filesystem.pl

@@ -37,13 +37,14 @@
 		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);

regress/usr.sbin/syslogd/args-privsep.pl

@@ -18,7 +18,7 @@
 	nouser => 1,
 	loggrep => {
 	    qr/ -F / => 0,
-	    qr/ -d / => 1,
+	    qr/ -d / => '>=1',
 	    qr/\[priv\]: fork\+exec done/ => 1,
 	},
 	fstat => {

regress/usr.sbin/syslogd/args-sendsyslog-dropped.pl

@@ -10,20 +10,25 @@
 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 @@
     },
     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,
 	},
     },

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;

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;

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;