ci: print live test results to the job log

.github/workflows/test-live.yml

@@ -70,7 +70,16 @@ jobs:
         env:
           B2_APPLICATION_KEY_ID: ${{ secrets.B2_APPLICATION_KEY_ID }}
           B2_APPLICATION_KEY: ${{ secrets.B2_APPLICATION_KEY }}
-        run: go test -json -count=1 -timeout 30m ./b2/... ./base/... > test.json
+        run: |
+          set -o pipefail
+          go test -json -count=1 -timeout 30m ./b2/... ./base/... | tee test.json | jq -Rrj --unbuffered '
+            fromjson? | if .Action == "build-output" or (.Test == null and .Action == "output") then .Output
+            elif .Action == "output" and (.Output | test("^panic: |test timed out|^fatal error: ")) then .Output
+            elif .Action == "build-fail" then "BUILD FAIL \(.ImportPath)\n"
+            elif .Action == "pass" or .Action == "fail" or .Action == "skip" then
+              select(.Test != null and (.Test | contains("/") | not))
+              | "\(.Action | ascii_upcase) \(.Package | sub(".*/blazer/"; "")) \(.Test) (\(.Elapsed // 0)s)\n"
+            else empty end'
       - name: Report live test results
         if: ${{ always() && steps.creds.outcome == 'success' }}
         run: scripts/live-test-report.sh test.json

scripts/live-test-report.sh

@@ -1,12 +1,12 @@
 #!/usr/bin/env bash
 # Summarizes a `go test -json` run of the live tests and fails unless they really ran against B2.
 # Usage: scripts/live-test-report.sh test.json
-# Writes a Markdown summary to $GITHUB_STEP_SUMMARY when set. Exit 1 when a test failed, when any test
+# Prints the Markdown summary and the output of failed tests to stdout (the job log) and, when set, also
+# appends the summary to $GITHUB_STEP_SUMMARY. Exit 1 when a test failed, when any test
 # skipped, or when a test defined in a live test file did not pass.
 set -euo pipefail
 
 in=${1:?usage: live-test-report.sh test.json}
-summary=${GITHUB_STEP_SUMMARY:-/dev/stdout}
 module=github.com/Backblaze/blazer
 # Every top-level test in these files must run and pass; there is no other way to tell they reached B2.
 live_files=(b2/integration_test.go b2/lock_test.go base/integration_test.go)
@@ -34,7 +34,7 @@ list() {
   while IFS= read -r line; do echo "- \`${line#"$module"/}\`"; done <<<"$2"
 }
 
-{
+report() {
   echo "## Live integration tests"
   echo
   echo "Commit \`${GITHUB_SHA:-local}\` · trigger \`${GITHUB_EVENT_NAME:-local}\`"
@@ -46,7 +46,46 @@ list() {
   list "Failed packages" "$failed_pkgs"
   list "Skipped (no test may skip in the live run)" "$skipped"
   list "Live tests that did not pass" "$missing"
-} >>"$summary"
+}
+
+if [ -n "${GITHUB_STEP_SUMMARY:-}" ]; then
+  report | tee -a "$GITHUB_STEP_SUMMARY"
+else
+  report
+fi
+
+# Where the time went, per package, so the log shows what ran.
+jq -r 'select(.Test == null and (.Action == "pass" or .Action == "fail" or .Action == "skip"))
+  | "\(.Action | ascii_upcase) \(.Package) (\(.Elapsed // 0)s)"' "$in" | sed "s#$module/##"
+
+# Output of failed tests, and of tests a panic or timeout cut off: Go attributes that stack trace to the
+# running test but emits no failure event for it, only one for the package. Each test (and each failed
+# package) gets its own budget so a noisy one cannot hide another's failure. Past 300 lines the first 100
+# and last 200 are kept, and panic, timeout and fatal lines are always kept.
+if [ -n "$failed" ] || [ -n "$failed_pkgs" ]; then
+  echo "::group::Output of failed tests"
+  jq -rs '
+    def key: "\(.Package) \(.Test)";
+    def important: test("^panic: |test timed out|^fatal error: ");
+    def cap: if length <= 300 then . else
+        ([.[:100][], .[-200:][]]) as $kept
+        | ([.[] | select(important)] | .[:20] - $kept) as $key
+        | .[:100] + ["... \(length - 300) lines omitted ..."] + (if ($key | length) > 0 then ["... key lines from the omitted part ..."] + $key + ["..."] else [] end) + .[-200:]
+      end;
+    [.[] | select(.Action == "fail" and .Test == null) | .Package] as $badpkgs
+    | [.[] | select(.Test != null and (.Action == "pass" or .Action == "fail" or .Action == "skip")) | key] as $done
+    | [.[] | select(.Action == "run" and (.Package as $p | $badpkgs | index($p) != null)) | key | select(. as $k | $done | index($k) == null)] as $cut
+    | [.[] | select(.Action == "fail" and .Test != null) | key] as $f
+    | [.[] | select(.Action == "output" and (
+        (.Test != null and ((key as $k | $f | index($k) != null) or (key as $k | $cut | index($k) != null)))
+        or (.Test == null and (.Package as $p | $badpkgs | index($p) != null))))]
+    | group_by(if .Test != null then key else .Package end)
+    | .[]
+    | "=== \(.[0] | if .Test != null then key else .Package end)",
+      ((map(.Output) | join("") | split("\n") | if length > 0 and .[-1] == "" then .[:-1] else . end | cap)[])
+  ' "$in"
+  echo "::endgroup::"
+fi
 
 status=0
 [ -n "$failed" ] && { echo "::error::Tests failed in the live run."; status=1; }

scripts/live-test-report_test.sh

@@ -0,0 +1,120 @@
+#!/usr/bin/env bash
+# Tests scripts/live-test-report.sh against a small `go test -json` fixture.
+set -euo pipefail
+
+here=$(cd "$(dirname "$0")" && pwd)
+root=$(cd "$here/.." && pwd)
+tmp=$(mktemp -d)
+trap 'rm -rf "$tmp"' EXIT
+cd "$root"
+
+# Every top-level test of the live files, all passing.
+live=$(for f in b2/integration_test.go b2/lock_test.go base/integration_test.go; do
+  grep -oE '^func Test[A-Za-z0-9_]*\(t \*testing\.T\)' "$f" |
+    sed -E "s#^func (Test[A-Za-z0-9_]*).*#$(dirname "$f") \1#"
+done)
+ev() { printf '{"Action":"%s","Package":"github.com/Backblaze/blazer/%s","Test":"%s","Elapsed":0.5}\n' "$1" "$2" "$3"; }
+while read -r dir name; do ev pass "$dir" "$name"; done <<<"$live" >"$tmp/pass.json"
+echo '{"Action":"pass","Package":"github.com/Backblaze/blazer/b2","Elapsed":12.5}' >>"$tmp/pass.json"
+
+fail=0
+check() { # name, expected exit, expected log text, json file
+  : >"$tmp/summary.md"
+  set +e
+  out=$(GITHUB_STEP_SUMMARY="$tmp/summary.md" "$here/live-test-report.sh" "$4" 2>&1)
+  code=$?
+  set -e
+  if [ "$code" = "$2" ] && grep -qF -- "$3" <<<"$out"; then
+    echo "ok   $1"
+  else
+    echo "FAIL $1: exit $code, want $2 with '$3'"; sed 's/^/       /' <<<"$out"; fail=1
+  fi
+}
+
+check "prints the summary to the log" 0 "Live integration tests" "$tmp/pass.json"
+if grep -qF "Live integration tests" "$tmp/summary.md"; then echo "ok   writes the summary file too"; else echo "FAIL summary file is empty"; fail=1; fi
+check "prints the per-package result" 0 "PASS b2 (12.5s)" "$tmp/pass.json"
+
+cp "$tmp/pass.json" "$tmp/fail.json"
+{
+  printf '%s\n' '{"Action":"output","Package":"github.com/Backblaze/blazer/b2","Test":"TestAttrs","Output":"    attrs_test.go:9: boom\n"}'
+  ev fail b2 TestAttrs
+} >>"$tmp/fail.json"
+check "prints the output of a failed test" 1 "attrs_test.go:9: boom" "$tmp/fail.json"
+
+# A passing test whose name is a prefix of a failing one must not have its output printed.
+cp "$tmp/pass.json" "$tmp/prefix.json"
+{
+  printf '%s\n' '{"Action":"output","Package":"github.com/Backblaze/blazer/b2","Test":"TestAttrs","Output":"PASSING-OUTPUT\n"}'
+  printf '%s\n' '{"Action":"output","Package":"github.com/Backblaze/blazer/b2","Test":"TestAttrsLong","Output":"FAILING-OUTPUT\n"}'
+  ev fail b2 TestAttrsLong
+} >>"$tmp/prefix.json"
+set +e
+out=$(GITHUB_STEP_SUMMARY="$tmp/summary.md" "$here/live-test-report.sh" "$tmp/prefix.json" 2>&1)
+set -e
+if grep -qF FAILING-OUTPUT <<<"$out" && ! grep -qF PASSING-OUTPUT <<<"$out"; then
+  echo "ok   prints only failed tests' output"
+else
+  echo "FAIL exact test-name matching"; sed 's/^/       /' <<<"$out"; fail=1
+fi
+
+# A timeout: Go attributes the stack trace to the running test and emits only a package failure.
+cp "$tmp/pass.json" "$tmp/timeout.json"
+{
+  printf '%s\n' '{"Action":"run","Package":"github.com/Backblaze/blazer/b2","Test":"TestHangs"}'
+  printf '%s\n' '{"Action":"output","Package":"github.com/Backblaze/blazer/b2","Test":"TestHangs","Output":"panic: test timed out after 30m0s\n"}'
+  printf '%s\n' '{"Action":"output","Package":"github.com/Backblaze/blazer/b2","Test":"TestAttrs","Output":"UNRELATED-OUTPUT\n"}'
+  printf '%s\n' '{"Action":"fail","Package":"github.com/Backblaze/blazer/b2","Elapsed":1800}'
+} >>"$tmp/timeout.json"
+check "prints the timeout reason of a cut-off test" 1 "panic: test timed out after 30m0s" "$tmp/timeout.json"
+set +e
+out=$(GITHUB_STEP_SUMMARY="$tmp/summary.md" "$here/live-test-report.sh" "$tmp/timeout.json" 2>&1)
+set -e
+if grep -qF UNRELATED-OUTPUT <<<"$out"; then echo "FAIL prints output of a passing test in a failed package"; fail=1; else echo "ok   skips finished tests in a failed package"; fi
+
+# More than 300 lines of output must still reach the closing group and the error line.
+cp "$tmp/pass.json" "$tmp/long.json"
+# Enough output to fill the pipe, so a `head` that exits early would SIGPIPE the writer.
+awk 'BEGIN { pad = sprintf("%80s", ""); for (i = 1; i <= 5000; i++) printf "{\"Action\":\"output\",\"Package\":\"github.com/Backblaze/blazer/b2\",\"Test\":\"TestAttrs\",\"Output\":\"line %d%s\\n\"}\n", i, pad }' >>"$tmp/long.json"
+ev fail b2 TestAttrs >>"$tmp/long.json"
+check "keeps the error line after long failure output" 1 "::error::Tests failed in the live run." "$tmp/long.json"
+
+
+# The failure message comes last, after the noise (David's case): 400 log lines, then the t.Fatal line.
+cp "$tmp/pass.json" "$tmp/fatal.json"
+awk 'BEGIN { for (i = 1; i <= 400; i++) printf "{\"Action\":\"output\",\"Package\":\"github.com/Backblaze/blazer/b2\",\"Test\":\"TestAttrs\",\"Output\":\"    noise %d\\n\"}\n", i }' >>"$tmp/fatal.json"
+printf '%s\n' '{"Action":"output","Package":"github.com/Backblaze/blazer/b2","Test":"TestAttrs","Output":"    attrs_test.go:99: FATAL-MESSAGE\n"}' >>"$tmp/fatal.json"
+ev fail b2 TestAttrs >>"$tmp/fatal.json"
+check "keeps the last lines of long failure output" 1 "FATAL-MESSAGE" "$tmp/fatal.json"
+check "says how many lines were omitted" 1 "lines omitted" "$tmp/fatal.json"
+
+# A timeout keeps its reason (first lines) even when the stack trace is long.
+cp "$tmp/pass.json" "$tmp/longtimeout.json"
+printf '%s\n' '{"Action":"run","Package":"github.com/Backblaze/blazer/b2","Test":"TestHangs"}' '{"Action":"output","Package":"github.com/Backblaze/blazer/b2","Test":"TestHangs","Output":"panic: test timed out after 30m0s\n"}' >>"$tmp/longtimeout.json"
+awk 'BEGIN { for (i = 1; i <= 600; i++) printf "{\"Action\":\"output\",\"Package\":\"github.com/Backblaze/blazer/b2\",\"Test\":\"TestHangs\",\"Output\":\"goroutine %d [running]\\n\"}\n", i }' >>"$tmp/longtimeout.json"
+printf '%s\n' '{"Action":"fail","Package":"github.com/Backblaze/blazer/b2","Elapsed":1800}' >>"$tmp/longtimeout.json"
+check "keeps the timeout reason above a long stack trace" 1 "panic: test timed out after 30m0s" "$tmp/longtimeout.json"
+
+
+# The timeout reason sits after 150 lines of progress output and before a 600-line stack trace.
+cp "$tmp/pass.json" "$tmp/latepanic.json"
+printf '%s\n' '{"Action":"run","Package":"github.com/Backblaze/blazer/b2","Test":"TestHangs"}' >>"$tmp/latepanic.json"
+awk 'BEGIN { for (i = 1; i <= 150; i++) printf "{\"Action\":\"output\",\"Package\":\"github.com/Backblaze/blazer/b2\",\"Test\":\"TestHangs\",\"Output\":\"progress %d\\n\"}\n", i }' >>"$tmp/latepanic.json"
+printf '%s\n' '{"Action":"output","Package":"github.com/Backblaze/blazer/b2","Test":"TestHangs","Output":"panic: test timed out after 30m0s\n"}' >>"$tmp/latepanic.json"
+awk 'BEGIN { for (i = 1; i <= 600; i++) printf "{\"Action\":\"output\",\"Package\":\"github.com/Backblaze/blazer/b2\",\"Test\":\"TestHangs\",\"Output\":\"goroutine %d [running]\\n\"}\n", i }' >>"$tmp/latepanic.json"
+printf '%s\n' '{"Action":"fail","Package":"github.com/Backblaze/blazer/b2","Elapsed":1800}' >>"$tmp/latepanic.json"
+check "keeps a timeout reason that follows 150 progress lines" 1 "panic: test timed out after 30m0s" "$tmp/latepanic.json"
+
+# Three failing tests: the quiet one sits between two noisy ones and must not lose its message.
+cp "$tmp/pass.json" "$tmp/two.json"
+noisy() { # test, count: that many noise lines, then the failure message and the fail event
+  awk -v t="$1" -v n="$2" 'BEGIN { for (i = 1; i <= n; i++) printf "{\"Action\":\"output\",\"Package\":\"github.com/Backblaze/blazer/b2\",\"Test\":\"%s\",\"Output\":\"noise %d\\n\"}\n", t, i }'
+  printf '{"Action":"output","Package":"github.com/Backblaze/blazer/b2","Test":"%s","Output":"    x_test.go:1: FATAL-%s\\n"}\n' "$1" "$1"
+  ev fail b2 "$1"
+}
+{ noisy TestA 400; noisy TestB 0; noisy TestC 500; } >>"$tmp/two.json"
+check "keeps the failure of the first of three failing tests" 1 "FATAL-TestA" "$tmp/two.json"
+check "keeps the failure of the quiet test between two noisy ones" 1 "FATAL-TestB" "$tmp/two.json"
+check "keeps the failure of the last of three failing tests" 1 "FATAL-TestC" "$tmp/two.json"
+
+exit "$fail"