Log test debugging for all ssh/sshd processes.

Makefile.in

@@ -517,6 +517,10 @@ regress/modpipe$(EXEEXT): $(srcdir)/regress/modpipe.c $(REGRESSLIBS)
 	$(CC) $(CFLAGS) $(CPPFLAGS) -o $@ $(srcdir)/regress/modpipe.c \
 	$(LDFLAGS) -lssh -lopenbsd-compat -lssh -lopenbsd-compat $(TESTLIBS)
 
+regress/timestamp$(EXEEXT): $(srcdir)/regress/timestamp.c $(REGRESSLIBS)
+	$(CC) $(CFLAGS) $(CPPFLAGS) -o $@ $(srcdir)/regress/timestamp.c \
+	$(LDFLAGS) -lssh -lopenbsd-compat -lssh -lopenbsd-compat $(TESTLIBS)
+
 regress/setuid-allowed$(EXEEXT): $(srcdir)/regress/setuid-allowed.c $(REGRESSLIBS)
 	$(CC) $(CFLAGS) $(CPPFLAGS) -o $@ $(srcdir)/regress/setuid-allowed.c \
 	$(LDFLAGS) -lssh -lopenbsd-compat -lssh -lopenbsd-compat $(TESTLIBS)
@@ -690,6 +694,7 @@ regress/misc/sk-dummy/sk-dummy.so: $(SK_DUMMY_OBJS)
 
 regress-binaries: regress-prep $(LIBCOMPAT) \
 	regress/modpipe$(EXEEXT) \
+	regress/timestamp$(EXEEXT) \
 	regress/setuid-allowed$(EXEEXT) \
 	regress/netcat$(EXEEXT) \
 	regress/check-perm$(EXEEXT) \

regress/agent-restrict.sh

@@ -39,14 +39,14 @@ Host host_$h
 	Hostname host_$h
 	HostkeyAlias host_$h
 	IdentityFile $OBJ/user_$h
-	ProxyCommand ${SUDO} env SSH_SK_HELPER=\"$SSH_SK_HELPER\" sh ${SRC}/sshd-log-wrapper.sh ${TEST_SSHD_LOGFILE} ${SSHD} -i -f $OBJ/sshd_proxy_host_$h
+	ProxyCommand ${SUDO} env SSH_SK_HELPER=\"$SSH_SK_HELPER\" ${OBJ}/sshd-log-wrapper.sh -i -f $OBJ/sshd_proxy_host_$h
 _EOF
 	# Variant with no specified keys.
 	cat << _EOF >> $OBJ/ssh_proxy_noid
 Host host_$h
 	Hostname host_$h
 	HostkeyAlias host_$h
-	ProxyCommand ${SUDO} env SSH_SK_HELPER=\"$SSH_SK_HELPER\" sh ${SRC}/sshd-log-wrapper.sh ${TEST_SSHD_LOGFILE} ${SSHD} -i -f $OBJ/sshd_proxy_host_$h
+	ProxyCommand ${SUDO} env SSH_SK_HELPER=\"$SSH_SK_HELPER\" ${OBJ}/sshd-log-wrapper.sh -i -f $OBJ/sshd_proxy_host_$h
 _EOF
 done
 cat $OBJ/ssh_proxy.bak >> $OBJ/ssh_proxy

regress/dhgex.sh

@@ -3,8 +3,6 @@
 
 tid="dhgex"
 
-LOG=${TEST_SSH_LOGFILE}
-rm -f ${LOG}
 cp $OBJ/sshd_proxy $OBJ/sshd_proxy_bak
 
 kexs=`${SSH} -Q kex | grep diffie-hellman-group-exchange`
@@ -18,7 +16,6 @@ ssh_test_dhgex()
 	cp $OBJ/sshd_proxy_bak $OBJ/sshd_proxy
 	echo "KexAlgorithms=$kex" >> $OBJ/sshd_proxy
 	echo "Ciphers=$cipher" >> $OBJ/sshd_proxy
-	rm -f ${LOG}
 	opts="-oKexAlgorithms=$kex -oCiphers=$cipher"
 	min=2048
 	max=8192
@@ -28,6 +25,7 @@ ssh_test_dhgex()
 	if [ $? -ne 0 ]; then
 		fail "ssh failed ($@)"
 	fi
+	LOG=`ssh_logfile`
 	# check what we request
 	grep "SSH2_MSG_KEX_DH_GEX_REQUEST($groupsz) sent" ${LOG} >/dev/null
 	if [ $? != 0 ]; then

regress/integrity.sh

@@ -18,7 +18,7 @@ macs="$macs `${SSH} -Q cipher-auth`"
 #	>> $OBJ/ssh_proxy
 
 # sshd-command for proxy (see test-exec.sh)
-cmd="$SUDO env SSH_SK_HELPER="$SSH_SK_HELPER" sh ${SRC}/sshd-log-wrapper.sh ${TEST_SSHD_LOGFILE} ${SSHD} -i -f $OBJ/sshd_proxy"
+cmd="$SUDO env SSH_SK_HELPER="$SSH_SK_HELPER" sh ${OBJ}/sshd-log-wrapper.sh -i -f $OBJ/sshd_proxy"
 
 for m in $macs; do
 	trace "test $tid: mac $m"
@@ -53,7 +53,7 @@ for m in $macs; do
 			fail "ssh -m $m succeeds with bit-flip at $off"
 		fi
 		ecnt=`expr $ecnt + 1`
-		out=$(egrep -v "^debug" $TEST_SSH_LOGFILE | tail -2 | \
+		out=$(egrep -v "^debug" $(ssh_logfile) | tail -2 | \
 		     tr -s '\r\n' '.')
 		case "$out" in
 		Bad?packet*)	elen=`expr $elen + 1`; skip=3;;

regress/rekey.sh

@@ -3,9 +3,6 @@
 
 tid="rekey"
 
-LOG=${TEST_SSH_LOGFILE}
-
-rm -f ${LOG}
 cp $OBJ/sshd_proxy $OBJ/sshd_proxy_bak
 
 # Test rekeying based on data volume only.
@@ -19,13 +16,14 @@ ssh_data_rekeying()
 		echo "$_kexopt" >> $OBJ/sshd_proxy
 		_opts="$_opts -o$_kexopt"
 	fi
-	rm -f ${COPY} ${LOG}
+	rm -f ${COPY}
 	_opts="$_opts -oCompression=no"
 	${SSH} <${DATA} $_opts -v -F $OBJ/ssh_proxy somehost "cat > ${COPY}"
 	if [ $? -ne 0 ]; then
 		fail "ssh failed ($@)"
 	fi
 	cmp ${DATA} ${COPY}		|| fail "corrupted copy ($@)"
+	LOG=`ssh_logfile`
 	n=`grep 'NEWKEYS sent' ${LOG} | wc -l`
 	n=`expr $n - 1`
 	trace "$n rekeying(s)"
@@ -69,14 +67,15 @@ done
 
 for s in 5 10; do
 	verbose "client rekeylimit default ${s}"
-	rm -f ${COPY} ${LOG}
+	rm -f ${COPY}
 	${SSH} < ${DATA} -oCompression=no -oRekeyLimit="default $s" -F \
 		$OBJ/ssh_proxy somehost "cat >${COPY};sleep $s;sleep 10"
 	if [ $? -ne 0 ]; then
 		fail "ssh failed"
 	fi
 	cmp ${DATA} ${COPY}		|| fail "corrupted copy"
-	n=`grep 'NEWKEYS sent' ${LOG} | wc -l`
+	LOG=`ssh_logfile`
+	n=`grep 'NEWKEYS sent' ${LOG}) | wc -l`
 	n=`expr $n - 1`
 	trace "$n rekeying(s)"
 	if [ $n -lt 1 ]; then
@@ -86,12 +85,13 @@ done
 
 for s in 5 10; do
 	verbose "client rekeylimit default ${s} no data"
-	rm -f ${COPY} ${LOG}
+	rm -f ${COPY}
 	${SSH} -oCompression=no -oRekeyLimit="default $s" -F \
 		$OBJ/ssh_proxy somehost "sleep $s;sleep 10"
 	if [ $? -ne 0 ]; then
 		fail "ssh failed"
 	fi
+	LOG=`ssh_logfile`
 	n=`grep 'NEWKEYS sent' ${LOG} | wc -l`
 	n=`expr $n - 1`
 	trace "$n rekeying(s)"
@@ -104,13 +104,14 @@ for s in 16 1k 128k 256k; do
 	verbose "server rekeylimit ${s}"
 	cp $OBJ/sshd_proxy_bak $OBJ/sshd_proxy
 	echo "rekeylimit ${s}" >>$OBJ/sshd_proxy
-	rm -f ${COPY} ${LOG}
+	rm -f ${COPY}
 	${SSH} -oCompression=no -F $OBJ/ssh_proxy somehost "cat ${DATA}" \
 	    > ${COPY}
 	if [ $? -ne 0 ]; then
 		fail "ssh failed"
 	fi
 	cmp ${DATA} ${COPY}		|| fail "corrupted copy"
+	LOG=`ssh_logfile`
 	n=`grep 'NEWKEYS sent' ${LOG} | wc -l`
 	n=`expr $n - 1`
 	trace "$n rekeying(s)"
@@ -123,11 +124,12 @@ for s in 5 10; do
 	verbose "server rekeylimit default ${s} no data"
 	cp $OBJ/sshd_proxy_bak $OBJ/sshd_proxy
 	echo "rekeylimit default ${s}" >>$OBJ/sshd_proxy
-	rm -f ${COPY} ${LOG}
+	rm -f ${COPY}
 	${SSH} -oCompression=no -F $OBJ/ssh_proxy somehost "sleep $s;sleep 10"
 	if [ $? -ne 0 ]; then
 		fail "ssh failed"
 	fi
+	LOG=`ssh_logfile`
 	n=`grep 'NEWKEYS sent' ${LOG} | wc -l`
 	n=`expr $n - 1`
 	trace "$n rekeying(s)"

regress/test-exec.sh

@@ -240,6 +240,10 @@ fi
 # SSH_LOGFILE should be the debug output of ssh(1) only
 # SSHD_LOGFILE should be the debug output of sshd(8) only
 # REGRESS_LOGFILE is the output of the test itself stdout and stderr
+if [ "x$TEST_SSH_LOGDIR" = "x" ]; then
+	TEST_SSH_LOGDIR=$OBJ/log
+	mkdir -p $TEST_SSH_LOGDIR
+fi
 if [ "x$TEST_SSH_LOGFILE" = "x" ]; then
 	TEST_SSH_LOGFILE=$OBJ/ssh.log
 fi
@@ -275,8 +279,6 @@ if [ "x$TEST_REGRESS_CACHE_DIR" != "x" ]; then
 fi
 
 # truncate logfiles
->$TEST_SSH_LOGFILE
->$TEST_SSHD_LOGFILE
 >$TEST_REGRESS_LOGFILE
 
 # Create wrapper ssh with logging.  We can't just specify "SSH=ssh -E..."
@@ -286,16 +288,46 @@ fi
 SSHLOGWRAP=$OBJ/ssh-log-wrapper.sh
 cat >$SSHLOGWRAP <<EOD
 #!/bin/sh
-echo "Executing: ${SSH} \$@" >>${TEST_SSH_LOGFILE}
+timestamp="\`$OBJ/timestamp\`"
+logfile="${TEST_SSH_LOGDIR}/ssh.\${timestamp}.\$\$.log"
+echo "Executing: ${SSH} \$@" >>\${logfile}
 for i in "\$@";do shift;case "\$i" in -q):;; *) set -- "\$@" "\$i";;esac;done
-exec ${SSH} -E${TEST_SSH_LOGFILE} "\$@"
+ln -f -s \${logfile} $OBJ/ssh.log
+exec ${SSH} -E\${logfile} "\$@"
 EOD
 
 chmod a+rx $OBJ/ssh-log-wrapper.sh
 REAL_SSH="$SSH"
 REAL_SSHD="$SSHD"
 SSH="$SSHLOGWRAP"
 
+SSHDLOGWRAP=$OBJ/sshd-log-wrapper.sh
+cat >$SSHDLOGWRAP <<EOD
+#!/bin/sh
+timestamp="\`$OBJ/timestamp\`"
+logfile="${TEST_SSH_LOGDIR}/sshd.\${timestamp}.\$\$.log"
+ln -f -s \${logfile} $OBJ/sshd.log
+echo "Executing: ${SSHD} \$@" >>\${logfile}
+exec ${SSHD} -E\${logfile} "\$@"
+EOD
+chmod a+rx $OBJ/sshd-log-wrapper.sh
+
+ssh_logfile ()
+{
+	if [ `echo $TEST_SSH_LOGDIR/ssh.* | wc -l | awk '{print $1}'` != 1 ]; then
+		fatal ssh log file requested but more than one log file present
+	fi
+	echo $TEST_SSH_LOGDIR/ssh.*
+}
+
+sshd_logfile ()
+{
+	if [ `echo $TEST_SSH_LOGDIR/sshd.* | wc -l | awk '{print $1}'` != 1 ]; then
+		fatal sshd logfile requested but more than one log file present
+	fi
+	echo $TEST_SSH_LOGDIR/sshd.*
+}
+
 # Some test data.  We make a copy because some tests will overwrite it.
 # The tests may assume that $DATA exists and is writable and $COPY does
 # not exist.  Tests requiring larger data files can call increase_datafile_size
@@ -450,19 +482,32 @@ cleanup ()
 
 start_debug_log ()
 {
-	echo "trace: $@" >$TEST_REGRESS_LOGFILE
-	echo "trace: $@" >$TEST_SSH_LOGFILE
-	echo "trace: $@" >$TEST_SSHD_LOGFILE
+	echo "trace: $@" >>$TEST_REGRESS_LOGFILE
+	if [ -d "$TEST_SSH_LOGDIR" ]; then
+		rm -f $TEST_SSH_LOGDIR/*
+	fi
 }
 
 save_debug_log ()
 {
 	echo $@ >>$TEST_REGRESS_LOGFILE
-	echo $@ >>$TEST_SSH_LOGFILE
-	echo $@ >>$TEST_SSHD_LOGFILE
 	(cat $TEST_REGRESS_LOGFILE; echo) >>$OBJ/failed-regress.log
-	(cat $TEST_SSH_LOGFILE; echo) >>$OBJ/failed-ssh.log
-	(cat $TEST_SSHD_LOGFILE; echo) >>$OBJ/failed-sshd.log
+	(echo $@; cat `ssh_logfile`; echo) >>$OBJ/failed-ssh.log
+	(echo $@; cat `sshd_logfile`; echo) >>$OBJ/failed-sshd.log
+
+	# Save all logfiles in a tarball.
+	testname=`echo $tid | tr ' ' _`
+	(cd $OBJ &&
+	  logfiles=""
+	  for i in $TEST_REGRESS_LOGFILE $TEST_SSH_LOGFILE $TEST_SSHD_LOGFILE \
+	    $TEST_SSH_LOGDIR; do
+		if [ -e "`basename $i`" ]; then
+			logfiles="$logfiles `basename $i`"
+		else
+			logfiles="$logfiles $i"
+		fi
+	  done
+	  tar cfv $OBJ/failed-$testname-logs.tar $logfiles)
 }
 
 trace ()
@@ -724,7 +769,7 @@ if test "$REGRESS_INTEROP_PUTTY" = "yes" ; then
 	echo "HostName=127.0.0.1" >> ${OBJ}/.putty/sessions/localhost_proxy
 	echo "PortNumber=$PORT" >> ${OBJ}/.putty/sessions/localhost_proxy
 	echo "ProxyMethod=5" >> ${OBJ}/.putty/sessions/localhost_proxy
-	echo "ProxyTelnetCommand=sh ${SRC}/sshd-log-wrapper.sh ${TEST_SSHD_LOGFILE} ${SSHD} -i -f $OBJ/sshd_proxy" >> ${OBJ}/.putty/sessions/localhost_proxy
+	echo "ProxyTelnetCommand=${OBJ}/sshd-log-wrapper.sh -i -f $OBJ/sshd_proxy" >> ${OBJ}/.putty/sessions/localhost_proxy
 	echo "ProxyLocalhost=1" >> ${OBJ}/.putty/sessions/localhost_proxy
 
 	PUTTYDIR=${OBJ}/.putty
@@ -734,7 +779,7 @@ fi
 # create a proxy version of the client config
 (
 	cat $OBJ/ssh_config
-	echo proxycommand ${SUDO} env SSH_SK_HELPER=\"$SSH_SK_HELPER\" sh ${SRC}/sshd-log-wrapper.sh ${TEST_SSHD_LOGFILE} ${SSHD} -i -f $OBJ/sshd_proxy
+	echo proxycommand ${SUDO} env SSH_SK_HELPER=\"$SSH_SK_HELPER\" ${OBJ}/sshd-log-wrapper.sh -i -f $OBJ/sshd_proxy
 ) > $OBJ/ssh_proxy
 
 # check proxy config
@@ -743,9 +788,11 @@ ${SSHD} -t -f $OBJ/sshd_proxy	|| fatal "sshd_proxy broken"
 start_sshd ()
 {
 	# start sshd
+	logfile="${TEST_SSH_LOGDIR}/sshd.`$OBJ/timestamp`.$$.log"
 	$SUDO ${SSHD} -f $OBJ/sshd_config "$@" -t || fatal "sshd_config broken"
 	$SUDO env SSH_SK_HELPER="$SSH_SK_HELPER" \
-	    ${SSHD} -f $OBJ/sshd_config "$@" -E$TEST_SSHD_LOGFILE
+	    ${SSHD} -f $OBJ/sshd_config "$@" -E$logfile
+	echo "trace: Started sshd as daemon, logfile $logfile" >>$TEST_REGRESS_LOGFILE
 
 	trace "wait for sshd"
 	i=0;

regress/timestamp.c

@@ -0,0 +1,39 @@
+/*
+ * Copyright (c) 2023 Darren Tucker <dtucker@openssh.com>
+ *
+ * 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.
+ */
+
+/* $OpenBSD$ */
+
+#include <sys/time.h>
+
+#include <stdio.h>
+#include <stdlib.h>
+#include <time.h>
+
+int
+main(void)
+{
+	struct timeval tv;
+	struct tm *tm;
+	char buf[1024];
+
+	if (gettimeofday(&tv, NULL) != 0)
+		exit(1);
+	if ((tm = localtime(&tv.tv_sec)) == NULL)
+		exit(2);
+	if (strftime(buf, sizeof buf, "%Y-%m-%dT%H:%M:%S", tm) <= 0)
+		exit(3);
+	printf("%s.%06d\n", buf, (int)tv.tv_usec);
+}