7 files changed, 59 insertions, 23 deletions

diff --git a/ChangeLog b/ChangeLog
index 14450ac65..bb6787cf4 100644
--- a/ChangeLog
+++ b/ChangeLog
@@ -14,6 +14,13 @@
      Split the regress log into 3 parts: the debug output from ssh, the debug
      log from sshd and the output from the client command (ssh, scp or sftp).
      Somewhat functional now, will become more useful when ssh/sshd -E is added.
+   - dtucker@cvs.openbsd.org 2013/04/07 02:16:03
+     [regress/Makefile regress/rekey.sh regress/integrity.sh
+     regress/sshd-log-wrapper.sh regress/forwarding.sh regress/test-exec.sh]
+     use -E option for ssh and sshd to write debuging logs to ssh{,d}.log and
+     save the output from any failing tests.  If a test fails the debug output
+     from ssh and sshd for the failing tests (and only the failing tests) should
+     be available in failed-ssh{,d}.log.
 
 20130516
  - (djm) [contrib/ssh-copy-id] Fix bug that could cause "rm *" to be 
diff --git a/regress/Makefile b/regress/Makefile
index b99bd3e83..4ac5b4d42 100644
--- a/regress/Makefile
+++ b/regress/Makefile
@@ -1,4 +1,4 @@
-#       $OpenBSD: Makefile,v 1.63 2013/04/06 06:00:22 dtucker Exp $
+#       $OpenBSD: Makefile,v 1.64 2013/04/07 02:16:03 dtucker Exp $
 
 REGRESS_TARGETS=        t1 t2 t3 t4 t5 t6 t7 t8 t9 t-exec
 tests:          $(REGRESS_TARGETS)
@@ -83,7 +83,8 @@ CLEANFILES=	t2.out t3.out t6.out1 t6.out2 t7.out t7.out.pub copy.1 copy.2 \
                 key.rsa-* key.dsa-* key.ecdsa-* \
                 authorized_principals_${USER} expect actual ready \
                 sshd_proxy.* authorized_keys_${USER}.* modpipe revoked-* krl-* \
-                ssh.log sshd.log regress.log
+                ssh.log failed-ssh.log sshd.log failed-sshd.log \
+                regress.log failed-regress.log ssh-log-wrapper.sh
 
 # Enable all malloc(3) randomisations and checks
 TEST_ENV=      "MALLOC_OPTIONS=AFGJPRX"
diff --git a/regress/forwarding.sh b/regress/forwarding.sh
index f9c367beb..6a7003070 100644
--- a/regress/forwarding.sh
+++ b/regress/forwarding.sh
@@ -1,4 +1,4 @@
-#       $OpenBSD: forwarding.sh,v 1.8 2012/06/01 00:47:35 djm Exp $
+#       $OpenBSD: forwarding.sh,v 1.9 2013/04/07 02:16:03 dtucker Exp $
 #       Placed in the Public Domain.
 
 tid="local and remote forwarding"
@@ -75,7 +75,7 @@ for p in 1 2; do
         else
                 # this one should fail
                 ${SSH} -$p -F $OBJ/ssh_config -p ${base}01 true \
-                     2>>$TEST_SSH_LOGFILE && \
+                     >>$TEST_REGRESS_LOGFILE 2>&1 && \
                         fail "local forwarding not cleared"
         fi
         sleep 10
@@ -88,7 +88,7 @@ for p in 1 2; do
         else
                 # this one should fail
                 ${SSH} -$p -F $OBJ/ssh_config -p ${base}01 true \
-                     2>>$TEST_SSH_LOGFILE && \
+                     >>$TEST_REGRESS_LOGFILE 2>&1 && \
                         fail "remote forwarding not cleared"
         fi
         sleep 10
diff --git a/regress/integrity.sh b/regress/integrity.sh
index 1bd330a18..3950b7d1f 100644
--- a/regress/integrity.sh
+++ b/regress/integrity.sh
@@ -1,4 +1,4 @@
-#       $OpenBSD: integrity.sh,v 1.8 2013/04/06 06:00:22 dtucker Exp $
+#       $OpenBSD: integrity.sh,v 1.9 2013/04/07 02:16:03 dtucker Exp $
 #       Placed in the Public Domain.
 
 tid="integrity"
@@ -47,14 +47,15 @@ for m in $macs; do
                         aes*gcm*)       macopt="-c $m";;
                         *)              macopt="-m $m";;
                 esac
-                output=`${SSH} $macopt -2F $OBJ/ssh_proxy -o "$pxy" \
-                    999.999.999.999 'printf "%4096s" " "' 2>&1`
+                verbose "test $tid: $m @$off $output"
+                ${SSH} $macopt -2F $OBJ/ssh_proxy -o "$pxy" \
+                    999.999.999.999 'printf "%4096s" " "' >/dev/null
                 if [ $? -eq 0 ]; then
                         fail "ssh -m $m succeeds with bit-flip at $off"
                 fi
                 ecnt=`expr $ecnt + 1`
-                output=`echo $output | tr -s '\r\n' '.'`
-                verbose "test $tid: $m @$off $output"
+                output=$(tail -2 $TEST_SSH_LOGFILE | egrep -v "^debug" | \
+                     tr -s '\r\n' '.')
                 case "$output" in
                 Bad?packet*)    elen=`expr $elen + 1`; skip=3;;
                 Corrupted?MAC* | Decryption?integrity?check?failed*)
diff --git a/regress/rekey.sh b/regress/rekey.sh
index b23cfca70..d2542ecd4 100644
--- a/regress/rekey.sh
+++ b/regress/rekey.sh
@@ -1,4 +1,4 @@
-#       $OpenBSD: rekey.sh,v 1.2 2013/04/06 06:00:22 dtucker Exp $
+#       $OpenBSD: rekey.sh,v 1.3 2013/04/07 02:16:03 dtucker Exp $
 #       Placed in the Public Domain.
 
 tid="rekey during transfer data"
@@ -16,8 +16,7 @@ for s in 16 1k 128k 256k; do
         rm -f ${COPY}
         cat $DATA | \
                 ${SSH} -oCompression=no -oRekeyLimit=$s \
-                        -v -F $OBJ/ssh_proxy somehost "cat > ${COPY}" \
-                2> ${LOG}
+                        -v -F $OBJ/ssh_proxy somehost "cat > ${COPY}"
         if [ $? -ne 0 ]; then
                 fail "ssh failed"
         fi
diff --git a/regress/sshd-log-wrapper.sh b/regress/sshd-log-wrapper.sh
index c7a5ef3a6..a9386be4d 100644
--- a/regress/sshd-log-wrapper.sh
+++ b/regress/sshd-log-wrapper.sh
@@ -1,5 +1,5 @@
 #!/bin/sh
-#       $OpenBSD: sshd-log-wrapper.sh,v 1.2 2005/02/27 11:40:30 dtucker Exp $
+#       $OpenBSD: sshd-log-wrapper.sh,v 1.3 2013/04/07 02:16:03 dtucker Exp $
 #       Placed in the Public Domain.
 #
 # simple wrapper for sshd proxy mode to catch stderr output
@@ -10,4 +10,4 @@ log=$2
 shift
 shift
 
-exec $sshd $@ -e 2>>$log
+exec $sshd -E$log $@
diff --git a/regress/test-exec.sh b/regress/test-exec.sh
index b02172c03..f797ab68d 100644
--- a/regress/test-exec.sh
+++ b/regress/test-exec.sh
@@ -1,4 +1,4 @@
-#       $OpenBSD: test-exec.sh,v 1.39 2013/04/06 06:00:22 dtucker Exp $
+#       $OpenBSD: test-exec.sh,v 1.40 2013/04/07 02:16:03 dtucker Exp $
 #       Placed in the Public Domain.
 
 #SUDO=sudo
@@ -159,6 +159,15 @@ fi
 DATA=$OBJ/testdata
 cat $SSHD${EXEEXT} $SSHD${EXEEXT} $SSHD${EXEEXT} $SSHD${EXEEXT} >$DATA
 
+# Create wrapper ssh with logging.  We can't just specify "SSH=ssh -E..."
+# because sftp and scp don't handle spaces in arguments.
+SSHLOGWRAP=$OBJ/ssh-log-wrapper.sh
+echo "#!/bin/sh" > $SSHLOGWRAP
+echo "exec ${SSH} -E${TEST_SSH_LOGFILE} "'"$@"' >>$SSHLOGWRAP
+
+chmod a+rx $OBJ/ssh-log-wrapper.sh
+SSH="$SSHLOGWRAP"
+
 # these should be used in tests
 export SSH SSHD SSHAGENT SSHADD SSHKEYGEN SSHKEYSCAN SFTP SFTPSERVER SCP
 #echo $SSH $SSHD $SSHAGENT $SSHADD $SSHKEYGEN $SSHKEYSCAN $SFTP $SFTPSERVER $SCP
@@ -214,9 +223,26 @@ cleanup ()
         fi
 }
 
+start_debug_log ()
+{
+        echo "trace: $@" >$TEST_REGRESS_LOGFILE
+        echo "trace: $@" >$TEST_SSH_LOGFILE
+        echo "trace: $@" >$TEST_SSHD_LOGFILE
+}
+
+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
+}
+
 trace ()
 {
-        echo "trace: $@" >>$TEST_REGRESS_LOGFILE
+        start_debug_log $@
         if [ "X$TEST_SSH_TRACE" = "Xyes" ]; then
                 echo "$@"
         fi
@@ -224,7 +250,7 @@ trace ()
 
 verbose ()
 {
-        echo "verbose: $@" >>$TEST_REGRESS_LOGFILE
+        start_debug_log $@
         if [ "X$TEST_SSH_QUIET" != "Xyes" ]; then
                 echo "$@"
         fi
@@ -238,15 +264,16 @@ warn ()
 
 fail ()
 {
-        echo "FAIL: $@" >>$TEST_REGRESS_LOGFILE
+        save_debug_log "FAIL: $@"
         RESULT=1
         echo "$@"
+
 }
 
 fatal ()
 {
-        echo "FATAL: $@" >>$TEST_REGRESS_LOGFILE
-        echon "FATAL: "
+        save_debug_log "FATAL: $@"
+        echo -n "FATAL: "
         fail "$@"
         cleanup
         exit $RESULT
@@ -278,7 +305,7 @@ cat << EOF > $OBJ/sshd_config
         #ListenAddress          ::1
         PidFile                 $PIDFILE
         AuthorizedKeysFile      $OBJ/authorized_keys_%u
-        LogLevel                VERBOSE
+        LogLevel                DEBUG3
         AcceptEnv               _XXX_TEST_*
         AcceptEnv               _XXX_TEST
         Subsystem       sftp    $SFTPSERVER
@@ -312,6 +339,7 @@ Host *
         PasswordAuthentication  no
         BatchMode               yes
         StrictHostKeyChecking   yes
+        LogLevel                DEBUG3
 EOF
 
 if [ ! -z "$TEST_SSH_SSH_CONFOPTS" ]; then
@@ -405,7 +433,7 @@ start_sshd ()
 {
         # start sshd
         $SUDO ${SSHD} -f $OBJ/sshd_config "$@" -t || fatal "sshd_config broken"
-        $SUDO ${SSHD} -f $OBJ/sshd_config -e "$@" >>$TEST_SSHD_LOGFILE 2>&1
+        $SUDO ${SSHD} -f $OBJ/sshd_config "$@" -E$TEST_SSHD_LOGFILE
 
         trace "wait for sshd"
         i=0;