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