upstream: Rework logging for the regression tests.

Previously we would log to ssh.log and sshd.log, but that is insufficient
for tests that have more than one concurent ssh/sshd.

Instead, we'll log to separate datestamped files in a $OBJ/log/ and
leave a symlink at the previous location pointing at the most recent
instance with an entry in regress.log showing which files were created
at each point.  This should be sufficient to reconstruct what happened
even for tests that use multiple instances of each program.  If the test
fails, tar up all of the logs for later analysis.

This will let us also capture the output from some of the other tools
which was previously sent to /dev/null although most of those will be
in future commits.

OpenBSD-Regress-ID: f802aa9e7fa51d1a01225c05fb0412d015c33e24

diff --git a/Makefile.in b/Makefile.in
index c0ebfa0415255d669c535e5d1ae4059377a6a6ac..70287f51fb81402c6d33af56c36c67644abba418 100644 (file)
--- a/Makefile.in
+++ b/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)
@@ -691,6 +695,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) \

diff --git a/regress/Makefile b/regress/Makefile
index bf1d057aad339e607d7621d9d2b952096955adba..d80bf59fabc211d4820b231b6760aae3bdf2783b 100644 (file)
--- a/regress/Makefile
+++ b/regress/Makefile
@@ -1,4 +1,4 @@
-#      $OpenBSD: Makefile,v 1.122 2023/01/06 08:07:39 djm Exp $
+#      $OpenBSD: Makefile,v 1.124 2023/03/01 09:29:32 dtucker Exp $
 
 tests:         prep file-tests t-exec unit
 
@@ -138,8 +138,8 @@ CLEANFILES= *.core actual agent-key.* authorized_keys_${USERNAME} \
                sshd_config.* sshd_proxy sshd_proxy.* sshd_proxy_bak \
                sshd_proxy_orig t10.out t10.out.pub t12.out t12.out.pub \
                t2.out t3.out t6.out1 t6.out2 t7.out t7.out.pub \
-               t8.out t8.out.pub t9.out t9.out.pub testdata \
-               user_*key* user_ca* user_key*
+               t8.out t8.out.pub t9.out t9.out.pub \
+               timestamp testdata user_*key* user_ca* user_key*
 
 # Enable all malloc(3) randomisations and checks
 TEST_ENV=      "MALLOC_OPTIONS=CFGJRSUX"

diff --git a/regress/agent-restrict.sh b/regress/agent-restrict.sh
index a30aed7bf3d5ec43b89d06f98e8f4bab531c5c5b..62cea85225e7c39ab5a1d452c47b576a3ab3b460 100644 (file)
--- a/regress/agent-restrict.sh
+++ b/regress/agent-restrict.sh
@@ -1,4 +1,4 @@
-#      $OpenBSD: agent-restrict.sh,v 1.5 2022/01/13 04:53:16 dtucker Exp $
+#      $OpenBSD: agent-restrict.sh,v 1.6 2023/03/01 09:29:32 dtucker Exp $
 #      Placed in the Public Domain.
 
 tid="agent restrictions"
@@ -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

diff --git a/regress/agent.sh b/regress/agent.sh
index f187b675720142a9f235536478074b093e56e8d1..5f1060608eb58e26291d4994ccde6b84c352985e 100644 (file)
--- a/regress/agent.sh
+++ b/regress/agent.sh
@@ -1,4 +1,4 @@
-#      $OpenBSD: agent.sh,v 1.20 2021/02/25 03:27:34 djm Exp $
+#      $OpenBSD: agent.sh,v 1.21 2023/03/01 09:29:32 dtucker Exp $
 #      Placed in the Public Domain.
 
 tid="simple agent test"
@@ -9,7 +9,7 @@ if [ $? -ne 2 ]; then
 fi
 
 trace "start agent, args ${EXTRA_AGENT_ARGS} -s"
-eval `${SSHAGENT} ${EXTRA_AGENT_ARGS} -s` > /dev/null
+eval `${SSHAGENT} ${EXTRA_AGENT_ARGS} -s` >`ssh_logfile ssh-agent`
 r=$?
 if [ $r -ne 0 ]; then
        fatal "could not start ssh-agent: exit code $r"

diff --git a/regress/integrity.sh b/regress/integrity.sh
index bc030cb74f3566121a446224512c98d31c92c92b..202483c75f4fb2e84a6a6a4d6c322c082d49ca22 100644 (file)
--- a/regress/integrity.sh
+++ b/regress/integrity.sh
@@ -1,4 +1,4 @@
-#      $OpenBSD: integrity.sh,v 1.24 2020/01/21 08:06:27 djm Exp $
+#      $OpenBSD: integrity.sh,v 1.25 2023/03/01 09:29:32 dtucker Exp $
 #      Placed in the Public Domain.
 
 tid="integrity"
@@ -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"

diff --git a/regress/multiplex.sh b/regress/multiplex.sh
index f9c8fc10bd149147b0c712d508e29d74da8381d3..8282d0d940f5e060e5ef56592cb23ec6d0de24b2 100644 (file)
--- a/regress/multiplex.sh
+++ b/regress/multiplex.sh
@@ -1,4 +1,4 @@
-#      $OpenBSD: multiplex.sh,v 1.35 2023/01/13 04:47:34 dtucker Exp $
+#      $OpenBSD: multiplex.sh,v 1.36 2023/03/01 09:29:32 dtucker Exp $
 #      Placed in the Public Domain.
 
 make_tmpdir
@@ -87,7 +87,7 @@ cmp ${DATA} ${COPY}           || fail "scp: corrupted copy of ${DATA}"
 rm -f ${COPY}
 verbose "test $tid: forward"
 trace "forward over TCP/IP and check result"
-$NC -N -l 127.0.0.1 $((${PORT} + 1)) < ${DATA} > /dev/null &
+$NC -N -l 127.0.0.1 $((${PORT} + 1)) < ${DATA} >`ssh_logfile nc` &
 netcat_pid=$!
 ${SSH} -F $OBJ/ssh_config -S $CTL -Oforward -L127.0.0.1:$((${PORT} + 2)):127.0.0.1:$((${PORT} + 1)) otherhost >>$TEST_SSH_LOGFILE 2>&1
 sleep 1  # XXX remove once race fixed

diff --git a/regress/sshd-log-wrapper.sh b/regress/sshd-log-wrapper.sh
deleted file mode 100644 (file)
index 4b3c911..0000000
--- a/regress/sshd-log-wrapper.sh
+++ /dev/null
@@ -1,12 +0,0 @@
-#!/bin/sh
-#       $OpenBSD: sshd-log-wrapper.sh,v 1.5 2022/01/04 08:38:53 dtucker Exp $
-#       Placed in the Public Domain.
-#
-# simple wrapper for sshd proxy mode to catch stderr output
-# sh sshd-log-wrapper.sh /path/to/logfile /path/to/sshd [args...]
-
-log=$1
-shift
-
-echo "Executing: $@" >>$log
-exec "$@" -E$log

diff --git a/regress/test-exec.sh b/regress/test-exec.sh
index 325393ce9927e090e12d7373772f171c86d246ea..eecbac093940f7f182f496b710fb07c23b181399 100644 (file)
--- a/regress/test-exec.sh
+++ b/regress/test-exec.sh
@@ -1,4 +1,4 @@
-#      $OpenBSD: test-exec.sh,v 1.94 2023/01/13 04:47:34 dtucker Exp $
+#      $OpenBSD: test-exec.sh,v 1.95 2023/03/01 09:29:32 dtucker Exp $
 #      Placed in the Public Domain.
 
 #SUDO=sudo
@@ -240,7 +240,13 @@ fi
 # Logfiles.
 # 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
+# REGRESS_LOGFILE is the log of progress of the regress test itself.
+# TEST_SSH_LOGDIR will contain datestamped logs of all binaries run in
+# chronological order.
+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
@@ -276,20 +282,27 @@ 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..."
-# because sftp and scp don't handle spaces in arguments.  scp and sftp like
-# to use -q so we remove those to preserve our debug logging.  In the rare
-# instance where -q is desirable -qq is equivalent and is not removed.
+# Create ssh and sshd wrappers with logging.  These create a datestamped
+# unique file for every invocation so that we can retain all logs from a
+# given test no matter how many times it's invoked.  It also leaves a
+# symlink with the original name for tests (and people) who look for that.
+
+# For ssh, e can't just specify "SSH=ssh -E..." because sftp and scp don't
+# handle spaces in arguments.  scp and sftp like to use -q so we remove those
+# to preserve our debug logging.  In the rare instance where -q is desirable
+# -qq is equivalent and is not removed.
 SSHLOGWRAP=$OBJ/ssh-log-wrapper.sh
 cat >$SSHLOGWRAP <<EOD
 #!/bin/sh
-echo "Executing: ${SSH} \$@" >>${TEST_SSH_LOGFILE}
+timestamp="\`$OBJ/timestamp\`"
+logfile="${TEST_SSH_LOGDIR}/\${timestamp}.ssh.\$\$.log"
+echo "Executing: ${SSH} \$@" log \${logfile} >>$TEST_REGRESS_LOGFILE
+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} $TEST_SSH_LOGFILE
+exec ${SSH} -E\${logfile} "\$@"
 EOD
 
 chmod a+rx $OBJ/ssh-log-wrapper.sh
@@ -297,6 +310,27 @@ 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}/\${timestamp}.sshd.\$\$.log"
+ln -f -s \${logfile} $TEST_SSHD_LOGFILE
+echo "Executing: ${SSHD} \$@" log \${logfile} >>$TEST_REGRESS_LOGFILE
+echo "Executing: ${SSHD} \$@" >>\${logfile}
+exec ${SSHD} -E\${logfile} "\$@"
+EOD
+chmod a+rx $OBJ/sshd-log-wrapper.sh
+
+ssh_logfile ()
+{
+       tool="$1"
+       timestamp="`$OBJ/timestamp`"
+       logfile="${TEST_SSH_LOGDIR}/${timestamp}.$tool.$$.log"
+       echo "Logging $tool to log \${logfile}" >>$TEST_REGRESS_LOGFILE
+       echo $logfile
+}
+
 # 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
@@ -451,9 +485,10 @@ 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 ()
@@ -464,6 +499,20 @@ save_debug_log ()
        (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
+
+       # 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 ()
@@ -725,7 +774,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
@@ -735,7 +784,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
@@ -744,6 +793,7 @@ ${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

diff --git a/regress/timestamp.c b/regress/timestamp.c
new file mode 100644 (file)
index 0000000..77dae45
--- /dev/null
+++ b/regress/timestamp.c
@@ -0,0 +1,46 @@
+/*
+ * 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: timestamp.c,v 1.1 2023/03/01 09:29:32 dtucker Exp $ */
+
+/*
+ * Print a microsecond-granularity timestamp to stdout in an ISO8601-ish
+ * format, which we can then use as the first component of the log file
+ * so that they'll sort into chronological order.
+ */
+
+#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);
+       exit(0);
+}