diff --git a/.github/workflows/test-live.yml b/.github/workflows/test-live.yml index 49b70f69..d3f76d34 100644 --- a/.github/workflows/test-live.yml +++ b/.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 diff --git a/scripts/live-test-report.sh b/scripts/live-test-report.sh index 8c87a77f..f4d28fe5 100755 --- a/scripts/live-test-report.sh +++ b/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; } diff --git a/scripts/live-test-report_test.sh b/scripts/live-test-report_test.sh new file mode 100755 index 00000000..2297da69 --- /dev/null +++ b/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"