myasnikovdaniil 67b4e23ca2 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 -->
2026-09-02 10:44:23 +05:00
2025-10-08 09:43:34 +05:00
2024-02-08 12:04:32 +01:00

Cozystack Cozystack

Open Source Apache-2.0 License Support Active GitHub Release GitHub Commit OpenSSF Best Practices OpenSSF Scorecard

Cozystack

Cozystack is a free platform and framework for building clouds.

Cozystack is a CNCF Sandbox Level Project that was originally built and sponsored by Ænix.

With Cozystack, you can transform a bunch of servers into an intelligent system with a simple REST API for spawning Kubernetes clusters, Database-as-a-Service, virtual machines, load balancers, HTTP caching services, and other services with ease.

Use Cozystack to build your own cloud or provide a cost-effective development environment.

Cozystack user interface

Use-Cases

Documentation

The documentation is located on the cozystack.io website.

Read the Getting Started section for a quick start.

If you encounter any difficulties, start with the troubleshooting guide and work your way through the process that we've outlined.

Versioning

Versioning adheres to the Semantic Versioning principles.
A full list of the available releases is available in the GitHub repository's Release section.

Contributions

Contributions are highly appreciated and very welcomed!

In case of bugs, please check if the issue has already been opened by checking the GitHub Issues section. If it isn't, you can open a new one. A detailed report will help us replicate it, assess it, and work on a fix.

You can express your intention to on the fix on your own. Commits are used to generate the changelog, and their author will be referenced in it.

If you have a concrete feature request, open an issue. For a cross-cutting or architectural change, open a design proposal in the community repo. For questions or early ideas, use GitHub Discussions. See CONTRIBUTING.md for the full routing.

Community

You are welcome to join our Telegram group and come to our weekly community meetings. Add them to your Google Calendar or iCal for convenience.

License

Cozystack is licensed under Apache 2.0.
The code is provided as-is with no warranties.

Commercial Support

A list of companies providing commercial support for this project can be found on official site.

Languages
Go 46.8%
Shell 37.9%
TypeScript 7%
Go Template 5.5%
Makefile 1.5%
Other 1.1%