- 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.

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 

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"

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

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" \
+		verbose "test $tid: $m @$off $output"
-		    999.999.999.999 'printf "%4096s" " "' 2>&1`
+		${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' '.'`
+		output=$(tail -2 $TEST_SSH_LOGFILE | egrep -v "^debug" | \
-		verbose "test $tid: $m @$off $output"
+		     tr -s '\r\n' '.')
 		case "$output" in
 		Bad?packet*)	elen=`expr $elen + 1`; skip=3;;
 		Corrupted?MAC* | Decryption?integrity?check?failed*)

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}" \
+			-v -F $OBJ/ssh_proxy somehost "cat > ${COPY}"
-		2> ${LOG}
 	if [ $? -ne 0 ]; then
 		fail "ssh failed"
 	fi

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 $@

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
+	save_debug_log "FATAL: $@"
-	echon "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;