From 64a2a974ff129f12827bed16cdae8961d5c9aa0f Mon Sep 17 00:00:00 2001 From: bluhm Date: Tue, 9 Mar 2021 15:16:28 +0000 Subject: [PATCH] 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 | 8 ++- regress/usr.sbin/syslogd/LICENSE | 2 +- regress/usr.sbin/syslogd/Makefile | 6 +- regress/usr.sbin/syslogd/Syslogd.pm | 8 ++- .../syslogd/args-dropped-filesystem.pl | 2 +- .../syslogd/args-dropped-sighup-filesystem.pl | 3 +- .../args-dropped-sigterm-filesystem.pl | 3 +- regress/usr.sbin/syslogd/args-privsep.pl | 2 +- .../syslogd/args-sendsyslog-dropped.pl | 19 +++-- .../usr.sbin/syslogd/args-sendsyslog-fault.pl | 59 ++++++++++++++++ .../syslogd/args-sendsyslog-logstash.pl | 66 +++++++++++++++++ .../syslogd/args-sendsyslog-nostash.pl | 70 +++++++++++++++++++ regress/usr.sbin/syslogd/logflush.c | 67 ++++++++++++++++++ 13 files changed, 300 insertions(+), 15 deletions(-) create mode 100644 regress/usr.sbin/syslogd/args-sendsyslog-fault.pl create mode 100644 regress/usr.sbin/syslogd/args-sendsyslog-logstash.pl create mode 100644 regress/usr.sbin/syslogd/args-sendsyslog-nostash.pl create mode 100644 regress/usr.sbin/syslogd/logflush.c 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 # @@ -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 +Copyright (c) 2010-2021 Alexander Bluhm 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 # Copyright (c) 2014 Florian Riehm @@ -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 + * + * 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 +#include + +#include +#include +#include +#include +#include +#include +#include +#include + +__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; +} -- 2.20.1