diff --git a/Makefile b/Makefile index cf0b39b42..8e07a1bb9 100644 --- a/Makefile +++ b/Makefile @@ -160,6 +160,19 @@ test-check-readiness: # (e.g. to use `find ... -print0 | xargs -0`). BATS_UNIT_FILES := $(filter-out hack/e2e-%.bats,$(wildcard hack/*.bats)) +# Quiet by default: cozytest.sh streams every test's xtrace live, which over +# this many suites buried the one failing assertion under ~240k lines of +# trace in CI. COZYTEST_TRACE=0 keeps the per-test start/end lines and still dumps +# the full trace of whichever test FAILS -- but not of one that is killed +# instead, a hang reaped by the job timeout among them, since the dump runs +# after the test returns. See the COZYTEST_TRACE comment in hack/cozytest.sh. +# Override to watch a run line by +# line: `COZYTEST_TRACE=1 make bats-unit-tests`, or invoke the runner +# directly (`hack/cozytest.sh hack/foo.bats [pattern]`), which stays verbose. +# The e2e call sites in packages/core/testing/Makefile are untouched and keep +# the live stream -- see the COZYTEST_TRACE comment in hack/cozytest.sh. +COZYTEST_TRACE ?= 0 + bats-unit-tests: @if [ -z "$(BATS_UNIT_FILES)" ]; then \ echo "ERROR: no hack/*.bats unit test files found"; \ @@ -167,7 +180,7 @@ bats-unit-tests: fi @for f in $(BATS_UNIT_FILES); do \ echo "--- running $$f ---"; \ - hack/cozytest.sh "$$f" || exit 1; \ + COZYTEST_TRACE=$(COZYTEST_TRACE) hack/cozytest.sh "$$f" || exit 1; \ done # Operator-facing host preflight check. Warns about a standalone diff --git a/hack/capture-previous-logs.bats b/hack/capture-previous-logs.bats index bb39d2683..30439f088 100644 --- a/hack/capture-previous-logs.bats +++ b/hack/capture-previous-logs.bats @@ -6,6 +6,7 @@ # # - prevlog_filter_restarted -- keep only containers with restartCount > 0; # - prevlog_prioritize -- put the failing test's namespace first; +# - prevlog_sort_recent -- newest restart first, undated rows last; # - prevlog_cap -- bound the dump so a wedged cluster cannot # explode the catch; # - prevlog_logfile_name -- per-container artifact filename. @@ -44,6 +45,10 @@ E2E_CAPTURE_PREVLOGS_LIB=1 . "$SCRIPT" @test "filter restarted keeps only containers whose restart count is above zero" { + # Deliberately fed the five-field shape, without the trailing finishedAt: the + # filter emits six fields either way, so the timestamp column is present and + # empty rather than absent. Uniform arity is what lets prevlog_sort_recent key + # on field 6 unconditionally. rows="$(printf '%s\n' \ 'tenant-test|mariadb-test-0|mariadb|container|3' \ 'tenant-test|mariadb-test-1|mariadb|container|0' \ @@ -53,8 +58,8 @@ E2E_CAPTURE_PREVLOGS_LIB=1 out="$(printf '%s\n' "$rows" | prevlog_filter_restarted)" [ "$(printf '%s\n' "$out" | grep -c .)" -eq 2 ] - printf '%s\n' "$out" | grep -q '^tenant-test|mariadb-test-0|mariadb|container|3$' - printf '%s\n' "$out" | grep -q '^tenant-test|mariadb-test-0|init-datadir|init|2$' + printf '%s\n' "$out" | grep -q '^tenant-test|mariadb-test-0|mariadb|container|3|$' + printf '%s\n' "$out" | grep -q '^tenant-test|mariadb-test-0|init-datadir|init|2|$' # `! cmd` is vacuous under cozytest's `set -e` (errexit is suppressed for a # `!`-negated pipeline), so a filter regression that let these rows through # would not fail the test. Assert the absence via `if cmd; then ...; false`. @@ -170,6 +175,171 @@ E2E_CAPTURE_PREVLOGS_LIB=1 [ "$(printf '%s\n' "$out" | sed -n '4p' | cut -d'|' -f2)" = "tenant-test-runner" ] } +@test "sort_recent puts the newest previous instance first and undated rows last" { + # The ordering the cap is spent under. Rows 1 and 4 are the fixture that makes + # this bite: the oldest restart arrives first from kubectl (pods are listed by + # namespace, not by time) and must end up behind the newest. + rows="$(printf '%s\n' \ + 'cozy-kubevirt|virt-api-a|virt-api|container|1|2026-08-13T01:30:56Z' \ + 'tenant-test|mariadb-0|mariadb|container|2|' \ + 'tenant-test|postgres-0|postgres|container|4|2026-08-22T09:06:00Z' \ + 'cozy-linstor|satellite-x|linstor|container|3|2026-08-17T13:07:28Z')" + + out="$(printf '%s\n' "$rows" | prevlog_sort_recent)" + + # Ordering, never dropping. + [ "$(printf '%s\n' "$out" | grep -c .)" -eq 4 ] + [ "$(printf '%s\n' "$out" | sed -n '1p' | cut -d'|' -f2)" = "postgres-0" ] + [ "$(printf '%s\n' "$out" | sed -n '2p' | cut -d'|' -f2)" = "satellite-x" ] + [ "$(printf '%s\n' "$out" | sed -n '3p' | cut -d'|' -f2)" = "virt-api-a" ] + # A container whose lastState the kubelet has already dropped carries no + # timestamp. It still has a previous instance worth reading, so it sorts last + # rather than being filtered out. + [ "$(printf '%s\n' "$out" | sed -n '4p' | cut -d'|' -f2)" = "mariadb-0" ] +} + +@test "sort_recent leaves simultaneous restarts in input order" { + # A node reboot restarts a dozen containers on the same second. Without a + # stable sort their order would vary between runs, and so would which of them + # the cap keeps -- turning a capture into something that cannot be compared + # against the previous run's. + # + # Fixture deliberately in DESCENDING name order. An ascending one (first, + # second, third) is reproduced by sort's last-resort whole-line comparison + # with no -s at all, so the test would pass on a platform that ignores -s -- + # which is the only platform it exists to catch. + rows="$(printf '%s\n' \ + 'ns|zeta|c|container|1|2026-08-17T13:07:28Z' \ + 'ns|mu|c|container|1|2026-08-17T13:07:28Z' \ + 'ns|alpha|c|container|1|2026-08-17T13:07:28Z')" + + out="$(printf '%s\n' "$rows" | prevlog_sort_recent)" + + [ "$(printf '%s\n' "$out" | sed -n '1p' | cut -d'|' -f2)" = "zeta" ] + [ "$(printf '%s\n' "$out" | sed -n '2p' | cut -d'|' -f2)" = "mu" ] + [ "$(printf '%s\n' "$out" | sed -n '3p' | cut -d'|' -f2)" = "alpha" ] +} + +@test "sort_recent is a no-op on rows that carry no timestamp field" { + # Every row ties, so the stable sort must return the input untouched. This is + # what lets the five-field fixtures elsewhere in this file keep asserting + # input order through prevlog_prioritize. + # Descending, for the same reason as the fixture above. + rows="$(printf '%s\n' \ + 'ns|p3|c|container|1' \ + 'ns|p2|c|container|1' \ + 'ns|p1|c|container|1')" + + out="$(printf '%s\n' "$rows" | prevlog_sort_recent)" + + [ "$out" = "$rows" ] +} + +@test "prioritize ranks namespace above recency" { + # Both keys in tension on purpose: the freshest restart in the cluster is in + # another namespace, and the failing test's own namespace holds only an older + # one. Namespace has to win -- a stale restart in the namespace under test is + # likelier to explain the failure than a fresh one somewhere unrelated -- and + # recency has to order within each group rather than across them. + rows="$(printf '%s\n' \ + 'cozy-kubevirt|virt-api|virt-api|container|1|2026-08-27T10:00:00Z' \ + 'tenant-test|mariadb-0|mariadb|container|1|2026-08-13T01:00:00Z' \ + 'cozy-linstor|satellite|linstor|container|1|2026-08-20T10:00:00Z' \ + 'tenant-test|postgres-0|postgres|container|1|2026-08-14T01:00:00Z')" + + out="$(printf '%s\n' "$rows" | prevlog_prioritize tenant-test)" + + [ "$(printf '%s\n' "$out" | grep -c .)" -eq 4 ] + # The test's namespace first, newest of the two leading it. + [ "$(printf '%s\n' "$out" | sed -n '1p' | cut -d'|' -f2)" = "postgres-0" ] + [ "$(printf '%s\n' "$out" | sed -n '2p' | cut -d'|' -f2)" = "mariadb-0" ] + # Then everything else, also newest first. + [ "$(printf '%s\n' "$out" | sed -n '3p' | cut -d'|' -f2)" = "virt-api" ] + [ "$(printf '%s\n' "$out" | sed -n '4p' | cut -d'|' -f2)" = "satellite" ] +} + +@test "filter_restarted carries the restart timestamp through" { + # The field the ordering depends on. It also has to be READ rather than left + # to fall into $restarts as trailing text: `read -r ... restarts` without a + # sixth variable folds the timestamp into the count, which reaches the dump + # header as `restarts=1|2026-08-22T09:06:00Z`. + rows="$(printf '%s\n' \ + 'ns|p1|c|container|2|2026-08-22T09:06:00Z' \ + 'ns|p2|c|container|0|2026-08-22T09:06:00Z' \ + 'ns|p3|c|container|1|')" + + out="$(printf '%s\n' "$rows" | prevlog_filter_restarted)" + + # p2 never restarted, so it is dropped regardless of its timestamp. + [ "$(printf '%s\n' "$out" | grep -c .)" -eq 2 ] + [ "$(printf '%s\n' "$out" | sed -n '1p')" = 'ns|p1|c|container|2|2026-08-22T09:06:00Z' ] + [ "$(printf '%s\n' "$out" | sed -n '2p' | cut -d'|' -f5)" = "1" ] + [ "$(printf '%s\n' "$out" | sed -n '2p' | cut -d'|' -f6)" = "" ] +} + +@test "a no value timestamp sorts last instead of jumping the queue" { + # kubectl renders a missing template leaf as the literal string ``, + # and `<` (0x3C) sorts ABOVE every digit, so under a reverse sort such a row + # lands FIRST and displaces the most recent real restart -- inverting the one + # thing this ordering exists to do. The template now guards the leaf so the + # string cannot be produced; this pins the row-level behaviour too, so the + # ordering is still defensible if some other producer ever emits it. + rows="$(printf '%s\n' \ + 'ns|undated|c|container|1|' \ + 'tenant-test|newest|c|container|4|2026-08-22T09:06:00Z' \ + 'tenant-test|older|c|container|1|2026-08-13T01:30:56Z')" + + out="$(printf '%s\n' "$rows" | prevlog_sort_recent)" + + first=$(printf '%s\n' "$out" | sed -n '1p' | cut -d'|' -f2) + if [ "$first" != "newest" ]; then + echo "FAIL: expected the newest real restart first, got '$first'" + printf '%s\n' "$out" + false + fi + [ "$(printf '%s\n' "$out" | sed -n '3p' | cut -d'|' -f2)" = "undated" ] +} + +@test "the pod template guards the timestamp leaf and not only its parents" { + # The stub-driven tests below inject rows directly and so never execute the + # go-template, which is exactly how the `` shape reached a live job + # log unnoticed. Assert the guard's shape in the script text instead: two + # levels (lastState, terminated) leave the leaf ungarded, and `finishedAt` is + # a metav1.Time whose zero value marshals to null, which the kubelet does + # produce (ContainerStatusUnknown, which also bumps restartCount). + guarded=$(grep -c 'if .lastState.terminated.finishedAt }}{{ .lastState.terminated.finishedAt }}' "$SCRIPT") + # One for initContainerStatuses, one for containerStatuses. + if [ "$guarded" -ne 2 ]; then + echo "FAIL: expected 2 leaf-guarded finishedAt references in the template, found $guarded" + grep -n 'finishedAt' "$SCRIPT" + false + fi +} + +@test "the dump header names when the previous instance ended" { + # The whole-script path: every other integration test here feeds five-field + # rows, so the sixth field reached the header with no coverage at all, and + # deleting it from the consumer loop's `read` left this suite green while the + # header printed `restarts=1|2026-08-22T09:06:00Z`. + tmp="$(mktemp -d)" + stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub" + out="$tmp/previous-logs" + rows='tenant-test|db-0|postgres|container|4|2026-08-22T09:06:00Z' + + PATH="$stub:$PATH" PREVLOG_STUB_ROWS="$rows" \ + sh "$SCRIPT" "$out" tenant-test >"$tmp/stdout" 2>&1 + + grep -q 'restarts=4, previous instance ended 2026-08-22T09:06:00Z' "$tmp/stdout" + # The count must not have absorbed the timestamp, which is the shape the + # missing read variable produced. + if grep -q 'restarts=4|' "$tmp/stdout"; then + echo "FAIL: the timestamp was folded into the restart count" + grep 'previous logs:' "$tmp/stdout" + false + fi + rm -rf "$tmp" +} + @test "cap keeps at most the requested number of rows" { rows="$(printf '%s\n' \ 'ns|p1|c|container|1' 'ns|p2|c|container|1' 'ns|p3|c|container|1' \ @@ -428,6 +598,29 @@ STUB rm -rf "$tmp" } +@test "an empty preferred namespace group does not consume a cap slot" { + tmp="$(mktemp -d)" + stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub" + out="$tmp/previous-logs" + rows="$(printf '%s\n' \ + 'cozy-system|operator-0|operator|container|4' \ + 'cozy-linstor|satellite-0|linstor|container|3' \ + 'cozy-cilium|agent-0|cilium|container|2')" + + PATH="$stub:$PATH" PREVLOG_STUB_ROWS="$rows" COZY_PREVLOG_MAX=3 \ + sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1 + + # No row matches tenant-test, so the preferred group is empty. Its lack of + # output must not become a blank line that head counts against the cap. + [ "$(ls "$out" | grep -c '\.log$')" -eq 3 ] + if grep -q 'reached COZY_PREVLOG_MAX=3 cap' "$out/capture-notes.txt"; then + echo "FAIL: an empty preferred group manufactured a cap overflow" + cat "$out/capture-notes.txt" + false + fi + rm -rf "$tmp" +} + @test "a missing timeout is named as a local dependency, not as a cluster failure" { tmp="$(mktemp -d)" bin="$tmp/bin"; mkdir -p "$bin" diff --git a/hack/cozytest-trace-switch.bats b/hack/cozytest-trace-switch.bats new file mode 100644 index 000000000..5208ff2c1 --- /dev/null +++ b/hack/cozytest-trace-switch.bats @@ -0,0 +1,188 @@ +#!/usr/bin/env bats +# ----------------------------------------------------------------------------- +# Behavioural tests for the COZYTEST_TRACE switch in hack/cozytest.sh. +# +# The runner streams every @test body's xtrace live. Across the unit suites that +# was 233,444 of 238,794 lines in one job log, with the single failing assertion +# at line 238,573, so `make unit-tests` now runs with the stream off. What makes +# that safe is a single invariant: run_one tees the raw stream to $log and the +# fail handler prints all of it for whichever test fails, so quiet mode drops +# the output of PASSING tests only. +# +# That invariant fails SILENTLY. It is only exercised when a test fails, so a +# green CI run proves nothing about it: a refactor of run_one's reader loop that +# also broke the dump would ship, and would be discovered by whoever next needed +# a red unit run diagnosed -- with no trace, having already lost the run. Hence +# a suite whose fixtures fail on purpose. +# +# Both directions are pinned, and the verbose one is the positive control for +# the quiet one: "no trace lines" is satisfied just as well by a harness where +# nothing ran at all. +# +# awk-transform constraint (hack/cozytest.sh rewrites this file before sourcing +# it, see the longer note in hack/cozytest-capture-gate.bats): a line beginning +# `@test "` becomes a function header wherever it appears, heredocs included, so +# a fixture written as a heredoc gets its own @test harvested into THIS suite. +# The fixtures below are built with printf, which puts that text inside a format +# string where no rule matches it. Titles must also stay distinctive in their +# [A-Za-z0-9] run, which is all that survives into the function name. +# +# Run with: hack/cozytest.sh hack/cozytest-trace-switch.bats +# ----------------------------------------------------------------------------- + +HACK_DIR="$(cd "$(dirname "${BATS_TEST_FILENAME:-$0}")" && pwd)" +RUNNER="$HACK_DIR/cozytest.sh" +REPO_ROOT="$(cd "$HACK_DIR/.." && pwd)" + +# Printed by the fixture from inside the test body. It reaches the job log by +# exactly two routes, the live stream and the fail handler's dump, which is what +# lets the quiet-mode test below tell those routes apart. +MARKER='cozytest-trace-switch-fixture-marker' + +# $1 = `pass` or `fail`. The failing fixture exercises the dump path under test. +# +# Named without an e2e- prefix on purpose. That prefix is what arms the runner's +# cluster captures (hack/cozytest-capture-gate.bats owns that gate), and a +# fixture that tripped them would spend the capture timeouts on every test here. +make_fixture() { + _dir=$(mktemp -d) + if [ "$1" = pass ]; then + printf '@test "fixture that passes and prints the marker" {\n echo %s\n}\n' \ + "$MARKER" >"$_dir/trace-fixture.bats" + else + printf '@test "fixture that prints the marker then fails" {\n echo %s\n false\n}\n' \ + "$MARKER" >"$_dir/trace-fixture.bats" + fi + printf '%s' "$_dir" +} + +# Output goes to a file rather than a variable, for the reason spelled out in +# hack/cozytest-capture-gate.bats: these suites can run under `set -x`, and a +# variable holding a fixture's output is expanded into the trace of whatever +# reads it, printing the fixture's deliberate failure into the job log where it +# reads as a real one. +# +# `env -u COZYTEST_TRACE` when $2 is empty, because the Makefile passes the +# variable as a command prefix and that EXPORTS it: a nested runner started from +# a suite that `make unit-tests` is itself running would inherit 0 and the +# default would never be under test. Verified: `sh -c 'COZYTEST_TRACE=0 sh -c +# printenv'` shows it in the grandchild. +run_fixture() { + _fdir=$1 _mode=$2 + if [ -z "$_mode" ]; then + env -u COZYTEST_TRACE "$RUNNER" "$_fdir/trace-fixture.bats" >"$_fdir/out" 2>&1 || true + else + COZYTEST_TRACE="$_mode" "$RUNNER" "$_fdir/trace-fixture.bats" >"$_fdir/out" 2>&1 || true + fi +} + +count_streamed_marker_lines() { + # A live line has a [mm:ss] timestamp; the failure dump has the same marker + # without one. Keep the pattern ASCII-only so tracing this assertion does not + # put the runner's decorative UTF-8 prefix into its own raw log. + grep -cE '[[][0-9][0-9]:[0-9][0-9][]].*cozytest-trace-switch-fixture-marker' "$1" || true +} + +@test "quiet mode streams no trace for a suite whose tests pass" { + dir=$(make_fixture pass) + run_fixture "$dir" 0 + # Positive control first: the test has to have run, or the absence below is + # satisfied by an empty output. + grep -qF 'Test OK' "$dir/out" + n=$(count_streamed_marker_lines "$dir/out") + # Spelled as an if rather than `! grep`: `set -e` is specified to ignore a + # command whose status is inverted with `!`, which would make the assertion + # vacuous -- the exact shape this suite exists to catch elsewhere. + if [ "$n" -ne 0 ]; then + echo "quiet mode still streamed $n trace line(s)" + cat "$dir/out" + exit 1 + fi + rm -rf "$dir" +} + +@test "the unset default stays verbose so the e2e call sites keep their stream" { + # The positive control for the test above, and a guard in its own right: the + # e2e suites in packages/core/testing/Makefile invoke the runner without the + # variable, and for a long suite that stream is the only progress signal, and + # the only record at all when a step timeout kills the job before the fail + # handler can run. Flipping the default silently takes that away. + dir=$(make_fixture pass) + run_fixture "$dir" '' + grep -qF 'Test OK' "$dir/out" + n=$(count_streamed_marker_lines "$dir/out") + if [ "$n" -eq 0 ]; then + echo "the default is no longer verbose; e2e lost its live stream" + cat "$dir/out" + exit 1 + fi + rm -rf "$dir" +} + +@test "a failing test still dumps its whole trace when the stream is quiet" { + # The load-bearing invariant. Quiet mode is only defensible because this dump + # survives it, and nothing else in the tree exercises the failure path. + dir=$(make_fixture fail) + run_fixture "$dir" 0 + grep -qF 'Test failed' "$dir/out" + grep -qF 'captured output' "$dir/out" + # The marker reaches the log by two routes and quiet mode closes one of them, + # so with no streamed copy present its appearance can only have come from the + # dump. That pairing is the assertion; either half alone is weaker. + n=$(count_streamed_marker_lines "$dir/out") + if [ "$n" -ne 0 ]; then + echo "expected no live trace in quiet mode, got $n line(s)" + exit 1 + fi + grep -qF "$MARKER" "$dir/out" + # The xtrace itself, not just the echoed output: the dump is worth having + # because it carries the commands, and `+ false` is the failing one. + grep -qF '+ false' "$dir/out" + rm -rf "$dir" +} + +@test "quiet mode still fails the run when a test fails" { + dir=$(make_fixture fail) + COZYTEST_TRACE=0 "$RUNNER" "$dir/trace-fixture.bats" >"$dir/out" 2>&1 && rc=0 || rc=$? + if [ "$rc" -eq 0 ]; then + echo "a failing suite exited 0 under quiet mode, so CI would go green on red" + exit 1 + fi + rm -rf "$dir" +} + +@test "quiet mode keeps the per test markers so a stuck test is still visible" { + # With the stream off these two lines are the only evidence of which test is + # in flight, which is what makes a hang diagnosable: a start with no matching + # end names the test that never returned. + dir=$(make_fixture pass) + run_fixture "$dir" 0 + grep -qF 'Run test:' "$dir/out" + grep -qF 'Test OK:' "$dir/out" + rm -rf "$dir" +} + +@test "the unit lane recipe asks for the quiet runner" { + # Without this the 31MB job log comes back the first time somebody tidies the + # recipe, and every test above keeps passing while it happens. + grep -qE '^COZYTEST_TRACE \?= 0' "$REPO_ROOT/Makefile" + grep -qF 'COZYTEST_TRACE=$(COZYTEST_TRACE) hack/cozytest.sh' "$REPO_ROOT/Makefile" +} + +@test "the e2e recipes do not silence their runner" { + # The other half of the design, and the half a well-meaning cleanup would + # break by making the two lanes consistent with each other. + # Matches an ASSIGNMENT, not any mention: documenting this design in a comment + # over there is expected and must not turn the guard red. The recipes are + # `docker exec ... sh -c '...'`, which does not carry host env either, so the + # variable structurally cannot reach those suites today -- this pins the + # recipe text so a future rewrite that does export it is caught. + e2e_mk="$REPO_ROOT/packages/core/testing/Makefile" + if grep -nE '^[^#]*COZYTEST_TRACE[[:space:]]*[:?+]?=' "$e2e_mk"; then + echo "an e2e recipe now sets COZYTEST_TRACE; those suites need the live stream" + exit 1 + fi + # Positive control: the file does invoke the runner, so the absence above is + # about the variable and not about a moved call site. + grep -qF 'hack/cozytest.sh hack/e2e-' "$e2e_mk" +} diff --git a/hack/cozytest.sh b/hack/cozytest.sh index b9ff82517..57a7db57a 100755 --- a/hack/cozytest.sh +++ b/hack/cozytest.sh @@ -9,6 +9,45 @@ TEST_FILE=${1:?Usage: ./cozytest.sh [pattern]} PATTERN=${2:-*} LINE='----------------------------------------------------------------' +# Live per-line streaming of each test's xtrace and command output, prefixed +# with a timestamp. Default on, because for a long e2e suite that stream is the +# only progress signal, and the only record at all when a step timeout or a dead +# runner kills the job before the fail handler below can dump anything. +# +# Set COZYTEST_TRACE=0 to keep only the per-test start/end lines. For a test that +# RETURNS, nothing diagnostic is lost: run_one tees the raw stream to $log and +# the fail handler prints all of it, so quiet mode drops the output of passing +# tests only -- which by definition did not establish the result. On the unit +# lane that is a ~40x cut (1338 tests: 239k lines/15M of which 98% was trace), +# and it is why the Makefile's bats-unit-tests target sets it. +# +# One exception, stated because it is the whole exposure quiet mode adds: the +# fail handler runs only after the pipeline returns, and there is no INT/TERM +# trap here, so a test killed rather than failed -- a hang reaped by the job's +# timeout-minutes, a SIGKILLed process group -- never dumps $log at all. The +# A start line with no matching end still names which test was in flight, but +# under quiet mode its trace is gone rather than already printed. +# +# An INT/TERM trap that flushed the tail of $log is the obvious repair and it +# does not work -- built, measured, reverted. POSIX sh defers a trap until the +# current foreground command returns, so installing one stops the runner from +# dying on the signal at all: a suite hung on `sleep 30` took 30s to exit with +# the trap versus 2s under the default disposition. GitHub's cancellation +# escalates INT, TERM, then KILL, so the deferred handler would be SIGKILLed +# before it ever ran -- no dump, and the grace period spent waiting. Making it +# work means running the test pipeline in the background and `wait`ing on it, +# since `wait` is the interruptible one; that is surgery on the path every +# suite in the repo takes, for a partial trace in a rare case. +# +# So the escape hatch stands instead: re-run that suite with COZYTEST_TRACE=1, +# which for the unit lane costs 48s and needs no cluster. That asymmetry is +# also why e2e keeps the stream on by default -- there, re-running is an hour +# and a live cluster, so the record has to be written as it goes. +# +# Anything other than the literal 0 leaves the stream on, so a typo fails +# open to the verbose behaviour rather than silently swallowing a suite. +COZYTEST_TRACE=${COZYTEST_TRACE:-1} + cols() { stty size 2>/dev/null | awk '{print $2}' || echo 80; } if [ -t 1 ]; then MAXW=$(( $(cols) - 12 )); [ "$MAXW" -lt 40 ] && MAXW=70 @@ -38,6 +77,7 @@ run_one() { ) printf '__RC__%s\n' "$?" } 2>&1 | tee "$log" | while IFS= read -r line; do + if [ "$COZYTEST_TRACE" = 0 ]; then continue; fi case "$line" in '__RC__'*) : ;; '+ '*) cmd=${line#'+ '} diff --git a/hack/e2e-capture-previous-logs.sh b/hack/e2e-capture-previous-logs.sh index 6ec4cf189..42c087f95 100755 --- a/hack/e2e-capture-previous-logs.sh +++ b/hack/e2e-capture-previous-logs.sh @@ -33,6 +33,14 @@ # omitted: an absent capture-notes.txt is indistinguishable from a capture that # never ran. # +# Ordering, where the cap binds: the failing test's namespace first, and within +# each namespace group the most recent restart first (prevlog_sort_recent). The +# restarts alive on a cluster at any moment span days, and install-time restarts +# have a head start on every app suite that runs afterwards, so without a time +# key the cap was routinely spent on containers that had already stopped +# restarting before the failing test began. Nothing is dropped for being old -- +# an install-time restart is the explanation when the install is what broke. +# # Usage: e2e-capture-previous-logs.sh [preferred-namespace] # # Environment: @@ -62,18 +70,21 @@ # Each takes text on stdin / in args and emits text -- no kubectl, no globals # # -- so hack/capture-previous-logs.bats can source this file (with # # E2E_CAPTURE_PREVLOGS_LIB set, see the guard below) and unit-test the # -# restart filtering, namespace prioritisation and capping against mock input # +# restart filtering, namespace prioritisation, recency ordering and capping # +# against mock input # # without a cluster. Keep them above the guard and free of any runtime state. # # --------------------------------------------------------------------------- # -# prevlog_filter_restarted: stdin = `ns|pod|container|kind|restartCount` rows -# (one container per line, as emitted by the kubectl go-template in main). +# prevlog_filter_restarted: stdin = `ns|pod|container|kind|restartCount|finishedAt` +# rows (one container per line, as emitted by the kubectl go-template in main). +# finishedAt is when the PREVIOUS instance terminated, and may be empty -- see +# prevlog_sort_recent. # Emits only the rows whose restartCount parses as an integer greater than # zero -- i.e. the containers that actually HAVE a previous instance to read. # A row whose count is empty, non-numeric or zero is dropped: asking for # `--previous` there is guaranteed to fail and would only add noise. prevlog_filter_restarted() { - while IFS='|' read -r ns pod container kind restarts; do + while IFS='|' read -r ns pod container kind restarts finished; do [ -n "$ns" ] && [ -n "$pod" ] && [ -n "$container" ] || continue # Reject anything that is not a bare non-negative integer before comparing. # This is not load-bearing for control flow -- `[ "" -gt 0 ]` exits 2, @@ -84,20 +95,85 @@ prevlog_filter_restarted() { '' | *[!0-9]*) continue ;; esac [ "$restarts" -gt 0 ] || continue - printf '%s|%s|%s|%s|%s\n' "$ns" "$pod" "$container" "$kind" "$restarts" + printf '%s|%s|%s|%s|%s|%s\n' "$ns" "$pod" "$container" "$kind" "$restarts" "$finished" done } +# prevlog_sort_recent: stdin = rows, stdout = the same rows, newest previous +# instance first, rows carrying no timestamp last, ties left in input order. +# +# Why this exists. prevlog_prioritize below keeps the cap from being spent on +# containers unrelated to the failing test, and until now "unrelated" meant only +# "in another namespace". Time was not part of it, so a container that restarted +# once during cluster bring-up competed on equal footing with one that +# crash-looped during the test -- and won whenever the list happened to reach it +# first. Measured on a live stand, the restarts present at any moment span days +# (a nine-day spread, measured on a development cluster), and in CI the +# install-time restarts have that head start: they exist before the first app +# suite runs, so every failed test afterwards pays for them. A restart that +# finished before the test began cannot explain the test's failure. +# +# Ordering, not filtering, and deliberately so: an install-time restart IS the +# explanation when the install is what broke, and this capture has no reference +# point for "when the test began" that would make a cutoff honest. Sorting costs +# nothing when the cap does not bind and picks the right dozen when it does. +# +# Lexicographic sort over RFC3339 UTC is chronological: kubectl renders these as +# fixed-width Z-suffixed strings, so no date parsing is needed. Reverse puts the +# newest first and, because the empty string sorts below every timestamp, leaves +# the rows whose lastState has already been dropped by the kubelet at the end. +# -s keeps equal timestamps in input order, which a node reboot produces in +# bulk; without it the order of a dozen simultaneous restarts would vary between +# runs. Rows with no timestamp at all therefore pass through untouched, which is +# also what keeps this a no-op for callers that pass 5-field rows. +prevlog_sort_recent() { + # LC_ALL=C because the key is a fixed-format ASCII timestamp: collation buys + # nothing here and a locale that reorders punctuation could only surprise. + # + # Falls back to the input order rather than to nothing. The caller compares + # row counts to report the cap, so a sort that died would otherwise be + # indistinguishable from a cap overflow -- it would report "0 of N captured, + # N more not captured" and send the reader looking for a cap that never + # fired. Ordering is an optimisation over which dozen rows to keep; losing it + # must not lose the rows. `sort -s` and the per-key `r` are both extensions + # (GNU, BSD and busybox all carry them, which is why this is a fallback and + # not a reimplementation), so this is the branch a stricter POSIX sort takes. + # Anything in the timestamp column that is not shaped like one is treated as + # undated. Two reasons, and the second is why this is not redundant with the + # template guard above it: `` sorts ABOVE every digit, so a single + # such row would take the front of the queue from the newest real restart; + # and the header prints this field verbatim, so a non-timestamp there becomes + # a claim about a time nothing observed. Normalising to empty puts the row + # last and prints nothing, which are both already handled paths. + # + # Only when the field exists: setting $6 on a five-field row would append a + # separator and change its shape. The pattern is spelled out character by + # character rather than with an interval like {4}, which older mawk does not + # support and Ubuntu's default awk is mawk. + _psr_rows=$(awk -F'|' -v OFS='|' \ + '{ if (NF >= 6 && $6 !~ /^[0-9][0-9][0-9][0-9]-[0-9][0-9]-[0-9][0-9]T/) $6 = ""; print }') + [ -n "$_psr_rows" ] || return 0 + if _psr_out=$(printf '%s\n' "$_psr_rows" | LC_ALL=C sort -s -t'|' -k6,6r 2>/dev/null); then + printf '%s\n' "$_psr_out" + else + echo "[capture-previous-logs] sort unavailable for recency ordering; keeping discovery order" >&2 + printf '%s\n' "$_psr_rows" + fi +} + # prevlog_prioritize: stdin = filtered rows, $1 = the failing test's namespace. # Emits the rows whose namespace matches $1 first, then everything else, each -# group keeping its input order. On a broadly degraded cluster the container cap -# below would otherwise be spent on unrelated cozy-* restarts while the pod the -# test actually failed on -- the whole reason we are here -- falls off the end. -# An empty $1 is a no-op passthrough. +# group ordered newest-restart-first by prevlog_sort_recent. On a broadly +# degraded cluster the container cap below would otherwise be spent on unrelated +# cozy-* restarts while the pod the test actually failed on -- the whole reason +# we are here -- falls off the end. Namespace stays the primary key and recency +# only breaks ties within a group: a stale restart in the failing test's own +# namespace is still likelier to be relevant than a fresh one three namespaces +# away. An empty $1 orders the whole input by recency. prevlog_prioritize() { _pp_ns="$1" if [ -z "$_pp_ns" ]; then - cat + prevlog_sort_recent return 0 fi # Buffer once, emit twice: stdin is consumable only once, and the two passes @@ -112,8 +188,8 @@ prevlog_prioritize() { # than closed, and a comment claiming otherwise is the kind of thing a later # reader trusts instead of rechecking. _pp_rows=$(cat) - printf '%s\n' "$_pp_rows" | awk -F'|' -v p="$_pp_ns" '$1 == p' || true - printf '%s\n' "$_pp_rows" | awk -F'|' -v p="$_pp_ns" 'NF && $1 != p' || true + printf '%s\n' "$_pp_rows" | awk -F'|' -v p="$_pp_ns" '$1 == p' | prevlog_sort_recent || true + printf '%s\n' "$_pp_rows" | awk -F'|' -v p="$_pp_ns" 'NF && $1 != p' | prevlog_sort_recent || true } # prevlog_cap: stdin = prioritised rows, $1 = max rows to keep. Emits at most $1 @@ -337,6 +413,19 @@ if ! command -v kubectl >/dev/null 2>&1; then exit 0 fi +# The finishedAt guard is three deep, and the innermost one is the load-bearing +# one: `finishedAt` is a metav1.Time behind `json:",omitempty"`, which cannot +# omit a struct, and its zero value marshals to `null`. The kubelet does +# synthesize a terminated state with no time -- ContainerStatusUnknown on a pod +# deleted mid-run, which also bumps restartCount and so clears the filter above. +# kubectl renders that leaf as the literal string ``, and `<` sorts +# ABOVE every digit, so under the reverse sort that row would land FIRST and +# displace the most recent real restart: the exact inversion this ordering +# exists to prevent. It would also print `previous instance ended `, +# a claim about a time nothing observed. Guarding the leaf collapses both +# shapes -- null, and the key absent -- into the empty-timestamp path that +# sorts last. Covered by the `` cases in hack/capture-previous-logs.bats. +# # One cluster-wide list call. Both initContainerStatuses and containerStatuses # are walked: an interrupted bootstrap that leaves the datadir half-written # lives in an init container, and that is exactly the instance whose log gets @@ -354,10 +443,10 @@ if ROWS=$($PREVLOG_LIST_BOUND kubectl get pods --all-namespaces -o go-template=' {{- $ns := .metadata.namespace -}} {{- $pod := .metadata.name -}} {{- range .status.initContainerStatuses -}} -{{ $ns }}|{{ $pod }}|{{ .name }}|init|{{ .restartCount }} +{{ $ns }}|{{ $pod }}|{{ .name }}|init|{{ .restartCount }}|{{ if .lastState }}{{ if .lastState.terminated }}{{ if .lastState.terminated.finishedAt }}{{ .lastState.terminated.finishedAt }}{{ end }}{{ end }}{{ end }} {{ end -}} {{- range .status.containerStatuses -}} -{{ $ns }}|{{ $pod }}|{{ .name }}|container|{{ .restartCount }} +{{ $ns }}|{{ $pod }}|{{ .name }}|container|{{ .restartCount }}|{{ if .lastState }}{{ if .lastState.terminated }}{{ if .lastState.terminated.finishedAt }}{{ .lastState.terminated.finishedAt }}{{ end }}{{ end }}{{ end }} {{ end -}} {{- end -}}' 2>"${LIST_ERR:-/dev/null}"); then LIST_RC=0 @@ -430,7 +519,7 @@ if [ "$KEPT" -gt 0 ] && [ "$TAIL" != "-1" ]; then log "every previous-instance log in this directory holds at most the last $TAIL lines (COZY_PREVLOG_TAIL=$TAIL); anything earlier was never requested" fi -printf '%s\n' "$SELECTED" | while IFS='|' read -r ns pod container kind restarts; do +printf '%s\n' "$SELECTED" | while IFS='|' read -r ns pod container kind restarts finished; do [ -n "$ns" ] || continue file="$OUT/$(prevlog_logfile_name "$ns" "$pod" "$container")" # --timestamps so these lines can be interleaved with the events and the @@ -586,11 +675,26 @@ printf '%s\n' "$SELECTED" | while IFS='|' read -r ns pod container kind restarts # trailing prose line breaks every parser that could read the file before. # Echo as well as archive. The archive is for later; the failing job's log is # where whoever is triaging the red run is already looking. + # + # When the previous instance ended is in the header because it is the first + # thing that decides whether this dump is worth reading: an instance that + # ended during cluster bring-up cannot explain a test that started afterwards, + # and until a reader knows that they have to read 200 lines to find out. It is + # also what prevlog_sort_recent ordered on, so the header shows the ordering + # rather than leaving it implicit. Omitted rather than guessed when the kubelet + # has already dropped the lastState -- "ended unknown" and "ended at 00:00" + # are not the same claim. + # # "last -1 lines" would be nonsense; -1 means the whole log was requested. - if [ "$TAIL" = "-1" ]; then - echo "----- previous logs: $ns/$pod [$kind $container] (restarts=$restarts, whole log) -----" + if [ -n "$finished" ]; then + _ended=", previous instance ended $finished" else - echo "----- previous logs: $ns/$pod [$kind $container] (restarts=$restarts, last $TAIL lines) -----" + _ended="" + fi + if [ "$TAIL" = "-1" ]; then + echo "----- previous logs: $ns/$pod [$kind $container] (restarts=$restarts$_ended, whole log) -----" + else + echo "----- previous logs: $ns/$pod [$kind $container] (restarts=$restarts$_ended, last $TAIL lines) -----" fi cat "$file" echo "----- end $ns/$pod [$container] -----" diff --git a/hack/e2e-chainsaw/.chainsaw.yaml b/hack/e2e-chainsaw/.chainsaw.yaml index 9eefab7c4..49c64066b 100644 --- a/hack/e2e-chainsaw/.chainsaw.yaml +++ b/hack/e2e-chainsaw/.chainsaw.yaml @@ -108,7 +108,11 @@ spec: # own pods first, so a broadly degraded cluster cannot spend the cap on # unrelated cozy-* restarts); it never restricts it. tenant-test is the # namespace every app suite runs in, declared under `namespace.name` - # above. + # above. Within each namespace group the helper orders by how recently + # the previous instance ended, so the install-time restarts that exist + # before any app suite runs no longer displace one that happened during + # the failing test. Also ordering only -- an install-time restart is + # the explanation when the install is what broke. if [ -x ../../e2e-capture-previous-logs.sh ]; then timeout -k 30 300 ../../e2e-capture-previous-logs.sh \ "${snap}/previous-logs" "${COZY_TEST_NAMESPACE:-tenant-test}" 2>&1