Skip to content

Commit 66cd0fb

Browse files
authored
test(e2e): time the guest console capture and baseline it on a green run (#3841)
## What this PR does A tenant worker's guest serial console is stamped in seconds since that guest's own kernel started. So a log that ends mid-boot tells you how far the guest got and nothing at all about when that was. Whether it ends there because the guest started late or because the guest stopped printing is the difference between two unrelated failures, and neither instant was written down anywhere: the read's own instant was nowhere in the file, surviving only as the artifact's mtime, which is metadata rather than content and so says nothing to anyone who opens the log, and the guest's start only inside a `describe` dump that the capture triggers exclusively when some console came back silent. On a run where every console returned bytes, that dump does not exist. I went looking for the answer in three collected reports before changing anything. Every one of the twelve captures across them exited zero, so no read was truncated by its 30s bound or by `--limit-bytes`, and the logs are 23 to 79 KB against a 1 MiB cap. The captures stop at 305, 370, 432, 456, 474, 497, 564, 570, 583, 599 and 639 guest seconds. A fixed cutting mechanism does not produce a 334 second spread. The logs end where the guests stopped printing. On the single worker where both ends were recoverable at all, by reading the file's mtime and the describe together, the guest had been alive for 955 seconds and had printed up to second 564. Each console log now carries the instant its own read started and returned, and `CAPTURE-TIMELINE.txt` beside it carries each Pod's phase, its start time and the start of its compute and console containers, from one bounded read taken once for the whole selector rather than per Pod. Those two subtract to how long a guest had been alive when it was read, which is what the log's last kernel stamp gets compared against. Close together means the guest was still printing and the log ends because it had not got further. Far apart means it stopped. A Pod with no compute start never ran a guest at all, whatever its console file says. The legend in the file names the units on both ends, because an epoch integer and an RFC 3339 string subtract to nonsense if you take them as printed. A read that failed and a read that answered with nothing are written down as themselves instead of leaving an absent file. The same capture now also runs on the passing path, after the last assertion and before the tenant is deleted, because the container holding the stream goes with the Pod and no read recovers it afterwards. Every console this tree has collected came from a failure, so nobody has ever measured what a healthy boot looks like, while "slower than usual" is the claim the node-join failure keeps resting on. That caller asks for the pool's minimum rather than its maximum, since two workers booting is the same measurement as ten, and it warns in the job log instead of failing a suite that has already proved everything it exists to prove. Both paths write the same directory, so the capture records which of them produced it. The cost moves by one bounded read. The serial console family goes from roughly 5m50s to 6m25s at worst and from 3m30s to 4m05s at the pool minimum, both against the 7m diagnostics phase budget, and the figure in both suite comments moves with it under the guard that holds the two in step. The passing path adds six bounded reads at 30s and 5s kill grace, so 210s. That 210s is real wall clock at the tail of an operation with a fixed 50m ceiling, which is a way for a run that already passed to be killed while collecting a debugging aid. So the passing-path capture declines itself out loud when the ceiling no longer has room for it, against a reserve derived from its own cost plus the deletes after it. The ceiling it measures against is read from both sides by a guard, so a suite that changes its `timeout:` fails there rather than leaving the reserve protecting a number that moved. What this deliberately does not do is widen a capture window. I could not derive a number for one that would be honest. The reads are already complete, so there is no read side bound to relax, and the only remaining lever is waiting longer before reading. How much longer depends on whether the tail silence is the guest freezing or the stream stopping, and that is precisely what was not measurable. The evidence leans toward the guest: the logs end on complete lines, and one of them ends on an RCU stall backtrace, which is the kernel reporting it was not being scheduled. If that holds, the silence has no ceiling and no fixed window can promise to contain a milestone. The green baseline this adds is what would set the number, and it does not exist yet. Context for #3513, which this does not fix. It restores the instrument that investigation needs. ### Screenshots Not a UI change. ### Downstream repositories I walked the trigger map in `docs/agents/contributing.md` against the actual diff. It touches `docs/agents/e2e-testing.md`, the shared e2e helper `hack/e2e-chainsaw/_lib/run-kubernetes.sh`, the two `kubernetes-*` suite files and three unit test files under `hack/`. Nothing under `packages/`, no `ApplicationDefinition`, no values schema or enum or default, no namespace, no emitted metric, no label or annotation another component reads, no node prerequisite in `hack/e2e-prepare-cluster.bats`, no make target and no file moved or renamed under `hack/`. No trigger in the map matches. - [x] No downstream repository is affected by this change - [ ] [cozystack/website](https://github.com/cozystack/website) - follow-up: - [ ] [cozystack/terraform-provider-cozystack](https://github.com/cozystack/terraform-provider-cozystack) - follow-up: - [ ] [cozystack/ansible-cozystack](https://github.com/cozystack/ansible-cozystack) - follow-up: - [ ] [cozystack/ccp](https://github.com/cozystack/ccp) - follow-up: - [ ] [cozystack/talm](https://github.com/cozystack/talm) - follow-up: - [ ] [cozystack/cozyhr](https://github.com/cozystack/cozyhr) - follow-up: - [ ] [cozystack/cozy-proxy](https://github.com/cozystack/cozy-proxy) - follow-up: - [ ] [cozystack/cozystack-telemetry-server](https://github.com/cozystack/cozystack-telemetry-server) - follow-up: - [ ] [cozystack/external-apps-example](https://github.com/cozystack/external-apps-example) - follow-up: - [ ] [cozystack/examples](https://github.com/cozystack/examples) - follow-up: ### Release note ```release-note test(e2e): stamp each tenant worker guest console capture with the instant it was read and the instant its guest started, and take the same capture on passing runs so a failing boot has a healthy one to be compared against ``` <!-- This is an auto-generated comment: release notes by coderabbit.ai --> ## Summary by CodeRabbit * **Diagnostics** * Improved Kubernetes serial-console diagnostics with capture context, bounded collection, per-read timestamps, and cluster-wide Pod start-time timelines. * Added clearer reporting for incomplete, unavailable, or failed diagnostic data. * Added absolute timestamps and explicit time units to support reliable troubleshooting. * **Reliability** * Passing test runs now collect baseline diagnostics only when sufficient time remains, helping prevent suite timeouts. * **Tests & Documentation** * Expanded diagnostic coverage and updated documented timing expectations for supported Kubernetes versions. <!-- end of auto-generated comment: release notes by coderabbit.ai -->
2 parents ff3294e + 959e90c commit 66cd0fb

7 files changed

Lines changed: 865 additions & 17 deletions

File tree

‎docs/agents/e2e-testing.md‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -105,6 +105,8 @@ Be precise about TIA's scope — it is narrower than "skip E2E for unrelated PRs
105105
- **A catch script needs an explicit `timeout:` that exceeds the inner budgets it contains.** A Chainsaw `script` op is bounded by `timeouts.exec` (5m in `.chainsaw.yaml`) unless it overrides it, so a catch whose own `timeout -k …` wrappers sum past that is *structurally guaranteed* to be killed — it reports `SCRIPT | ERROR | signal: killed` and yields nothing. That kill is strictly worse than an inner `timeout` firing: SIGKILL takes out the process group, so the collector dies mid-write **and** every later step in the script is skipped, whereas an inner `timeout` exits 124, leaves a partial capture on disk, and lets the rest of the catch run. Size the op timeout above the sum of the inner budgets and let the inner ones be what fires.
106106
- **When the sum cannot fit the op, bound the collection phase as a phase rather than raising the op.** The rule above assumes the inner budgets add up to something an op timeout can sit above. On a failure path that has accumulated collectors it stops being true — the tenant-Kubernetes node-join path in `hack/e2e-chainsaw/_lib/run-kubernetes.sh` sums past what is left of its 50m op once the bringup ahead of it and the snapshot behind it are counted, and several of its reads carry only `--request-timeout`, which bounds one HTTP request rather than a client retrying against a wedged apiserver, so parts of it have no ceiling to add up in the first place. Raising the op ceiling does not fix that shape, it postpones it: a larger ceiling multiplied by a sum that grows with every collector added is the same problem one collector later. What works instead is a wall-clock budget for the whole phase (`COZY_DIAG_PHASE_BUDGET`, with `cozy_diag_phase_start` / `cozy_diag_phase_has_time`): once it is spent, the collectors that have not started are declined out loud instead of attempted, so whatever must run after the phase — the tenant crust-gather snapshot, in that case — is never queued behind work begun past the deadline. Two consequences worth carrying to the next collector. The budget bounds when a collector may *start*, not when the phase ends, so it is not a worst case and the comment next to it must not be written as one. And because what runs last is what gets declined, source order becomes load-bearing: put the cheap reads that discriminate between failure modes ahead of the collectors that cost minutes, or the budget will spend itself on the expensive ones and drop the evidence the path exists to produce.
107107
- **Set `crust-gather --duration` explicitly.** It is crust-gather's own budget for the collection phase and it defaults to **60s**; on elapse it abandons the collection and skips its finish step, leaving a partial tree with nothing to say the rest is missing. The outer wall-clock must exceed it, because the API discovery crust-gather runs *first* is not covered by that budget at all — with an unhealthy aggregated APIService (the state a failed e2e is usually in) aggregated discovery times out and the fallback re-walks every group, which can consume the entire outer timeout before a single object is written. Do not diagnose a killed snapshot by bumping the outer number alone; the two budgets bound different phases. Send the collector's output to a log inside the snapshot rather than `/dev/null` so "complete or truncated?" is answerable from the artifact.
108+
- **A collector that only runs on failure answers in one direction.** Its output has no measured value to be read against, so a claim like "this boot was slow" rests on an impression of what a healthy run looks like rather than on a number from one. Where the evidence is destroyed by teardown — the tenant worker's guest serial console goes with the Pod that holds the stream — the baseline has to be taken on the passing run or it does not exist at all, which is why `hack/e2e-chainsaw/_lib/run-kubernetes.sh` captures that console on both paths and records which one it was. A passing-path collector is held to two rules the failure path does not need. It must not fail the suite, since everything the suite exists to prove has already passed by the time it runs — and its own cost counts, not just its exit status, so a collector that costs minutes declines itself out loud when the operation's ceiling no longer has room for what it is about to spend, rather than starting a walk that the ceiling cuts off mid-write. That bounds the collector's contribution and nothing else: work already on the path with no ceiling of its own stays unbounded, and no reserve makes it fit by arithmetic. And what it could not collect **at all** has to reach the **job log**, not only the report, because a green run's artifact is the one nobody downloads. Per-read outcomes stay beside the read in the report, as everywhere else in that collector: a note about one console is only usable next to that console, while a walk that collected nothing is a fact about the run.
109+
- **A diagnostic that carries a relative clock also has to carry the absolute one.** A guest kernel stamps its console in seconds since its own boot, so a log that ends at 500 seconds says how far that guest got and nothing about when. Whether it stopped early because it started late or because it stopped printing is decided by the instant the read happened and the instant the guest started, and neither is in the file: the first survives only as the artifact's mtime, which is metadata rather than content and so is invisible to anyone reading the log and lost by anything that regenerates it, and the second only in a `describe` dump that a healthy-looking capture never triggers. Write both beside the capture, and name the units on each — an epoch integer and an RFC 3339 string subtract to nonsense if a reader takes them as printed.
108110
- **Per-failed-test crust-gather snapshots** are the richest diagnostic — a `crust-gather serve`-able archive of the cluster *at the moment of failure*, before cleanup. The global `error.catch` in `hack/e2e-chainsaw/.chainsaw.yaml` captures the **host** cluster into `_out/cozyreport/snapshots/<test>/host` on any failure (the Chainsaw analog of the `hack/cozytest.sh` EXIT-trap snapshot used by the e2e BATS suites); the kubernetes suites additionally snapshot their **tenant** cluster from `hack/e2e-chainsaw/_lib/run-kubernetes.sh` while the tenant API LB is still routable. `hack/cozyreport.sh` folds `snapshots/` into the artifact. Do not remove the global catch — without it the Chainsaw suite uploads a report with no per-test cluster state.
109111

110112
### 9. Keep the test environment deterministic

0 commit comments

Comments
 (0)