Change syslog tests from transparent framing to octet counting.

Add tests for truncated buffer handling.

14 files changed, 206 insertions, 57 deletions

diff --git a/regress/usr.sbin/syslogd/args-dropped-sighup-tcp.pl b/regress/usr.sbin/syslogd/args-dropped-sighup-tcp.pl
index 8a432eed763..ec5c322b642 100644
--- a/regress/usr.sbin/syslogd/args-dropped-sighup-tcp.pl
+++ b/regress/usr.sbin/syslogd/args-dropped-sighup-tcp.pl
@@ -18,11 +18,7 @@ our %args = (
 	func => sub { write_between2logs(shift, sub {
 	    my $self = shift;
 	    write_message($self, get_secondlog());
-	    foreach (1..300) {
-		write_char($self, [1024], $_);
-		# if client sends too fast, syslogd will not see everything
-		sleep .01;
-	    }
+	    write_lines($self, 300, 1024);
 	    write_message($self, get_thirdlog());
 	    ${$self->{server}}->loggrep(get_secondlog(), 8)
 		or die ref($self), " server did not receive second log";
@@ -33,6 +29,7 @@ our %args = (
 	loggrep => {
 	    get_between2loggrep(),
 	    get_charlog() => 300,
+	    qr/ \(dropped\)/ => 14,
 	},
     },
     server => {
diff --git a/regress/usr.sbin/syslogd/args-dropped-sighup-tls.pl b/regress/usr.sbin/syslogd/args-dropped-sighup-tls.pl
index cc0af507754..01dffb640ef 100644
--- a/regress/usr.sbin/syslogd/args-dropped-sighup-tls.pl
+++ b/regress/usr.sbin/syslogd/args-dropped-sighup-tls.pl
@@ -18,11 +18,7 @@ our %args = (
 	func => sub { write_between2logs(shift, sub {
 	    my $self = shift;
 	    write_message($self, get_secondlog());
-	    foreach (1..300) {
-		write_char($self, [1024], $_);
-		# if client sends too fast, syslogd will not see everything
-		sleep .01;
-	    }
+	    write_lines($self, 300, 1024);
 	    write_message($self, get_thirdlog());
 	    ${$self->{server}}->loggrep(get_secondlog(), 8)
 		or die ref($self), " server did not receive second log";
@@ -33,6 +29,7 @@ our %args = (
 	loggrep => {
 	    get_between2loggrep(),
 	    get_charlog() => 300,
+	    qr/ \(dropped\)/ => 16,
 	},
     },
     server => {
@@ -59,8 +56,8 @@ our %args = (
 	    get_thirdlog() => 0,
 	    qr/syslogd: start/ => 1,
 	    qr/syslogd: restart/ => 1,
-	    get_charlog() => 42,
-	    qr/syslogd: dropped 260 messages to remote loghost/ => 1,
+	    get_charlog() => 41,
+	    qr/syslogd: dropped 261 messages to remote loghost/ => 1,
 	},
     },
     file => {
@@ -71,7 +68,7 @@ our %args = (
 	    qr/syslogd: start/ => 1,
 	    qr/syslogd: restart/ => 1,
 	    get_charlog() => 300,
-	    qr/syslogd: dropped 260 messages to remote loghost/ => 1,
+	    qr/syslogd: dropped 261 messages to remote loghost/ => 1,
 	},
     },
 );
diff --git a/regress/usr.sbin/syslogd/args-dropped-sigterm-tcp.pl b/regress/usr.sbin/syslogd/args-dropped-sigterm-tcp.pl
index 82a1201ef71..db269ca3ee9 100644
--- a/regress/usr.sbin/syslogd/args-dropped-sigterm-tcp.pl
+++ b/regress/usr.sbin/syslogd/args-dropped-sigterm-tcp.pl
@@ -18,11 +18,7 @@ our %args = (
 	func => sub { write_between2logs(shift, sub {
 	    my $self = shift;
 	    write_message($self, get_secondlog());
-	    foreach (1..300) {
-		write_char($self, [1024], $_);
-		# if client sends too fast, syslogd will not see everything
-		sleep .01;
-	    }
+	    write_lines($self, 300, 1024);
 	    write_message($self, get_thirdlog());
 	    ${$self->{server}}->loggrep(get_secondlog(), 8)
 		or die ref($self), " server did not receive second log";
@@ -32,6 +28,7 @@ our %args = (
 	loghost => '@tcp://localhost:$connectport',
 	loggrep => {
 	    get_charlog() => 300,
+	    qr/ \(dropped\)/ => 17,
 	},
     },
     server => {
@@ -53,7 +50,7 @@ our %args = (
 	    get_thirdlog() => 0,
 	    get_testlog() => 0,
 	    qr/syslogd: start/ => 1,
-	    get_charlog() => 43,
+	    get_charlog() => 42,
 	},
     },
     pipe => {
@@ -67,7 +64,7 @@ our %args = (
 	    get_testlog() => 0,
 	    qr/syslogd: start/ => 1,
 	    get_charlog() => 300,
-	    qr/syslogd: dropped 259 messages to remote loghost/ => 1,
+	    qr/syslogd: dropped 260 messages to remote loghost/ => 1,
 	},
     },
 );
diff --git a/regress/usr.sbin/syslogd/args-dropped-sigterm-tls.pl b/regress/usr.sbin/syslogd/args-dropped-sigterm-tls.pl
index f5b9b9961f4..c84549844bb 100644
--- a/regress/usr.sbin/syslogd/args-dropped-sigterm-tls.pl
+++ b/regress/usr.sbin/syslogd/args-dropped-sigterm-tls.pl
@@ -18,11 +18,7 @@ our %args = (
 	func => sub { write_between2logs(shift, sub {
 	    my $self = shift;
 	    write_message($self, get_secondlog());
-	    foreach (1..300) {
-		write_char($self, [1024], $_);
-		# if client sends too fast, syslogd will not see everything
-		sleep .01;
-	    }
+	    write_lines($self, 300, 1024);
 	    write_message($self, get_thirdlog());
 	    ${$self->{server}}->loggrep(get_secondlog(), 8)
 		or die ref($self), " server did not receive second log";
@@ -32,6 +28,7 @@ our %args = (
 	loghost => '@tls://localhost:$connectport',
 	loggrep => {
 	    get_charlog() => 300,
+	    qr/ \(dropped\)/ => 19,
 	},
     },
     server => {
@@ -53,7 +50,7 @@ our %args = (
 	    get_thirdlog() => 0,
 	    get_testlog() => 0,
 	    qr/syslogd: start/ => 1,
-	    get_charlog() => 42,
+	    get_charlog() => 40,
 	},
     },
     pipe => {
@@ -67,7 +64,7 @@ our %args = (
 	    get_testlog() => 0,
 	    qr/syslogd: start/ => 1,
 	    get_charlog() => 300,
-	    qr/syslogd: dropped 260 messages to remote loghost/ => 1,
+	    qr/syslogd: dropped 262 messages to remote loghost/ => 1,
 	},
     },
 );
diff --git a/regress/usr.sbin/syslogd/args-dropped-tcp.pl b/regress/usr.sbin/syslogd/args-dropped-tcp.pl
index dcf69a9797b..7770c5444b5 100644
--- a/regress/usr.sbin/syslogd/args-dropped-tcp.pl
+++ b/regress/usr.sbin/syslogd/args-dropped-tcp.pl
@@ -18,11 +18,7 @@ our %args = (
 	func => sub { write_between2logs(shift, sub {
 	    my $self = shift;
 	    write_message($self, get_secondlog());
-	    foreach (1..300) {
-		write_char($self, [1024], $_);
-		# if client sends too fast, syslogd will not see everything
-		sleep .01;
-	    }
+	    write_lines($self, 300, 1024);
 	    write_message($self, get_thirdlog());
 	    ${$self->{server}}->loggrep(get_secondlog(), 5)
 		or die ref($self), " server did not receive second log";
@@ -33,6 +29,7 @@ our %args = (
 	loggrep => {
 	    get_between2loggrep(),
 	    get_charlog() => 300,
+	    qr/ \(dropped\)/ => 14,
 	},
     },
     server => {
@@ -47,8 +44,8 @@ our %args = (
 	    get_between2loggrep(),
 	    get_secondlog() => 1,
 	    get_thirdlog() => 0,
-	    get_charlog() => 289,
-	    qr/syslogd: dropped 12 messages to loghost "\@tcp:.*"/ => 1,
+	    get_charlog() => 287,
+	    qr/syslogd: dropped 14 messages to loghost "\@tcp:.*"/ => 1,
 	},
     },
     file => {
@@ -57,7 +54,7 @@ our %args = (
 	    get_secondlog() => 1,
 	    get_thirdlog() => 1,
 	    get_charlog() => 300,
-	    qr/syslogd: dropped 12 messages to loghost "\@tcp:.*"/ => 1,
+	    qr/syslogd: dropped 14 messages to loghost "\@tcp:.*"/ => 1,
 	},
     },
 );
diff --git a/regress/usr.sbin/syslogd/args-dropped-tls.pl b/regress/usr.sbin/syslogd/args-dropped-tls.pl
index bc1cf36dd61..eff8d80218e 100644
--- a/regress/usr.sbin/syslogd/args-dropped-tls.pl
+++ b/regress/usr.sbin/syslogd/args-dropped-tls.pl
@@ -18,11 +18,7 @@ our %args = (
 	func => sub { write_between2logs(shift, sub {
 	    my $self = shift;
 	    write_message($self, get_secondlog());
-	    foreach (1..300) {
-		write_char($self, [1024], $_);
-		# if client sends too fast, syslogd will not see everything
-		sleep .01;
-	    }
+	    write_lines($self, 300, 1024);
 	    write_message($self, get_thirdlog());
 	    ${$self->{server}}->loggrep(get_secondlog(), 5)
 		or die ref($self), " server did not receive second log";
@@ -33,6 +29,7 @@ our %args = (
 	loggrep => {
 	    get_between2loggrep(),
 	    get_charlog() => 300,
+	    qr/ \(dropped\)/ => 16,
 	},
     },
     server => {
@@ -47,8 +44,8 @@ our %args = (
 	    get_between2loggrep(),
 	    get_secondlog() => 1,
 	    get_thirdlog() => 0,
-	    get_charlog() => 288,
-	    qr/syslogd: dropped 13 messages to loghost "\@tls:.*"/ => 1,
+	    get_charlog() => 285,
+	    qr/syslogd: dropped 16 messages to loghost "\@tls:.*"/ => 1,
 	},
     },
     file => {
@@ -57,7 +54,7 @@ our %args = (
 	    get_secondlog() => 1,
 	    get_thirdlog() => 1,
 	    get_charlog() => 300,
-	    qr/syslogd: dropped 13 messages to loghost "\@tls:.*"/ => 1,
+	    qr/syslogd: dropped 16 messages to loghost "\@tls:.*"/ => 1,
 	},
     },
 );
diff --git a/regress/usr.sbin/syslogd/args-length-tcp.pl b/regress/usr.sbin/syslogd/args-length-tcp.pl
index 172aa7ab069..ef937ecf5b6 100644
--- a/regress/usr.sbin/syslogd/args-length-tcp.pl
+++ b/regress/usr.sbin/syslogd/args-length-tcp.pl
@@ -24,12 +24,12 @@ our %args = (
     },
     server => {
 	listen => { domain => AF_UNSPEC, proto => "tcp", addr => "localhost" },
-	# >>> <13>Jan 31 00:10:11 0123456789ABC...567
+	# >>> 8213 <13>Jan 31 00:10:11 0123456789ABC...567\n
 	loggrep => {
 	    get_charlog() => 5,
-	    qr/^>>> .{19} .{8190}$/ => 1,
-	    qr/^>>> .{19} .{8191}$/ => 1,
-	    qr/^>>> .{19} .{8192}$/ => 3,
+	    qr/^>>> 8211 .{19} .{8190}$/ => 1,
+	    qr/^>>> 8212 .{19} .{8191}$/ => 1,
+	    qr/^>>> 8213 .{19} .{8192}$/ => 3,
 	},
     },
 );
diff --git a/regress/usr.sbin/syslogd/args-length-tls.pl b/regress/usr.sbin/syslogd/args-length-tls.pl
index e79d808c429..1ce9501e5c9 100644
--- a/regress/usr.sbin/syslogd/args-length-tls.pl
+++ b/regress/usr.sbin/syslogd/args-length-tls.pl
@@ -24,12 +24,12 @@ our %args = (
     },
     server => {
 	listen => { domain => AF_UNSPEC, proto => "tls", addr => "localhost" },
-	# >>> <13>Jan 31 00:10:11 0123456789ABC...567
+	# >>> 8213 <13>Jan 31 00:10:11 0123456789ABC...567\n
 	loggrep => {
 	    get_charlog() => 5,
-	    qr/^>>> .{19} .{8190}$/ => 1,
-	    qr/^>>> .{19} .{8191}$/ => 1,
-	    qr/^>>> .{19} .{8192}$/ => 3,
+	    qr/^>>> 8211 .{19} .{8190}$/ => 1,
+	    qr/^>>> 8212 .{19} .{8191}$/ => 1,
+	    qr/^>>> 8213 .{19} .{8192}$/ => 3,
 	},
     },
 );
diff --git a/regress/usr.sbin/syslogd/args-rsyslog-tcp.pl b/regress/usr.sbin/syslogd/args-rsyslog-tcp.pl
index 499695d1754..e29b1b85961 100644
--- a/regress/usr.sbin/syslogd/args-rsyslog-tcp.pl
+++ b/regress/usr.sbin/syslogd/args-rsyslog-tcp.pl
@@ -16,6 +16,10 @@ our %args = (
     },
     rsyslogd => {
 	listen => { proto => "tcp" },
+	loggrep => {
+	    get_testlog() => 1,
+	    qr/Error/ => 0,
+	},
     },
 );
 
diff --git a/regress/usr.sbin/syslogd/args-rsyslog-tls.pl b/regress/usr.sbin/syslogd/args-rsyslog-tls.pl
index bb2d2e9749c..aa4c70a2bc4 100644
--- a/regress/usr.sbin/syslogd/args-rsyslog-tls.pl
+++ b/regress/usr.sbin/syslogd/args-rsyslog-tls.pl
@@ -16,6 +16,10 @@ our %args = (
     },
     rsyslogd => {
 	listen => { proto => "tls" },
+	loggrep => {
+	    get_testlog() => 1,
+	    qr/Error/ => 0,
+	},
     },
 );
 
diff --git a/regress/usr.sbin/syslogd/args-rsyslog-udp.pl b/regress/usr.sbin/syslogd/args-rsyslog-udp.pl
index 5d087ec90cf..08491aecd04 100644
--- a/regress/usr.sbin/syslogd/args-rsyslog-udp.pl
+++ b/regress/usr.sbin/syslogd/args-rsyslog-udp.pl
@@ -10,7 +10,12 @@ use strict;
 use warnings;
 
 our %args = (
-    rsyslogd => {},
+    rsyslogd => {
+	loggrep => {
+	    get_testlog() => 2,
+	    qr/Error/ => 0,
+	},
+    },
 );
 
 1;
diff --git a/regress/usr.sbin/syslogd/args-sync-tcp.pl b/regress/usr.sbin/syslogd/args-sync-tcp.pl
new file mode 100644
index 00000000000..633a2b0d46c
--- /dev/null
+++ b/regress/usr.sbin/syslogd/args-sync-tcp.pl
@@ -0,0 +1,71 @@
+# The client writes 300 long messages to UDP socket.
+# The syslogd writes it into a file and through a pipe.
+# The syslogd does a TCP reconnect and passes it to loghost.
+# The server blocks the message on its TCP socket.
+# The server waits until the client has written all messages.
+# The server closes the TCP connection and accepts a new one.
+# The server receives the messages on its new accepted TCP socket.
+# This way the server receives a block of messages that is truncated
+# at the beginning and at the end.
+# Find the message in client, file, pipe, syslogd, server log.
+# Check that the server does not get lines that are cut in the middle.
+
+use strict;
+use warnings;
+use Socket;
+
+our %args = (
+    client => {
+	connect => { domain => AF_UNSPEC, addr => "localhost", port => 514 },
+	func => sub { write_between2logs(shift, sub {
+	    my $self = shift;
+	    write_message($self, get_secondlog());
+	    write_lines($self, 300, 3000);
+	    write_message($self, get_thirdlog());
+	    ${$self->{server}}->loggrep("Accepted", 5, 2)
+		or die ref($self), " server did not receive second log";
+	})},
+    },
+    syslogd => {
+	options => ["-u"],
+	loghost => '@tcp://127.0.0.1:$connectport',
+	loggrep => {
+	    get_between2loggrep(),
+	    get_charlog() => 300,
+	    qr/dropped partial message/ => 1,
+	},
+    },
+    server => {
+	listen => { domain => AF_INET, proto => "tcp", addr => "127.0.0.1" },
+	redo => 0,
+	func => sub { read_between2logs(shift, sub {
+	    my $self = shift;
+	    if ($self->{redo}) {
+		$self->{redo}--;
+		return;
+	    }
+	    ${$self->{client}}->loggrep(get_thirdlog(), 5)
+		or die ref($self), " client did not send third log";
+	    shutdown(\*STDOUT, 1)
+		or die "shutdown write failed: $!";
+	    $self->{redo}++;
+	})},
+	loggrep => {
+	    qr/Accepted/ => 2,
+	    get_between2loggrep(),
+	    get_secondlog() => 0,
+	    get_thirdlog() => 0,
+	    qr/>>> [0-9A-Za-z]{10}/ => 0,
+	},
+    },
+    file => {
+	loggrep => {
+	    get_between2loggrep(),
+	    get_secondlog() => 1,
+	    get_thirdlog() => 1,
+	    get_charlog() => 300,
+	},
+    },
+);
+
+1;
diff --git a/regress/usr.sbin/syslogd/args-sync-tls.pl b/regress/usr.sbin/syslogd/args-sync-tls.pl
new file mode 100644
index 00000000000..72a8656439d
--- /dev/null
+++ b/regress/usr.sbin/syslogd/args-sync-tls.pl
@@ -0,0 +1,71 @@
+# The client writes 300 long messages to UDP socket.
+# The syslogd writes it into a file and through a pipe.
+# The syslogd does a TLS reconnect and passes it to loghost.
+# The server blocks the message on its TLS socket.
+# The server waits until the client has written all messages.
+# The server closes the TLS connection and accepts a new one.
+# The server receives the messages on its new accepted TLS socket.
+# This way the server receives a block of messages that is truncated
+# at the beginning and at the end.
+# Find the message in client, file, pipe, syslogd, server log.
+# Check that the server does not get lines that are cut in the middle.
+
+use strict;
+use warnings;
+use Socket;
+
+our %args = (
+    client => {
+	connect => { domain => AF_UNSPEC, addr => "localhost", port => 514 },
+	func => sub { write_between2logs(shift, sub {
+	    my $self = shift;
+	    write_message($self, get_secondlog());
+	    write_lines($self, 300, 3000);
+	    write_message($self, get_thirdlog());
+	    ${$self->{server}}->loggrep("Accepted", 5, 2)
+		or die ref($self), " server did not receive second log";
+	})},
+    },
+    syslogd => {
+	options => ["-u"],
+	loghost => '@tls://127.0.0.1:$connectport',
+	loggrep => {
+	    get_between2loggrep(),
+	    get_charlog() => 300,
+	    qr/dropped partial message/ => 1,
+	},
+    },
+    server => {
+	listen => { domain => AF_INET, proto => "tls", addr => "127.0.0.1" },
+	redo => 0,
+	func => sub { read_between2logs(shift, sub {
+	    my $self = shift;
+	    if ($self->{redo}) {
+		$self->{redo}--;
+		return;
+	    }
+	    ${$self->{client}}->loggrep(get_thirdlog(), 5)
+		or die ref($self), " client did not send third log";
+	    shutdown(\*STDOUT, 1)
+		or die "shutdown write failed: $!";
+	    $self->{redo}++;
+	})},
+	loggrep => {
+	    qr/Accepted/ => 2,
+	    get_between2loggrep(),
+	    get_secondlog() => 0,
+	    get_thirdlog() => 0,
+	    qr/>>> [0-9A-Za-z]{10}/ => 0,
+	},
+    },
+    file => {
+	loggrep => {
+	    get_between2loggrep(),
+	    get_secondlog() => 1,
+	    get_thirdlog() => 1,
+	    get_charlog() => 300,
+	},
+    },
+);
+
+1;
diff --git a/regress/usr.sbin/syslogd/funcs.pl b/regress/usr.sbin/syslogd/funcs.pl
index 9bbaea9299e..2e0dbd12d9d 100644
--- a/regress/usr.sbin/syslogd/funcs.pl
+++ b/regress/usr.sbin/syslogd/funcs.pl
@@ -1,4 +1,4 @@
-#	$OpenBSD: funcs.pl,v 1.14 2015/02/06 00:27:41 bluhm Exp $
+#	$OpenBSD: funcs.pl,v 1.15 2015/02/08 15:24:14 bluhm Exp $
 
 # Copyright (c) 2010-2015 Alexander Bluhm <bluhm@openbsd.org>
 #
@@ -104,9 +104,20 @@ sub write_shutdown {
 	syslog(LOG_NOTICE, $downlog);
 }
 
-sub write_char {
+sub write_lines {
 	my $self = shift;
-	my @lenghts = @{shift || $self->{lengths}};
+	my ($lines, $lenght) = @_;
+
+	foreach (1..$lines) {
+		write_chars($self, $lenght, " $_");
+		# if client is sending too fast, syslogd will not see everything
+		sleep .01;
+	}
+}
+
+sub write_chars {
+	my $self = shift;
+	my @lenghts = shift || @{$self->{lengths}};
 	my $tail = shift // $self->{tail};
 
 	foreach my $len (@lenghts) {
@@ -131,7 +142,7 @@ sub write_char {
 
 sub write_length {
 	my $self = shift;
-	write_char($self, @_);
+	write_chars($self, @_);
 	write_log($self);
 }
 
@@ -214,7 +225,8 @@ sub get_thirdlog {
 }
 
 sub get_charlog {
-	return $charlog;
+	# add a space so that we match at the beginning of the message
+	return " $charlog";
 }
 
 sub get_between2loggrep {