[PATCH] travis-ci: include the trash directories of failed tests in the trace log

[PATCH] travis-ci: include the trash directories of failed tests in the trace log

[SZEDER Gábor]

The trash directory of a failed test might contain invaluable
information about the cause of the failure, but we have no access to
the trash directories of Travis CI build jobs.  The only feedback we
get from there is the build job's trace log, so...

Modify 'ci/print-test-failures.sh' to create a tar.gz archive of the
trash directory of each failed test, encode that archive with base64,
and print the resulting block of ASCII text, so it gets embedded in
the trace log.  Furthermore, run tests with '--immediate' to
faithfully preserve the failed state.

Extracting the trash directories from the trace log turned out to be a
bit of a hassle, partly because of the size of these logs (usually
resulting in several hundreds or even thousands of lines of
base64-encoded text), and partly because these logs have CRLF, CRCRLF
and occasionally even CRCRCRLF line endings, which cause 'base64 -d'
from coreutils to complain about "invalid input".  For convenience add
a small script 'ci/util/extract-trash-dirs.sh', which will extract and
unpack all base64-encoded trash directories embedded in the log fed to
its standard input, and include an example command to be copy-pasted
into a terminal to do it all at the end of the failure report.

A few of our tests create sizeable trash directories, so limit the
size of each included base64-encoded block, let's say, to 1MB.  And
just in case something fundamental gets broken and a lot of tests fail
at once, don't include trash directories when the combined size of the
included base64-encoded blocks would exceed 1MB.

Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>
---

Notes:
    This is an improved version of the PoC mentioned some months ago at:
    
      https://public-inbox.org/git/20180122182717.21539-1-szeder.dev@gmail.com/
    
    I'm still not sure whether this is too clever or too ugly, or both,
    but it did actually prove to be useful since then: it's very likely
    that we wouldn't have 2f3cbcd8c5 (tests: make forging GPG signed
    commits and tags more robust, 2018-06-04) without it.
    
    The output looks like this; with this patch on top of yesterday's
    'pu' (6f49f36eba), which happens to have multiple test failures:
    
      https://travis-ci.org/szeder/git/jobs/410471312#L3010
    
    (Note: the Travis CI webpage will likely fold up the failure output
    before you could take a closer look at it; then click on the line
    containing '$ ci/print-test-failures.sh' and scroll down for a while.)

 ci/lib-travisci.sh            |  2 +-
 ci/print-test-failures.sh     | 55 +++++++++++++++++++++++++++++++++--
 ci/util/extract-trash-dirs.sh | 50 +++++++++++++++++++++++++++++++
 3 files changed, 104 insertions(+), 3 deletions(-)
 create mode 100755 ci/util/extract-trash-dirs.sh

diff --git a/ci/lib-travisci.sh b/ci/lib-travisci.sh
index ceecc889ca..06970f7213 100755
--- a/ci/lib-travisci.sh
+++ b/ci/lib-travisci.sh
@@ -97,7 +97,7 @@ fi
 export DEVELOPER=1
 export DEFAULT_TEST_TARGET=prove
 export GIT_PROVE_OPTS="--timer --jobs 3 --state=failed,slow,save"
-export GIT_TEST_OPTS="--verbose-log -x"
+export GIT_TEST_OPTS="--verbose-log -x --immediate"
 export GIT_TEST_CLONE_2GB=YesPlease
 if [ "$jobname" = linux-gcc ]; then
 	export CC=gcc-8
diff --git a/ci/print-test-failures.sh b/ci/print-test-failures.sh
index 4f261ddc01..d55460a212 100755
--- a/ci/print-test-failures.sh
+++ b/ci/print-test-failures.sh
@@ -8,13 +8,24 @@
 # Tracing executed commands would produce too much noise in the loop below.
 set +x
 
-if ! ls t/test-results/*.exit >/dev/null 2>/dev/null
+cd t/
+
+if ! ls test-results/*.exit >/dev/null 2>/dev/null
 then
 	echo "Build job failed before the tests could have been run"
 	exit
 fi
 
-for TEST_EXIT in t/test-results/*.exit
+case "$jobname" in
+osx-clang|osx-gcc)
+	# base64 in OSX doesn't wrap its output at 76 columns by
+	# default, but prints a single, very long line.
+	base64_opts="-b 76"
+	;;
+esac
+
+combined_trash_size=0
+for TEST_EXIT in test-results/*.exit
 do
 	if [ "$(cat "$TEST_EXIT")" != "0" ]
 	then
@@ -23,5 +34,45 @@ do
 		echo "$(tput setaf 1)${TEST_OUT}...$(tput sgr0)"
 		echo "------------------------------------------------------------------------"
 		cat "${TEST_OUT}"
+
+		test_name="${TEST_EXIT%.exit}"
+		test_name="${test_name##*/}"
+		trash_dir="trash directory.$test_name"
+		trash_tgz_b64="trash.$test_name.base64"
+		if [ -d "$trash_dir" ]
+		then
+			tar czp "$trash_dir" |base64 $base64_opts >"$trash_tgz_b64"
+
+			trash_size=$(wc -c <"$trash_tgz_b64")
+			if [ $trash_size -gt 1048576 ]
+			then
+				# larger than 1MB
+				echo "$(tput setaf 1)Didn't include the trash directory of '$test_name' in the trace log, it's too big$(tput sgr0)"
+				continue
+			fi
+
+			new_combined_trash_size=$(($combined_trash_size + $trash_size))
+			if [ $new_combined_trash_size -gt 1048576 ]
+			then
+				echo "$(tput setaf 1)Didn't include the trash directory of '$test_name' in the trace log, there is plenty of trash in there already.$(tput sgr0)"
+				continue
+			fi
+			combined_trash_size=$new_combined_trash_size
+
+			# DO NOT modify these two 'echo'-ed strings below
+			# without updating 'ci/util/extract-trash-dirs.sh'
+			# as well.
+			echo "$(tput setaf 1)Start of trash directory of '$test_name':$(tput sgr0)"
+			cat "$trash_tgz_b64"
+			echo "$(tput setaf 1)End of trash directory of '$test_name'$(tput sgr0)"
+		fi
 	fi
 done
+
+if [ $combined_trash_size -gt 0 ]
+then
+	echo "------------------------------------------------------------------------"
+	echo "Trash directories embedded in this log can be extracted by running:"
+	echo
+	echo "  curl https://api.travis-ci.org/v3/job/$TRAVIS_JOB_ID/log.txt |./ci/util/extract-trash-dirs.sh"
+fi
diff --git a/ci/util/extract-trash-dirs.sh b/ci/util/extract-trash-dirs.sh
new file mode 100755
index 0000000000..8e67bec21a
--- /dev/null
+++ b/ci/util/extract-trash-dirs.sh
@@ -0,0 +1,50 @@
+#!/bin/sh
+
+error () {
+	echo >&2 "error: $@"
+	exit 1
+}
+
+find_embedded_trash () {
+	while read -r line
+	do
+		case "$line" in
+		*Start\ of\ trash\ directory\ of\ \'t[0-9][0-9][0-9][0-9]-*\':*)
+			test_name="${line#*\'}"
+			test_name="${test_name%\'*}"
+
+			return 0
+		esac
+	done
+
+	return 1
+}
+
+extract_embedded_trash () {
+	while read -r line
+	do
+		case "$line" in
+		*End\ of\ trash\ directory\ of\ \'$test_name\'*)
+			return
+			;;
+		*)
+			printf '%s\n' "$line"
+			;;
+		esac
+	done
+
+	error "unexpected end of input"
+}
+
+# Raw logs from Linux build jobs have CRLF line endings, while OSX
+# build jobs mostly have CRCRLF, except an odd line every now and
+# then that has CRCRCRLF.  'base64 -d' from 'coreutils' doesn't like
+# CRs and complains about "invalid input", so remove all CRs at the
+# end of lines.
+sed -e 's/\r*$//' | \
+while find_embedded_trash
+do
+	echo "Extracting trash directory of '$test_name'"
+
+	extract_embedded_trash |base64 -d |tar xzp
+done
-- 
2.18.0.408.g42635c01bc

Re: [PATCH] travis-ci: include the trash directories of failed tests in the trace log

[SZEDER Gábor]

On Tue, Aug 7, 2018 at 5:12 PM Lars Schneider <larsxschneider@gmail.com> wrote:
>
> > On Aug 1, 2018, at 12:56 AM, SZEDER Gábor <szeder.dev@gmail.com> wrote:
> >
> > The trash directory of a failed test might contain invaluable
> > information about the cause of the failure, but we have no access to
> > the trash directories of Travis CI build jobs.  The only feedback we
> > get from there is the build job's trace log, so...
>
> 100% agree that keeping the trash directory is valuable.
>
> > Modify 'ci/print-test-failures.sh' to create a tar.gz archive of the
> > trash directory of each failed test, encode that archive with base64,
> > and print the resulting block of ASCII text, so it gets embedded in
> > the trace log.  Furthermore, run tests with '--immediate' to
> > faithfully preserve the failed state.
>
> I feel that might be complicated to work with.

It works quite conveniently in practice, that was one of the points of
the next paragraph.

> How about this:
> We create an publicly available Git repo (e.g. github.com/git/git-test-trash`)

I'm not sure I understand.  A publicly _writable_ repository?  That
sounds like asking for trouble.

> and then we push the trash directory of every failed test run to
> this repo. Then we link the commit in the logs to help people find
> them.
>
> Wouldn't that make it easier to access the trash dir?

With this patch, if there are any trash directories embedded in the
log, then the log will show a command near the very end that you can
copy-paste into a terminal, and bam! in less than 3 seconds you have
all those trash directories downloaded and unpacked.

I'm not sure how it could be made any easier than that.

> > Extracting the trash directories from the trace log turned out to be a
> > bit of a hassle, partly because of the size of these logs (usually
> > resulting in several hundreds or even thousands of lines of
> > base64-encoded text), and partly because these logs have CRLF, CRCRLF
> > and occasionally even CRCRCRLF line endings, which cause 'base64 -d'
> > from coreutils to complain about "invalid input".  For convenience add
> > a small script 'ci/util/extract-trash-dirs.sh', which will extract and
> > unpack all base64-encoded trash directories embedded in the log fed to
> > its standard input, and include an example command to be copy-pasted
> > into a terminal to do it all at the end of the failure report.
> >
> > A few of our tests create sizeable trash directories, so limit the
> > size of each included base64-encoded block, let's say, to 1MB.  And
> > just in case something fundamental gets broken and a lot of tests fail
> > at once, don't include trash directories when the combined size of the
> > included base64-encoded blocks would exceed 1MB.
> >
> > Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>
> > ---