From fdb2e89fe7b49216f2f09382f0c56b902d138e7b Mon Sep 17 00:00:00 2001 From: Myasnikov Daniil Date: Thu, 27 Aug 2026 11:08:15 +0500 Subject: [PATCH 1/7] test(unit): make the bats trace stream opt-in, quiet on the unit lane MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit hack/cozytest.sh runs every @test body under `set -x` and streams the trace live. Across the ~40 hack/*.bats unit suites that is 233,444 of 238,794 lines - 98% of a 31 MB job log - and the single failing assertion sits at line 238,573 of it. The web log viewer is unusable at that size, and anyone (or anything) reading the job to find out what broke pays for the whole file first. Nothing in that stream is load-bearing on the unit lane. run_one already tees the raw output to $log and the fail handler dumps all of it for whichever test fails, so suppressing the live stream drops the output of PASSING tests only. Add COZYTEST_TRACE, default 1 so the e2e call sites in packages/core/testing/Makefile keep the live stream - there it 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 can run. The bats-unit-tests target sets 0; running the runner by hand stays verbose, which is the case where a human is actually watching. Measured on 25 suites locally, quiet vs verbose: 29,528 -> 951 lines, 3.9 MB -> 94 KB, and 71s -> 48s wall, the last because the per-line formatter forks date twice for every line it prints. Quiet output is byte-for-byte the non-trace subset of verbose, and a hanging test still shows as a ╭ with no matching ╰. Assisted-By: Claude Signed-off-by: Myasnikov Daniil --- Makefile | 12 +++++++++++- hack/cozytest.sh | 18 ++++++++++++++++++ 2 files changed, 29 insertions(+), 1 deletion(-) diff --git a/Makefile b/Makefile index cf0b39b42..ecdb63a09 100644 --- a/Makefile +++ b/Makefile @@ -160,6 +160,16 @@ 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 ╭/╰ lines and still dumps +# the full trace of whichever test fails. 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 +177,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/cozytest.sh b/hack/cozytest.sh index b9ff82517..00c82e578 100755 --- a/hack/cozytest.sh +++ b/hack/cozytest.sh @@ -9,6 +9,23 @@ TEST_FILE=${1:?Usage: ./cozytest.sh [pattern]} PATTERN=${2:-*} LINE='----------------------------------------------------------------' +# Live per-line streaming of each test's xtrace and command output, prefixed +# ┊[mm:ss]. 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 ╭/╰ lines. Nothing +# diagnostic is lost: run_one tees the raw stream to $log and a failing test +# prints all of it from the fail handler, 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. +# A hanging test still shows up as a ╭ with no matching ╰. +# +# 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 +55,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#'+ '} From 77418431782df1988835e0086f58a37b5800a744 Mon Sep 17 00:00:00 2001 From: Myasnikov Daniil Date: Thu, 27 Aug 2026 12:09:02 +0500 Subject: [PATCH 2/7] test(e2e): order previous-instance log capture by restart recency The container cap (COZY_PREVLOG_MAX=12) is spent in namespace order, and "unrelated" has meant only "in another namespace" - time was never a key. 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 pod list reached it first. Two measured e2e jobs spent 1034 and 1545 lines on virt-api and cdi-apiserver, restarted once at install time by `Unable to create certwatcher` hours before any app suite ran; on a development cluster 178 containers carried a restart, their timestamps spanning 24 days, so the cap binds hard enough for the order to decide everything. Ordering, not filtering, and deliberately: 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. Namespace stays the primary key - a stale restart in the namespace under test beats a fresh one three namespaces away. So this fixes cap displacement, not the raw volume of any single run. lastState.terminated.finishedAt joins the row, guarded so a missing lastState cannot error the list call and fail the capture open (verified against a live cluster: no , empty where the kubelet has already dropped it). Reading it also fixes a latent bug the sixth field would otherwise have caused - `read -r ... restarts` folds a trailing field into the last variable, so the dump header would have printed `restarts=1|2026-08-22T09:06:00Z`. It now names the time instead, which is the first thing that decides whether the dump is worth reading. Sorting is lexicographic over fixed-width RFC3339 UTC, so no date parsing: reverse puts newest first and leaves undated rows last, and -s keeps a node reboot's simultaneous restarts in input order so the selection is comparable between runs. Rows with no timestamp pass through untouched, which is what makes this a no-op for the existing five-field fixtures. Five tests added; both mutations are caught (a passthrough sort_recent, and dropping -s - the latter by the pre-existing namespace test). capture-previous-logs 39/39, cozyreport 184/184, bats-no-exit-trap 22/22. Assisted-By: Claude Signed-off-by: Myasnikov Daniil --- hack/capture-previous-logs.bats | 105 +++++++++++++++++++++++++++++- hack/e2e-capture-previous-logs.sh | 96 ++++++++++++++++++++++----- hack/e2e-chainsaw/.chainsaw.yaml | 6 +- 3 files changed, 186 insertions(+), 21 deletions(-) diff --git a/hack/capture-previous-logs.bats b/hack/capture-previous-logs.bats index bb39d2683..12f57d23a 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,102 @@ 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. + rows="$(printf '%s\n' \ + 'ns|first|c|container|1|2026-08-17T13:07:28Z' \ + 'ns|second|c|container|1|2026-08-17T13:07:28Z' \ + 'ns|third|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)" = "first" ] + [ "$(printf '%s\n' "$out" | sed -n '2p' | cut -d'|' -f2)" = "second" ] + [ "$(printf '%s\n' "$out" | sed -n '3p' | cut -d'|' -f2)" = "third" ] +} + +@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. + rows="$(printf '%s\n' \ + 'ns|p1|c|container|1' \ + 'ns|p2|c|container|1' \ + 'ns|p3|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 "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' \ diff --git a/hack/e2e-capture-previous-logs.sh b/hack/e2e-capture-previous-logs.sh index 6ec4cf189..97cb72ba9 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 the install-time ones +# 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,54 @@ 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 restarts +# are the ones with a 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() { + sort -s -t'|' -k6,6r +} + # 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 +157,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 @@ -354,10 +399,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 }}{{ .lastState.terminated.finishedAt }}{{ end }}{{ end }} {{ end -}} {{- range .status.containerStatuses -}} -{{ $ns }}|{{ $pod }}|{{ .name }}|container|{{ .restartCount }} +{{ $ns }}|{{ $pod }}|{{ .name }}|container|{{ .restartCount }}|{{ if .lastState }}{{ if .lastState.terminated }}{{ .lastState.terminated.finishedAt }}{{ end }}{{ end }} {{ end -}} {{- end -}}' 2>"${LIST_ERR:-/dev/null}"); then LIST_RC=0 @@ -430,7 +475,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 +631,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 From 599ace69fdf94d9ba5681d11b4c9410f4c2bd413 Mon Sep 17 00:00:00 2001 From: Myasnikov Daniil Date: Thu, 27 Aug 2026 18:15:30 +0500 Subject: [PATCH 3/7] test(tests): guard the COZYTEST_TRACE switch against silent regression The quiet unit lane rests on one invariant: run_one tees the raw stream to $log and the fail handler prints all of it for whichever test fails, so suppressing the live stream drops the output of PASSING tests only. That invariant fails silently. It is exercised only 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 found by whoever next needed a red unit run diagnosed, with no trace and the run already lost. Nothing in the tree covered it. Seven tests, fixtures that fail on purpose, following the structure of hack/cozytest-capture-gate.bats: - quiet mode streams no trace for a passing suite - the unset default stays verbose, which is what the e2e call sites in packages/core/testing/Makefile rely on - a failing test still dumps its whole trace under quiet mode, xtrace included, which is the load-bearing one - quiet mode still fails the run - the per-test start/end markers survive, so a hang still names the test that never returned - the unit recipe asks for the quiet runner - the e2e recipes do not silence theirs Every one is mutation-proven: removing the fail-handler dump, flipping the default, making the switch a no-op, dropping the variable from the unit recipe, adding it to an e2e recipe, and swallowing the exit code are each caught by exactly one test. The last of those is worth a note - it disables the mechanism the outer runner uses to report failure, so the run exits 0 while the failure is in its output. A probe keyed on the exit code alone reads that as uncaught. Two traps are recorded in the file's header rather than left to be rediscovered. Fixtures are built with printf because the awk transform harvests a heredoc's own @test line into the suite that contains it. And the default is asserted under `env -u COZYTEST_TRACE`, because the Makefile passes the variable as a command prefix, which exports it - a nested runner started from a suite that `make unit-tests` is running would otherwise inherit 0 and the default would never be under test. Assisted-By: Claude Signed-off-by: Myasnikov Daniil --- hack/cozytest-trace-switch.bats | 184 ++++++++++++++++++++++++++++++++ 1 file changed, 184 insertions(+) create mode 100644 hack/cozytest-trace-switch.bats diff --git a/hack/cozytest-trace-switch.bats b/hack/cozytest-trace-switch.bats new file mode 100644 index 000000000..1f2be210d --- /dev/null +++ b/hack/cozytest-trace-switch.bats @@ -0,0 +1,184 @@ +#!/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' + +# The trace prefix run_one puts on every streamed line. +TRACE_GLYPH='┊' + +# $1 = fixture basename, $2 = `pass` or `fail`. A failing fixture is the default +# case here: the dump under test only exists on the failure path. +# +# 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 [ "$2" = 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_trace_lines() { + grep -cF "$TRACE_GLYPH" "$1" || true +} + +@test "quiet mode streams no trace for a suite whose tests pass" { + dir=$(make_fixture trace-fixture.bats 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_trace_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 trace-fixture.bats pass) + run_fixture "$dir" '' + grep -qF 'Test OK' "$dir/out" + n=$(count_trace_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 trace-fixture.bats 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 zero trace lines present its appearance can only have come from the + # dump. That pairing is the assertion; either half alone is weaker. + n=$(count_trace_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 trace-fixture.bats 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 trace-fixture.bats 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. + e2e_mk="$REPO_ROOT/packages/core/testing/Makefile" + if grep -n 'COZYTEST_TRACE' "$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" +} From a5c90d984e2179660015114988cc3d475cfb1bd6 Mon Sep 17 00:00:00 2001 From: Myasnikov Daniil Date: Thu, 27 Aug 2026 22:03:19 +0500 Subject: [PATCH 4/7] fix(tests): guard the finishedAt leaf and make three guards actually bite Findings from two independent adversarial reviews of the preceding two commits. Each was reproduced locally before being fixed. The ordering inverted itself on a shape I had not probed. `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 restart filter). Two guards deep left the leaf exposed, and kubectl renders it as the literal `` -- which sorts ABOVE every digit, so that row took the front of the queue from the most recent real restart, and the header printed `previous instance ended `, a claim about a time nothing observed. Verified with a text/template probe over seven lastState shapes: `null` and a missing key both produced it. Fixed at both layers, because they fail independently. The template now guards the leaf, so the string cannot be produced. And the sort normalises any field-6 value not shaped like a timestamp to empty, so the ordering stays correct and the header stays quiet even if some other producer emits one. Earlier verification against a live cluster showed no `` and I read that as the guard being right; it only meant no container on that cluster was in that state. Three guards did not bite: - both stability fixtures were pre-sorted ascending, which is exactly what sort's last-resort whole-line compare reproduces with no -s at all, so the tests written for -s passed without it. Reversed; they now fail when -s is dropped. - no test fed a six-field row through the whole script, so the timestamp reached the dump header uncovered -- deleting the read variable left the suite green at 39/39. One integration test now asserts the header names the time. - the e2e guard matched any mention of COZYTEST_TRACE, so documenting the design over there would have turned it red. It now matches an assignment, and tolerating a comment is verified too. Also: a failed sort no longer discards a whole namespace group. The caller compares row counts to report the cap, so losing a group silently became "0 of N captured, N more not captured" and sent the reader after a cap that never fired. It falls back to discovery order and says so. LC_ALL=C on the sort, since the key is fixed-format ASCII. And the claim itself was too strong. "Nothing diagnostic is lost" holds only for a test that RETURNS: the fail handler runs after the pipeline, and there is no INT/TERM trap, so a test killed rather than failed -- a hang reaped by the job timeout -- never dumps its log, and under quiet mode its trace is gone rather than already printed. The comments in hack/cozytest.sh and the Makefile now say so and name the escape hatch. A trap that flushed the tail of the log would close it; left out deliberately rather than bundled in here. Every fix is mutation-proven: reverting the leaf guard, removing the key normalisation, dropping the read variable, dropping -s, and silencing an e2e recipe are each caught. Unit lane 1513 passed, 1 failed (hack/ghcr-mirror_test.bats, which reads a live cluster and fails the same way under main's runner). Assisted-By: Claude Assisted-By: GPT-5 Signed-off-by: Myasnikov Daniil --- Makefile | 5 +- hack/capture-previous-logs.bats | 85 ++++++++++++++++++++++++++++--- hack/cozytest-trace-switch.bats | 7 ++- hack/cozytest.sh | 22 +++++--- hack/e2e-capture-previous-logs.sh | 54 ++++++++++++++++++-- 5 files changed, 151 insertions(+), 22 deletions(-) diff --git a/Makefile b/Makefile index ecdb63a09..afa242da2 100644 --- a/Makefile +++ b/Makefile @@ -163,7 +163,10 @@ 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 ╭/╰ lines and still dumps -# the full trace of whichever test fails. Override to watch a run line by +# 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 diff --git a/hack/capture-previous-logs.bats b/hack/capture-previous-logs.bats index 12f57d23a..d92b6fa81 100644 --- a/hack/capture-previous-logs.bats +++ b/hack/capture-previous-logs.bats @@ -203,26 +203,32 @@ E2E_CAPTURE_PREVLOGS_LIB=1 # 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|first|c|container|1|2026-08-17T13:07:28Z' \ - 'ns|second|c|container|1|2026-08-17T13:07:28Z' \ - 'ns|third|c|container|1|2026-08-17T13:07:28Z')" + '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)" = "first" ] - [ "$(printf '%s\n' "$out" | sed -n '2p' | cut -d'|' -f2)" = "second" ] - [ "$(printf '%s\n' "$out" | sed -n '3p' | cut -d'|' -f2)" = "third" ] + [ "$(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|p1|c|container|1' \ + 'ns|p3|c|container|1' \ 'ns|p2|c|container|1' \ - 'ns|p3|c|container|1')" + 'ns|p1|c|container|1')" out="$(printf '%s\n' "$rows" | prevlog_sort_recent)" @@ -271,6 +277,69 @@ E2E_CAPTURE_PREVLOGS_LIB=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' \ diff --git a/hack/cozytest-trace-switch.bats b/hack/cozytest-trace-switch.bats index 1f2be210d..bd4dc21ed 100644 --- a/hack/cozytest-trace-switch.bats +++ b/hack/cozytest-trace-switch.bats @@ -173,8 +173,13 @@ count_trace_lines() { @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 -n 'COZYTEST_TRACE' "$e2e_mk"; then + 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 diff --git a/hack/cozytest.sh b/hack/cozytest.sh index 00c82e578..7d31762c9 100755 --- a/hack/cozytest.sh +++ b/hack/cozytest.sh @@ -14,13 +14,21 @@ LINE='----------------------------------------------------------------' # 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 ╭/╰ lines. Nothing -# diagnostic is lost: run_one tees the raw stream to $log and a failing test -# prints all of it from the fail handler, 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. -# A hanging test still shows up as a ╭ with no matching ╰. +# Set COZYTEST_TRACE=0 to keep only the per-test ╭/╰ 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 +# ╭ with no matching ╰ still names which test was in flight, but under quiet +# mode its trace is gone rather than already printed. A trap that flushed the +# tail of $log would close this; until then the escape hatch is re-running that +# suite with COZYTEST_TRACE=1, which for the unit lane costs 48s and no cluster. # # 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. diff --git a/hack/e2e-capture-previous-logs.sh b/hack/e2e-capture-previous-logs.sh index 97cb72ba9..1f7f7425e 100755 --- a/hack/e2e-capture-previous-logs.sh +++ b/hack/e2e-capture-previous-logs.sh @@ -36,7 +36,8 @@ # 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 the install-time ones -# have a head start on every app suite that runs afterwards, so without a time +# 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. @@ -108,7 +109,7 @@ prevlog_filter_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 restarts +# (a nine-day spread, measured on a development cluster), and in CI the # are the ones with a 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. @@ -127,7 +128,37 @@ prevlog_filter_restarted() { # 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() { - sort -s -t'|' -k6,6r + # 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 }') + 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. @@ -382,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 @@ -399,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 }}|{{ if .lastState }}{{ if .lastState.terminated }}{{ .lastState.terminated.finishedAt }}{{ end }}{{ end }} +{{ $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 }}|{{ if .lastState }}{{ if .lastState.terminated }}{{ .lastState.terminated.finishedAt }}{{ end }}{{ end }} +{{ $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 From 76d397523b6de9ff0a965c248444bab413bc41dd Mon Sep 17 00:00:00 2001 From: Myasnikov Daniil Date: Thu, 27 Aug 2026 22:30:18 +0500 Subject: [PATCH 5/7] docs(tests): record why an INT/TERM trap cannot cover a killed test The comment added with the trace switch pointed at a signal trap as the fix for the one case quiet mode does not cover: a test killed rather than failed never reaches the fail handler, so its trace is gone rather than already printed. That advice is wrong, and wrong in a way that costs whoever follows it. POSIX sh defers a trap until the current foreground command returns, so installing an INT/TERM handler stops the runner dying on the signal at all. Measured: a suite hung on `sleep 30` exits in 30s with the trap installed against 2s under the default disposition. GitHub's cancellation escalates INT, TERM, then KILL, so the deferred handler gets SIGKILLed before it runs -- no dump, and the grace period spent waiting for a hang. Built it, measured it, reverted it. Making it work means running the test pipeline in the background and waiting on it, because `wait` is the interruptible one. That is surgery on the path every suite in this repo takes, unit and e2e, to recover a partial trace in a rare case that already has a 48-second escape hatch. Not taken; recorded so the next reader does not spend the afternoon finding out the same way. Assisted-By: Claude Signed-off-by: Myasnikov Daniil --- hack/cozytest.sh | 20 +++++++++++++++++--- 1 file changed, 17 insertions(+), 3 deletions(-) diff --git a/hack/cozytest.sh b/hack/cozytest.sh index 7d31762c9..ddc02196a 100755 --- a/hack/cozytest.sh +++ b/hack/cozytest.sh @@ -26,9 +26,23 @@ LINE='----------------------------------------------------------------' # 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 # ╭ with no matching ╰ still names which test was in flight, but under quiet -# mode its trace is gone rather than already printed. A trap that flushed the -# tail of $log would close this; until then the escape hatch is re-running that -# suite with COZYTEST_TRACE=1, which for the unit lane costs 48s and no cluster. +# 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. From e949f398009c4c9f4952308bb015e8ca4231a714 Mon Sep 17 00:00:00 2001 From: Myasnikov Daniil Date: Fri, 28 Aug 2026 15:29:29 +0500 Subject: [PATCH 6/7] fix(e2e): preserve previous-log cap slots Assisted-By: GPT-5 Signed-off-by: Myasnikov Daniil --- hack/capture-previous-logs.bats | 23 +++++++++++++++++++++++ hack/e2e-capture-previous-logs.sh | 12 ++++++------ 2 files changed, 29 insertions(+), 6 deletions(-) diff --git a/hack/capture-previous-logs.bats b/hack/capture-previous-logs.bats index d92b6fa81..30439f088 100644 --- a/hack/capture-previous-logs.bats +++ b/hack/capture-previous-logs.bats @@ -598,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/e2e-capture-previous-logs.sh b/hack/e2e-capture-previous-logs.sh index 1f7f7425e..42c087f95 100755 --- a/hack/e2e-capture-previous-logs.sh +++ b/hack/e2e-capture-previous-logs.sh @@ -35,9 +35,8 @@ # # 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 the install-time ones -# install-time restarts have a head start on every app suite that runs -# afterwards, so without a time +# 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. @@ -110,9 +109,9 @@ prevlog_filter_restarted() { # 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 -# are the ones with a 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. +# 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 @@ -153,6 +152,7 @@ prevlog_sort_recent() { # 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 From c88da1813993f651a577caecd1600dfa011d7a46 Mon Sep 17 00:00:00 2001 From: Myasnikov Daniil Date: Fri, 28 Aug 2026 15:31:22 +0500 Subject: [PATCH 7/7] test(tests): keep trace switch suite ASCII-only Assisted-By: GPT-5 Signed-off-by: Myasnikov Daniil --- Makefile | 2 +- hack/cozytest-trace-switch.bats | 37 ++++++++++++++++----------------- hack/cozytest.sh | 10 ++++----- 3 files changed, 24 insertions(+), 25 deletions(-) diff --git a/Makefile b/Makefile index afa242da2..8e07a1bb9 100644 --- a/Makefile +++ b/Makefile @@ -162,7 +162,7 @@ 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 ╭/╰ lines and still dumps +# 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. diff --git a/hack/cozytest-trace-switch.bats b/hack/cozytest-trace-switch.bats index bd4dc21ed..5208ff2c1 100644 --- a/hack/cozytest-trace-switch.bats +++ b/hack/cozytest-trace-switch.bats @@ -39,18 +39,14 @@ REPO_ROOT="$(cd "$HACK_DIR/.." && pwd)" # lets the quiet-mode test below tell those routes apart. MARKER='cozytest-trace-switch-fixture-marker' -# The trace prefix run_one puts on every streamed line. -TRACE_GLYPH='┊' - -# $1 = fixture basename, $2 = `pass` or `fail`. A failing fixture is the default -# case here: the dump under test only exists on the failure path. +# $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 [ "$2" = pass ]; then + if [ "$1" = pass ]; then printf '@test "fixture that passes and prints the marker" {\n echo %s\n}\n' \ "$MARKER" >"$_dir/trace-fixture.bats" else @@ -80,17 +76,20 @@ run_fixture() { fi } -count_trace_lines() { - grep -cF "$TRACE_GLYPH" "$1" || true +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 trace-fixture.bats 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_trace_lines "$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. @@ -108,10 +107,10 @@ count_trace_lines() { # 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 trace-fixture.bats pass) + dir=$(make_fixture pass) run_fixture "$dir" '' grep -qF 'Test OK' "$dir/out" - n=$(count_trace_lines "$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" @@ -123,14 +122,14 @@ count_trace_lines() { @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 trace-fixture.bats fail) + 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 zero trace lines present its appearance can only have come from the + # 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_trace_lines "$dir/out") + 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 @@ -143,7 +142,7 @@ count_trace_lines() { } @test "quiet mode still fails the run when a test fails" { - dir=$(make_fixture trace-fixture.bats fail) + 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" @@ -156,10 +155,10 @@ count_trace_lines() { # 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 trace-fixture.bats pass) + dir=$(make_fixture pass) run_fixture "$dir" 0 - grep -qF '╭ » Run test:' "$dir/out" - grep -qF '✅ Test OK' "$dir/out" + grep -qF 'Run test:' "$dir/out" + grep -qF 'Test OK:' "$dir/out" rm -rf "$dir" } diff --git a/hack/cozytest.sh b/hack/cozytest.sh index ddc02196a..57a7db57a 100755 --- a/hack/cozytest.sh +++ b/hack/cozytest.sh @@ -10,11 +10,11 @@ PATTERN=${2:-*} LINE='----------------------------------------------------------------' # Live per-line streaming of each test's xtrace and command output, prefixed -# ┊[mm:ss]. 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 +# 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 ╭/╰ lines. For a test that +# 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 @@ -25,8 +25,8 @@ LINE='----------------------------------------------------------------' # 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 -# ╭ with no matching ╰ still names which test was in flight, but under quiet -# mode its trace is gone rather than already printed. +# 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