Skip to content

Commit 67b4e23

Browse files
test(tests): cut the noise in unit and e2e job logs (#3973)
## What this PR does Unit test job log is 238,794 lines and 31MB, and 233,444 of those are `set -x` trace from `hack/cozytest.sh`. The one failing assertion sits at line 238,573. Nothing in that stream is needed there, `run_one` already tees raw output to `$log` and the fail handler dumps all of it for whichever test fails, so dropping the live stream loses output of passing tests only. `COZYTEST_TRACE` defaults to 1, so e2e call sites in `packages/core/testing/Makefile` keep the live stream. 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 runs. `bats-unit-tests` sets 0. Running the runner by hand stays verbose, that is the case where a human is actually watching. Second thing, previous-instance log capture now orders by restart recency. Container cap (`COZY_PREVLOG_MAX=12`) is spent in namespace order and "unrelated" meant only "in another namespace", time was never a key. So a container that restarted once during 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`, both restarted once at install time by `Unable to create certwatcher`, hours before any app suite ran. On a live stand 178 containers carry a restart and their timestamps span 24 days, so the cap binds hard enough for order to decide everything. This orders, it does not filter. Install-time restart is the explanation when install is what broke, and the capture has no reference point for "when the test began" that would make a cutoff honest. Namespace stays primary key, because a stale restart in the namespace under test beats a fresh one three namespaces away. So it fixes cap displacement, not raw volume of a single run. `lastState.terminated.finishedAt` joins the row. The guard on it is three deep and the innermost one is load bearing, which I got wrong first time round and review caught: `finishedAt` is a metav1.Time behind `json:",omitempty"`, omitempty cannot omit a struct, and the 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. kubectl renders that leaf as the literal `<no value>`, and `<` sorts above every digit, so under the reverse sort that row landed FIRST and displaced the most recent real restart. Exactly the inversion the ordering exists to prevent, plus a header reading `previous instance ended <no value>`. Fixed at both layers because they fail independently: the template guards the leaf so the string cannot be produced, and the sort normalises any field that is not shaped like a timestamp to empty so the ordering holds even if some other producer emits one. Worth naming how that slipped through. I probed the template against a live cluster, saw no `<no value>`, and read it as the guard being correct. It only meant no container on that cluster was in that state. Reading the field also fixes a latent bug it would otherwise have caused: `read -r ... restarts` folds a trailing field into the last variable, so the dump header would print `restarts=1|2026-08-22T09:06:00Z`. Now it names the time, which is the first thing telling a reader whether the dump predates the test. ### What quiet mode keeps and what it drops Two things are dropped, and the second one came out of review rather than out of me. First, xtrace and stdout of tests that pass. You cannot diff a passing test's trace against the failing one inside the same job log, and a warning printed by a test that passed is gone. Second, a test that is KILLED rather than failed loses its trace as well. The fail handler runs only after the pipeline returns, so a hang reaped by the job timeout never dumps anything, and quiet mode has by then dropped the live stream. Verbose mode never noticed, because the trace was already printed. Measured: verbose leaves the line the test blocked on, quiet leaves the `╭` and nothing else. So this one is a real regression on the unit lane, not a pre-existing gap. An INT/TERM trap is the obvious repair and it does not work. POSIX sh defers a trap until the current foreground command returns, so installing one stops the runner dying on the signal at all: a suite hung on `sleep 30` took 30s to exit with the trap against 2s under the default disposition. GitHub escalates INT, then TERM, then KILL, so the deferred handler gets SIGKILLed before it ever runs, and the grace period goes on waiting for the hang. Built it, measured it, reverted it, and the measurement is in the comment now so the next reader does not repeat it. Making it work needs the test pipeline moved into the background with `wait`, which is the interruptible one, and that is surgery on the path every suite in this repo takes for a partial trace in a rare case. What is left for that case is the escape hatch below, which for this lane costs 48s and no cluster. The same argument is why e2e keeps the stream on: re-running there is an hour and a live cluster, so the record has to be written as it goes. Everything else stays. The `╭`/`╰` pair per test with elapsed time, so which tests ran, in what order and how long each took is all still there. Full trace, stdout and stderr of the failing test, same bytes as before, because `run_one` tees to `$log` and the fail handler dumps it, and that path is untouched. Anything printed outside `run_one` as well, file level code, `.bats` parse errors, and the `--- running <file> ---` markers. A hang still shows up as `╭` with no matching `╰`. And `make unit-tests` stops at the first failing test anyway, so there was never more than one dump to read. Measured on a suite that is actually red (`hack/ghcr-mirror_test.bats` fails on my machine because it reads a live cluster): verbose 1472 lines, quiet 63 lines, and the post-failure dump is 23 lines and byte-identical in both modes. Getting the trace back, both paths checked: ``` COZYTEST_TRACE=1 make unit-tests # env prefix, 29200 trace lines make unit-tests COZYTEST_TRACE=1 # make cmdline, same hack/cozytest.sh hack/foo.bats # by hand, verbose by default ``` This lane needs no cluster and runs locally in 48s, so anyone who wants the trace just reruns it. That is exactly why the same argument does not extend to e2e, and why the default stays 1 there. Nothing else consumed that stream. Unit lane stdout goes only to the job log, `cozyreport.sh` folds in crust-gather snapshots and the trap writes those to disk independently, and the unit lane produces none of them. ### Verification Measured on this PR's own run: unit job went from 238,794 lines and 31MB with 233,444 trace lines, to 5,720 lines and 580KB with 0 trace lines and 1548 tests OK. Those two totals are not strictly like for like, the old run was red and this one is green, so the honest comparator is 233,444 trace lines down to 0. Quiet output is byte-for-byte the non-trace subset of verbose, and the fail handler dump is unaffected (checked with a deliberately failing suite). Verbose output unchanged against main, byte-identical sorted on `hack/bats-no-exit-trap.bats`. Other suites are not self-stable run to run (temp names, epochs, stdout/stderr interleaving) so that is the ceiling on that check, not a finding. Eight tests on the capture and seven on the switch. Every fix is mutation proven: reverting the template leaf guard, removing the sort key normalisation, dropping the read variable, dropping `-s`, silencing an e2e recipe, removing the fail handler dump, flipping the default, and making the switch a no-op are each caught. Three of those guards did not bite when first written, which review also found: both stability fixtures were pre-sorted ascending, which is what sort's last-resort whole-line compare reproduces with no `-s` at all, and no test fed a six-field row through the whole script, so deleting the read variable left the suite green at 39/39. Whole unit lane, 83 files, 1503 passed and 1 failed. The failure is `hack/ghcr-mirror_test.bats`, it reads a live cluster and fails identically under main's own runner. ### Screenshots Not a UI change. ### Downstream repositories Walked the trigger map file by file against the diff. Nothing under `hack/` is moved or renamed, no make target changes what it does (`bats-unit-tests` runs the same files to the same verdict, only quieter), and `hack/package.mk`, `hack/common-envs.mk`, `hack/update-crd.sh` and `hack/e2e-prepare-cluster.bats` are untouched, which is what ccp, external-apps-example, talm and ansible-cozystack couple to. No package `values.yaml`, `values.schema.json`, CRD, namespace, label, annotation or metric name is involved. - [x] No downstream repository is affected by this change ### Release note ```release-note test(tests): bats unit test trace is now opt-in via COZYTEST_TRACE and quiet by default in `make unit-tests`, and the e2e previous-instance log capture now picks the most recently restarted containers first ``` <!-- This is an auto-generated comment: release notes by coderabbit.ai --> ## Summary by CodeRabbit - **Improvements** - Test runs can suppress live trace output for passing tests while preserving full diagnostics for failures. - Trace visibility can be customized through the test configuration. - Previous-instance logs are prioritized by the most recent container termination within the preferred namespace. - Captured log headers now show when the previous instance ended. - Undated logs are retained and placed after dated entries. - **Tests** - Added coverage for trace controls, failure handling, and recent-log ordering. <!-- end of auto-generated comment: release notes by coderabbit.ai -->
2 parents 5688b3c + c88da18 commit 67b4e23

6 files changed

Lines changed: 563 additions & 21 deletions

File tree

‎Makefile‎

Lines changed: 14 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -160,14 +160,27 @@ test-check-readiness:
160160
# (e.g. to use `find ... -print0 | xargs -0`).
161161
BATS_UNIT_FILES := $(filter-out hack/e2e-%.bats,$(wildcard hack/*.bats))
162162

163+
# Quiet by default: cozytest.sh streams every test's xtrace live, which over
164+
# this many suites buried the one failing assertion under ~240k lines of
165+
# trace in CI. COZYTEST_TRACE=0 keeps the per-test start/end lines and still dumps
166+
# the full trace of whichever test FAILS -- but not of one that is killed
167+
# instead, a hang reaped by the job timeout among them, since the dump runs
168+
# after the test returns. See the COZYTEST_TRACE comment in hack/cozytest.sh.
169+
# Override to watch a run line by
170+
# line: `COZYTEST_TRACE=1 make bats-unit-tests`, or invoke the runner
171+
# directly (`hack/cozytest.sh hack/foo.bats [pattern]`), which stays verbose.
172+
# The e2e call sites in packages/core/testing/Makefile are untouched and keep
173+
# the live stream -- see the COZYTEST_TRACE comment in hack/cozytest.sh.
174+
COZYTEST_TRACE ?= 0
175+
163176
bats-unit-tests:
164177
@if [ -z "$(BATS_UNIT_FILES)" ]; then \
165178
echo "ERROR: no hack/*.bats unit test files found"; \
166179
exit 1; \
167180
fi
168181
@for f in $(BATS_UNIT_FILES); do \
169182
echo "--- running $$f ---"; \
170-
hack/cozytest.sh "$$f" || exit 1; \
183+
COZYTEST_TRACE=$(COZYTEST_TRACE) hack/cozytest.sh "$$f" || exit 1; \
171184
done
172185

173186
# Operator-facing host preflight check. Warns about a standalone

‎hack/capture-previous-logs.bats‎

Lines changed: 195 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -6,6 +6,7 @@
66
#
77
# - prevlog_filter_restarted -- keep only containers with restartCount > 0;
88
# - prevlog_prioritize -- put the failing test's namespace first;
9+
# - prevlog_sort_recent -- newest restart first, undated rows last;
910
# - prevlog_cap -- bound the dump so a wedged cluster cannot
1011
# explode the catch;
1112
# - prevlog_logfile_name -- per-container artifact filename.
@@ -44,6 +45,10 @@ E2E_CAPTURE_PREVLOGS_LIB=1
4445
. "$SCRIPT"
4546

4647
@test "filter restarted keeps only containers whose restart count is above zero" {
48+
# Deliberately fed the five-field shape, without the trailing finishedAt: the
49+
# filter emits six fields either way, so the timestamp column is present and
50+
# empty rather than absent. Uniform arity is what lets prevlog_sort_recent key
51+
# on field 6 unconditionally.
4752
rows="$(printf '%s\n' \
4853
'tenant-test|mariadb-test-0|mariadb|container|3' \
4954
'tenant-test|mariadb-test-1|mariadb|container|0' \
@@ -53,8 +58,8 @@ E2E_CAPTURE_PREVLOGS_LIB=1
5358
out="$(printf '%s\n' "$rows" | prevlog_filter_restarted)"
5459

5560
[ "$(printf '%s\n' "$out" | grep -c .)" -eq 2 ]
56-
printf '%s\n' "$out" | grep -q '^tenant-test|mariadb-test-0|mariadb|container|3$'
57-
printf '%s\n' "$out" | grep -q '^tenant-test|mariadb-test-0|init-datadir|init|2$'
61+
printf '%s\n' "$out" | grep -q '^tenant-test|mariadb-test-0|mariadb|container|3|$'
62+
printf '%s\n' "$out" | grep -q '^tenant-test|mariadb-test-0|init-datadir|init|2|$'
5863
# `! cmd` is vacuous under cozytest's `set -e` (errexit is suppressed for a
5964
# `!`-negated pipeline), so a filter regression that let these rows through
6065
# would not fail the test. Assert the absence via `if cmd; then ...; false`.
@@ -170,6 +175,171 @@ E2E_CAPTURE_PREVLOGS_LIB=1
170175
[ "$(printf '%s\n' "$out" | sed -n '4p' | cut -d'|' -f2)" = "tenant-test-runner" ]
171176
}
172177

178+
@test "sort_recent puts the newest previous instance first and undated rows last" {
179+
# The ordering the cap is spent under. Rows 1 and 4 are the fixture that makes
180+
# this bite: the oldest restart arrives first from kubectl (pods are listed by
181+
# namespace, not by time) and must end up behind the newest.
182+
rows="$(printf '%s\n' \
183+
'cozy-kubevirt|virt-api-a|virt-api|container|1|2026-08-13T01:30:56Z' \
184+
'tenant-test|mariadb-0|mariadb|container|2|' \
185+
'tenant-test|postgres-0|postgres|container|4|2026-08-22T09:06:00Z' \
186+
'cozy-linstor|satellite-x|linstor|container|3|2026-08-17T13:07:28Z')"
187+
188+
out="$(printf '%s\n' "$rows" | prevlog_sort_recent)"
189+
190+
# Ordering, never dropping.
191+
[ "$(printf '%s\n' "$out" | grep -c .)" -eq 4 ]
192+
[ "$(printf '%s\n' "$out" | sed -n '1p' | cut -d'|' -f2)" = "postgres-0" ]
193+
[ "$(printf '%s\n' "$out" | sed -n '2p' | cut -d'|' -f2)" = "satellite-x" ]
194+
[ "$(printf '%s\n' "$out" | sed -n '3p' | cut -d'|' -f2)" = "virt-api-a" ]
195+
# A container whose lastState the kubelet has already dropped carries no
196+
# timestamp. It still has a previous instance worth reading, so it sorts last
197+
# rather than being filtered out.
198+
[ "$(printf '%s\n' "$out" | sed -n '4p' | cut -d'|' -f2)" = "mariadb-0" ]
199+
}
200+
201+
@test "sort_recent leaves simultaneous restarts in input order" {
202+
# A node reboot restarts a dozen containers on the same second. Without a
203+
# stable sort their order would vary between runs, and so would which of them
204+
# the cap keeps -- turning a capture into something that cannot be compared
205+
# against the previous run's.
206+
#
207+
# Fixture deliberately in DESCENDING name order. An ascending one (first,
208+
# second, third) is reproduced by sort's last-resort whole-line comparison
209+
# with no -s at all, so the test would pass on a platform that ignores -s --
210+
# which is the only platform it exists to catch.
211+
rows="$(printf '%s\n' \
212+
'ns|zeta|c|container|1|2026-08-17T13:07:28Z' \
213+
'ns|mu|c|container|1|2026-08-17T13:07:28Z' \
214+
'ns|alpha|c|container|1|2026-08-17T13:07:28Z')"
215+
216+
out="$(printf '%s\n' "$rows" | prevlog_sort_recent)"
217+
218+
[ "$(printf '%s\n' "$out" | sed -n '1p' | cut -d'|' -f2)" = "zeta" ]
219+
[ "$(printf '%s\n' "$out" | sed -n '2p' | cut -d'|' -f2)" = "mu" ]
220+
[ "$(printf '%s\n' "$out" | sed -n '3p' | cut -d'|' -f2)" = "alpha" ]
221+
}
222+
223+
@test "sort_recent is a no-op on rows that carry no timestamp field" {
224+
# Every row ties, so the stable sort must return the input untouched. This is
225+
# what lets the five-field fixtures elsewhere in this file keep asserting
226+
# input order through prevlog_prioritize.
227+
# Descending, for the same reason as the fixture above.
228+
rows="$(printf '%s\n' \
229+
'ns|p3|c|container|1' \
230+
'ns|p2|c|container|1' \
231+
'ns|p1|c|container|1')"
232+
233+
out="$(printf '%s\n' "$rows" | prevlog_sort_recent)"
234+
235+
[ "$out" = "$rows" ]
236+
}
237+
238+
@test "prioritize ranks namespace above recency" {
239+
# Both keys in tension on purpose: the freshest restart in the cluster is in
240+
# another namespace, and the failing test's own namespace holds only an older
241+
# one. Namespace has to win -- a stale restart in the namespace under test is
242+
# likelier to explain the failure than a fresh one somewhere unrelated -- and
243+
# recency has to order within each group rather than across them.
244+
rows="$(printf '%s\n' \
245+
'cozy-kubevirt|virt-api|virt-api|container|1|2026-08-27T10:00:00Z' \
246+
'tenant-test|mariadb-0|mariadb|container|1|2026-08-13T01:00:00Z' \
247+
'cozy-linstor|satellite|linstor|container|1|2026-08-20T10:00:00Z' \
248+
'tenant-test|postgres-0|postgres|container|1|2026-08-14T01:00:00Z')"
249+
250+
out="$(printf '%s\n' "$rows" | prevlog_prioritize tenant-test)"
251+
252+
[ "$(printf '%s\n' "$out" | grep -c .)" -eq 4 ]
253+
# The test's namespace first, newest of the two leading it.
254+
[ "$(printf '%s\n' "$out" | sed -n '1p' | cut -d'|' -f2)" = "postgres-0" ]
255+
[ "$(printf '%s\n' "$out" | sed -n '2p' | cut -d'|' -f2)" = "mariadb-0" ]
256+
# Then everything else, also newest first.
257+
[ "$(printf '%s\n' "$out" | sed -n '3p' | cut -d'|' -f2)" = "virt-api" ]
258+
[ "$(printf '%s\n' "$out" | sed -n '4p' | cut -d'|' -f2)" = "satellite" ]
259+
}
260+
261+
@test "filter_restarted carries the restart timestamp through" {
262+
# The field the ordering depends on. It also has to be READ rather than left
263+
# to fall into $restarts as trailing text: `read -r ... restarts` without a
264+
# sixth variable folds the timestamp into the count, which reaches the dump
265+
# header as `restarts=1|2026-08-22T09:06:00Z`.
266+
rows="$(printf '%s\n' \
267+
'ns|p1|c|container|2|2026-08-22T09:06:00Z' \
268+
'ns|p2|c|container|0|2026-08-22T09:06:00Z' \
269+
'ns|p3|c|container|1|')"
270+
271+
out="$(printf '%s\n' "$rows" | prevlog_filter_restarted)"
272+
273+
# p2 never restarted, so it is dropped regardless of its timestamp.
274+
[ "$(printf '%s\n' "$out" | grep -c .)" -eq 2 ]
275+
[ "$(printf '%s\n' "$out" | sed -n '1p')" = 'ns|p1|c|container|2|2026-08-22T09:06:00Z' ]
276+
[ "$(printf '%s\n' "$out" | sed -n '2p' | cut -d'|' -f5)" = "1" ]
277+
[ "$(printf '%s\n' "$out" | sed -n '2p' | cut -d'|' -f6)" = "" ]
278+
}
279+
280+
@test "a no value timestamp sorts last instead of jumping the queue" {
281+
# kubectl renders a missing template leaf as the literal string `<no value>`,
282+
# and `<` (0x3C) sorts ABOVE every digit, so under a reverse sort such a row
283+
# lands FIRST and displaces the most recent real restart -- inverting the one
284+
# thing this ordering exists to do. The template now guards the leaf so the
285+
# string cannot be produced; this pins the row-level behaviour too, so the
286+
# ordering is still defensible if some other producer ever emits it.
287+
rows="$(printf '%s\n' \
288+
'ns|undated|c|container|1|<no value>' \
289+
'tenant-test|newest|c|container|4|2026-08-22T09:06:00Z' \
290+
'tenant-test|older|c|container|1|2026-08-13T01:30:56Z')"
291+
292+
out="$(printf '%s\n' "$rows" | prevlog_sort_recent)"
293+
294+
first=$(printf '%s\n' "$out" | sed -n '1p' | cut -d'|' -f2)
295+
if [ "$first" != "newest" ]; then
296+
echo "FAIL: expected the newest real restart first, got '$first'"
297+
printf '%s\n' "$out"
298+
false
299+
fi
300+
[ "$(printf '%s\n' "$out" | sed -n '3p' | cut -d'|' -f2)" = "undated" ]
301+
}
302+
303+
@test "the pod template guards the timestamp leaf and not only its parents" {
304+
# The stub-driven tests below inject rows directly and so never execute the
305+
# go-template, which is exactly how the `<no value>` shape reached a live job
306+
# log unnoticed. Assert the guard's shape in the script text instead: two
307+
# levels (lastState, terminated) leave the leaf ungarded, and `finishedAt` is
308+
# a metav1.Time whose zero value marshals to null, which the kubelet does
309+
# produce (ContainerStatusUnknown, which also bumps restartCount).
310+
guarded=$(grep -c 'if .lastState.terminated.finishedAt }}{{ .lastState.terminated.finishedAt }}' "$SCRIPT")
311+
# One for initContainerStatuses, one for containerStatuses.
312+
if [ "$guarded" -ne 2 ]; then
313+
echo "FAIL: expected 2 leaf-guarded finishedAt references in the template, found $guarded"
314+
grep -n 'finishedAt' "$SCRIPT"
315+
false
316+
fi
317+
}
318+
319+
@test "the dump header names when the previous instance ended" {
320+
# The whole-script path: every other integration test here feeds five-field
321+
# rows, so the sixth field reached the header with no coverage at all, and
322+
# deleting it from the consumer loop's `read` left this suite green while the
323+
# header printed `restarts=1|2026-08-22T09:06:00Z`.
324+
tmp="$(mktemp -d)"
325+
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
326+
out="$tmp/previous-logs"
327+
rows='tenant-test|db-0|postgres|container|4|2026-08-22T09:06:00Z'
328+
329+
PATH="$stub:$PATH" PREVLOG_STUB_ROWS="$rows" \
330+
sh "$SCRIPT" "$out" tenant-test >"$tmp/stdout" 2>&1
331+
332+
grep -q 'restarts=4, previous instance ended 2026-08-22T09:06:00Z' "$tmp/stdout"
333+
# The count must not have absorbed the timestamp, which is the shape the
334+
# missing read variable produced.
335+
if grep -q 'restarts=4|' "$tmp/stdout"; then
336+
echo "FAIL: the timestamp was folded into the restart count"
337+
grep 'previous logs:' "$tmp/stdout"
338+
false
339+
fi
340+
rm -rf "$tmp"
341+
}
342+
173343
@test "cap keeps at most the requested number of rows" {
174344
rows="$(printf '%s\n' \
175345
'ns|p1|c|container|1' 'ns|p2|c|container|1' 'ns|p3|c|container|1' \
@@ -428,6 +598,29 @@ STUB
428598
rm -rf "$tmp"
429599
}
430600
601+
@test "an empty preferred namespace group does not consume a cap slot" {
602+
tmp="$(mktemp -d)"
603+
stub="$tmp/bin"; mkdir -p "$stub"; prevlog_stub_dir "$stub"
604+
out="$tmp/previous-logs"
605+
rows="$(printf '%s\n' \
606+
'cozy-system|operator-0|operator|container|4' \
607+
'cozy-linstor|satellite-0|linstor|container|3' \
608+
'cozy-cilium|agent-0|cilium|container|2')"
609+
610+
PATH="$stub:$PATH" PREVLOG_STUB_ROWS="$rows" COZY_PREVLOG_MAX=3 \
611+
sh "$SCRIPT" "$out" tenant-test >/dev/null 2>&1
612+
613+
# No row matches tenant-test, so the preferred group is empty. Its lack of
614+
# output must not become a blank line that head counts against the cap.
615+
[ "$(ls "$out" | grep -c '\.log$')" -eq 3 ]
616+
if grep -q 'reached COZY_PREVLOG_MAX=3 cap' "$out/capture-notes.txt"; then
617+
echo "FAIL: an empty preferred group manufactured a cap overflow"
618+
cat "$out/capture-notes.txt"
619+
false
620+
fi
621+
rm -rf "$tmp"
622+
}
623+
431624
@test "a missing timeout is named as a local dependency, not as a cluster failure" {
432625
tmp="$(mktemp -d)"
433626
bin="$tmp/bin"; mkdir -p "$bin"

0 commit comments

Comments
 (0)