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.

6 files changed, 51 insertions, 22 deletions

diff --git a/regress/usr.bin/ssh/Makefile b/regress/usr.bin/ssh/Makefile
index ad438119ec8..b0b8dd90062 100644
--- a/regress/usr.bin/ssh/Makefile
+++ b/regress/usr.bin/ssh/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
 
@@ -72,7 +72,8 @@ CLEANFILES+=	authorized_keys_${USER} known_hosts pidfile \
 		known_hosts-cert host_ca_key* cert_user_key* cert_host_key* \
 		authorized_principals_${USER} expect actual ready \
 		sshd_proxy.* authorized_keys_${USER}.* 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/usr.bin/ssh/forwarding.sh b/regress/usr.bin/ssh/forwarding.sh
index 242d7a986bb..c64ef5c87a5 100644
--- a/regress/usr.bin/ssh/forwarding.sh
+++ b/regress/usr.bin/ssh/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"
@@ -74,7 +74,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
@@ -87,7 +87,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/usr.bin/ssh/integrity.sh b/regress/usr.bin/ssh/integrity.sh
index ce33c52c7e5..8cd145ef3e0 100644
--- a/regress/usr.bin/ssh/integrity.sh
+++ b/regress/usr.bin/ssh/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"
@@ -39,14 +39,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=$((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=$((elen+1)); skip=2;;
 		Corrupted?MAC* | Decryption?integrity?check?failed*)
diff --git a/regress/usr.bin/ssh/rekey.sh b/regress/usr.bin/ssh/rekey.sh
index d8c55a95b5c..e886db2856b 100644
--- a/regress/usr.bin/ssh/rekey.sh
+++ b/regress/usr.bin/ssh/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"
@@ -15,8 +15,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/usr.bin/ssh/sshd-log-wrapper.sh b/regress/usr.bin/ssh/sshd-log-wrapper.sh
index c7a5ef3a680..a9386be4d1c 100644
--- a/regress/usr.bin/ssh/sshd-log-wrapper.sh
+++ b/regress/usr.bin/ssh/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/usr.bin/ssh/test-exec.sh b/regress/usr.bin/ssh/test-exec.sh
index 9ada223be3b..a278168bc23 100644
--- a/regress/usr.bin/ssh/test-exec.sh
+++ b/regress/usr.bin/ssh/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.
 
 USER=`id -un`
@@ -115,6 +115,15 @@ fi
 >$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.
+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
@@ -144,9 +153,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
@@ -154,7 +180,7 @@ trace ()
 
 verbose ()
 {
-	echo "verbose: $@" >>$TEST_REGRESS_LOGFILE
+	start_debug_log $@
 	if [ "X$TEST_SSH_QUIET" != "Xyes" ]; then
 		echo "$@"
 	fi
@@ -163,14 +189,15 @@ verbose ()
 
 fail ()
 {
-	echo "FAIL: $@" >>$TEST_REGRESS_LOGFILE
+	save_debug_log "FAIL: $@"
 	RESULT=1
 	echo "$@"
+
 }
 
 fatal ()
 {
-	echo "FATAL: $@" >>$TEST_REGRESS_LOGFILE
+	save_debug_log "FATAL: $@"
 	echo -n "FATAL: "
 	fail "$@"
 	cleanup
@@ -191,7 +218,7 @@ cat << EOF > $OBJ/sshd_config
 	#ListenAddress		::1
 	PidFile			$PIDFILE
 	AuthorizedKeysFile	$OBJ/authorized_keys_%u
-	LogLevel		DEBUG
+	LogLevel		DEBUG3
 	AcceptEnv		_XXX_TEST_*
 	AcceptEnv		_XXX_TEST
 	Subsystem	sftp	$SFTPSERVER
@@ -226,6 +253,7 @@ Host *
 	RhostsRSAAuthentication	no
 	BatchMode		yes
 	StrictHostKeyChecking	yes
+	LogLevel		DEBUG3
 EOF
 
 if [ ! -z "$TEST_SSH_SSH_CONFOPTS" ]; then
@@ -319,7 +347,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;