Skip to content

Commit b1519ac

Browse files
authored
fix(e2e): cap the bucket S3 reads so the verify step honors its timeout (#4281)
## What this PR does Refs #4268 — a plain reference, not `Fixes`: the issue asks for a `script` op to be cut off at its declared ceiling, and that is Chainsaw behaviour this repo cannot change. Chainsaw runs the op's shell under Go's `exec.CommandContext`, whose default cancel SIGKILLs the shell PID alone and then blocks on the inherited stdout/stderr pipe until an orphaned `mc` closes it, so the op returns only when `mc` exits on its own rather than at the ceiling. This PR mitigates that where it bit — per-command caps so no descendant outlives its own budget — but the op-timeout gap itself lives in Chainsaw, so the link stays a reference rather than a `Fixes`. The sibling step that produced the 606s, `verify-every-bucket-takes-a-write` in the `bucket-1-capacity` Test, is on `main` and already carries its own per-call caps; this PR applies the same shape to `verify-s3-access`. On run 34948279363 the bucket suite's `verify-every-bucket-takes-a-write` step declared `timeout: 5m` but ran 606s and ended on `mc`'s own non-zero status rather than being cut at the ceiling. `verify-s3-access` in `hack/e2e-chainsaw/bucket/chainsaw-test.yaml` is the same-shaped step in this suite. This PR wraps every S3 (`mc`) and apiserver (`kubectl`) read in `verify-s3-access` in its own `timeout`, so a hung read dies at a known budget instead of holding the step open, and corrects the two places (`hack/e2e-chainsaw/.chainsaw.yaml` and `docs/agents/e2e-testing.md`) that explained the op ceiling with a mechanism that does not hold. It caps `verify-s3-access` for sharing the shape, not for producing the 606s number. ### Which of the issue's two candidate mechanisms holds The issue named two candidates and stated the log could not separate them. The Chainsaw v0.2.15 source separates them, and it is the second one, with the exact refinement the issue proposed. **Candidate 1 — "an operation `timeout` does not bound a `script` op" — is refuted.** The op timeout is applied and does reach the process: `pkg/runner/operations/script.go:24` copies the step's `timeout` into `Timeouts.Exec`, and `:38` wraps the op context with `ctx, cancel := context.WithTimeout(ctx, tc.Timeouts().Exec)` before calling `op.Exec(ctx, …)`. So a 5m step produces a real 300s deadline on the context the command runs under. **Candidate 2 — "it bounds it and kills the shell, but Chainsaw waits on a pipe a grandchild (`mc`) still holds open" — is confirmed.** In `pkg/engine/operations/script/operation.go` the command is built with `exec.CommandContext(ctx, shell, …)` (`:105`), and in `execute` its stdout/stderr are set to `*bytes.Buffer` (`:128`–`:129`, the buffers are `internal.CommandOutput` in `pkg/engine/operations/internal/command_output.go:12`–`13`) and run via `cmd.Run()` (`:130`). Two Go `os/exec` properties then produce the overrun: `exec.CommandContext`'s default cancel is `Process.Kill()` on the shell PID alone — not a process-group kill, and the operation sets no `SysProcAttr.Setpgid` — and because stdout/stderr are not `*os.File`, `os/exec` allocates OS pipes and copier goroutines, so `cmd.Wait()` blocks until those pipes reach EOF. EOF needs every inherited write-end closed. When the shell forks `mc`, `mc` inherits those fds; at 300s the deadline SIGKILLs the shell but `mc` is orphaned, keeps retrying the S3 PUT, and holds the pipe, so the op does not return until `mc` exits on its own at 606s. `cmd.Run()` then returns `signal: killed`, which is stored in the `$error` binding and never printed — only the `($error == null): true` check failure is logged — which is why grepping the run for `signal: killed` found nothing. **Empirical confirmation.** A standalone Go program reproduces it exactly. `exec.CommandContext` with a 1s timeout, `*bytes.Buffer` stdout/stderr, running `sh -c 'sleep 2 & sleep 4'` (a descendant that inherits the pipe): `cmd.Run()` returns after ~4s, not 1s, with `err=signal: killed` and `ctx.Err()=context deadline exceeded` — the ceiling fired at 1s, control came back only when the descendant closed the pipe. Redirecting the descendants' stdout/stderr away from the pipe (`… >/dev/null 2>&1`) returns at 1.00s. That is the whole mechanism: the ceiling cuts the shell but not a descendant that still holds the pipe. ### The fix Per-command caps, the remedy the issue itself points to ("every read carries its own cap") and the shape already used elsewhere in the suite. The bucket step now defines a `k()` wrapper (`timeout 30 kubectl`) and an `mc()` wrapper (`timeout 15 mc`) for the reads, and calls `timeout 45 mc cp` directly for the two PUTs; a hung read is killed at its own budget, releasing the inherited pipe promptly, so even when the op ceiling fires the residual is one inner cap rather than `mc`'s full retry exhaustion. The terminal precedents for these budgets are the redis suite's terminal `k()` (30s, `redis/chainsaw-test.yaml:298`) and the sibling `verify-every-bucket-takes-a-write` step's terminal `mc cp` (45s, `:390`, sized for a volume grow); the 15s cap on `mc` in `hack/e2e-chainsaw/_lib/backup-access-preflight.sh` is not a precedent, because it sits inside a `while :;` retry loop where a 124 costs one attempt, whereas here under `set -e` a 124 ends the step. The inner budgets — 2×30 for the two `k` reads + 2×45 for the two `mc cp` PUTs + at most 7×15 for the other `mc` calls (eight other call sites, but the two cleanup `mc rm` are mutually exclusive) + the 30s port-forward readiness wait = at most 285s — sit under the 5m op ceiling, which stays as a backstop, per the "op above the sum of inner budgets" rule in `docs/agents/e2e-testing.md`. The long-lived `kubectl port-forward` keeps no cap by design (it must persist for the whole step, and its stdout/stderr are already redirected to `/dev/null`, so it cannot hold the step's pipe). The `mc()` wrapper is non-recursive because `timeout` execs its argument through a PATH lookup that bypasses shell functions — verified in `dash`, `bash` and `sh`. The `catch` block's diagnostic read gets the same treatment — `timeout 30 kubectl` under a 1m op `timeout` — for the same pipe reason. ### The readonly deny probe fails on a timeout The readonly-upload probe used to branch on `mc` directly (`if mc cp …; then`), which suspends `set -e`, so a `timeout` there (exit 124) was indistinguishable from the access-denied non-zero the probe expects: a 45s hang on the deny path would exit 124, take the false branch, reach cleanup and exit 0 — a long hang turned green, the exact window this PR exists to bound. This is the first `ro-user` write in the step, so no earlier call proved that path healthy. The probe now captures the status: exit 0 is the readonly regression, 124 is a timed-out probe, both fail; any other non-zero is the expected denial. ### No unit surface; why the evidence is the proof This is an e2e-config and doc-correctness change. The embedded Chainsaw script is not extracted into a unit harness anywhere in the tree, so there is no red-to-green unit test to add without inventing a bespoke script-linter (which would be a new checker standing in for the fix). The regression is instead pinned by the mechanism proof above: the source citations show the ceiling cannot cut a descendant that holds the pipe, and the caps remove the only way a descendant outlives its budget. The deny-probe status handling and the pipe-vs-file secret reads were exercised against stub exit codes (0 → regression-fail, 124 → timeout-fail, other non-zero → expected denial) and the whole script passes `sh -n` and `bash -n`. ### Downstream repositories Walked the trigger map in `docs/agents/contributing.md` against the diff. The change touches only `hack/e2e-chainsaw/` suite content and `docs/agents/e2e-testing.md`; it moves or renames nothing under `hack/`, and touches no node-prerequisite or `package.mk` path. No downstream repository is reached. - [x] No downstream repository is affected by this change ### Release note ```release-note NONE ``` <!-- This is an auto-generated comment: release notes by coderabbit.ai --> ## Summary by CodeRabbit - **Bug Fixes** - Improved end-to-end S3 access verification so stalled Kubernetes API and S3 operations fail promptly. - Correctly distinguishes timed-out access checks from expected permission denials. - Preserves partial command output and allows subsequent test steps to continue after individual timeouts. - Applies separate time limits to bucket reads, uploads, and access checks for more predictable test behavior. - **Documentation** - Clarified operation timeout behavior and recommended per-command limits within the overall operation limit. - Documented timeout handling for orphaned processes and updated worst-case timing guidance. <!-- end of auto-generated comment: release notes by coderabbit.ai -->
2 parents ec706c4 + ac92b6b commit b1519ac

3 files changed

Lines changed: 102 additions & 23 deletions

File tree

‎docs/agents/e2e-testing.md‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -120,7 +120,7 @@ Be precise about TIA's scope — it is narrower than "skip E2E for unrelated PRs
120120
- **`COZY_REPORT_POD_TAIL` bounds each container log** at 2000 lines by default, and a log that was read successfully records which bound it was written under, since `--tail` drops the oldest lines and a file that begins mid-stream looks exactly like a complete one; `-1` restores kubectl's own default of the whole log. `COZY_REPORT_PREFER_NS` (default `tenant-`) is collected first, so a cap that only bites on a broadly degraded cluster is not spent on platform namespaces while the pod the suite died on falls off the end.
121121
- **Capture the PREVIOUS container instance, not just the current one.** For a crash-looping pod `kubectl logs` (and the Chainsaw `podLogs` collector, which in v0.2.15 has no `previous` option — it does accept `name`/`namespace`/`selector`/`container`/`tail`/`timeout`/`cluster`/`clusters`) shows the Nth restart — a fresh replay of the same startup path — while the evidence that explains the failure sits in the immediately preceding instance, reachable only via `--previous` and lost for good once the kubelet garbage-collects that container. `hack/e2e-capture-previous-logs.sh` closes this once for every suite from the global `error.catch` (and from `hack/cozytest.sh` for the e2e BATS suites) rather than per-suite: it discovers containers with `restartCount > 0` at runtime — init containers included, since an interrupted bootstrap lives there — orders the app suites' `tenant-test` namespace first (a best-effort ordering only — it never restricts the capture, and for a suite whose pods live in a child tenant namespace it simply degrades to input order), and dumps each to the job log and to `snapshots/<test>/previous-logs/`. Containers that never restarted are skipped, so a healthy run emits one line, not a page of "previous terminated container not found". Every way the capture can come up short is named rather than inferred: the `COZY_PREVLOG_MAX` overflow, a malformed cap, a `COZY_PREVLOG_TAIL` that was rejected and fell back to 200 (a zero or leading-zero tail asks kubectl for nothing, which would otherwise be reported as the container having logged nothing), the tail bound each kept log was written under — named in `capture-notes.txt` beside the logs rather than inside them, since `--tail` drops the oldest lines and nothing in the output says so while a log read in full is a complete artifact that a trailing prose line would stop any parser from reading, and suppressed on `-1` because no bound was applied then — a pod list that never returned (which is NOT the same as "nothing restarted" and must not be reported as such), a read that timed out versus one kubectl itself refused (kubelet GC, RBAC, an unreachable node — different problems that a blanket "kubelet GC" line would hide), a previous instance that produced no output, and a capture the outer backstop cut short. A partial log is kept and marked truncated, never deleted — it is the only copy of something already gone from the cluster. Each of those lines the script itself emits is written to `snapshots/<test>/previous-logs/capture-notes.txt` as well as to the job log, and the directory is created before the first of them, so a reader who has only the uploaded artifact can still tell a capture that found nothing from one that never ran. The outer backstop firing is the exception: that line comes from the callers, after the script has already been killed, and reaches the job log only. `hack/cozytest.sh` arms this capture, and the other two legs, only for suites whose own filename or whose parent directory carries the `e2e-` prefix, because all three read cluster state and a unit runner has `kubectl` on PATH with no cluster behind it, so a red unit test used to walk into the kubectl-gated legs on its way out, and into the crust-gather one as well on any machine where that binary happened to be installed.
122122
- **The data-plane collector is the third capture leg, and the only one that reads forwarding state off the node.** `hack/e2e-capture-dataplane.sh` runs after the crust-gather snapshot, from `hack/cozytest.sh` for the e2e BATS suites and from the global `error.catch` in `hack/e2e-chainsaw/.chainsaw.yaml` for the Chainsaw ones, and it collects what an object-state snapshot structurally cannot: the cilium endpoint and BPF conntrack view from an affected pod's node, the kernel conntrack table that is the authoritative one for the host-to-local-pod path under `enable-host-legacy-routing`, and the LoadBalancer datapath. Its two callers bound it differently, 600s from `cozytest.sh` and 300s from the Chainsaw catch, so anything added to what it collects has to fit the smaller of the two rather than the one you happened to test under. It holds the same notes contract as the previous-logs collector, with one stated exception: every read carries its own ceiling, and why a read produced nothing goes to `capture-notes.txt` beside the capture rather than only to the job log, because an empty result and a read that never answered are the same bytes on disk and only the note tells them apart; the two EndpointSlice reads in the LoadBalancer path are the exception and report nothing either way, so a `<none>` backend line there does not distinguish an endpointless Service from a read that never answered.
123-
- **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.
123+
- **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 hit the ceiling — it reports `SCRIPT | ERROR | signal: killed` and yields little. That kill is strictly worse than an inner `timeout` firing, and worse in a way the process tree makes precise: the ceiling SIGKILLs the **shell process alone**, not its process group. Chainsaw runs the shell under `exec.CommandContext` (`pkg/engine/operations/script/operation.go`), whose default cancel is `Process.Kill()` on the shell PID, so every later step in the script is skipped but any collector the shell already spawned is orphaned rather than killed — it keeps running, and it keeps the script's stdout/stderr pipe open. Because that op wires stdout/stderr to in-process buffers, `cmd.Wait()` does not return until the pipe reaches EOF, which needs every inherited fd closed, so the op does not even come back **at** its ceiling until the orphan exits on its own — the ceiling stops being a reliable cut (#4268, where the bucket suite's `verify-every-bucket-takes-a-write` step ran 606s under a 300s ceiling because `mc` kept retrying after the shell was gone). An inner `timeout` instead kills that read at a known budget, exits 124, leaves a partial capture on disk, and lets the rest of the catch run — which is why every read must carry its own cap rather than lean on the op ceiling. Size the op timeout above the sum of the inner budgets and let the inner ones be what fires.
124124
- **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 67m 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.
125125
- **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.
126126
- **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.

‎hack/e2e-chainsaw/.chainsaw.yaml‎

Lines changed: 26 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -45,19 +45,30 @@ spec:
4545
# Every catch script below carries an explicit `timeout:`. A Chainsaw script
4646
# op is bounded by `timeouts.exec` (5m above) unless it overrides it, and the
4747
# inner wall-clock budgets here sum well past that — so without the override
48-
# Chainsaw SIGKILLs the whole script partway through and the catch reports
49-
# `SCRIPT | ERROR | signal: killed` having collected nothing. That kill is
50-
# strictly worse than an inner `timeout` firing: SIGKILL takes out the process
51-
# group, so the collector dies mid-write AND every later step in the script is
52-
# skipped, whereas an inner `timeout` leaves a partial capture on disk and
53-
# lets the remaining steps run. Keep each op's `timeout:` above the sum of the
54-
# inner budgets it contains.
48+
# the op ceiling fires and the catch reports `SCRIPT | ERROR | signal: killed`
49+
# having collected little. That kill is strictly worse than an inner `timeout`
50+
# firing, and worse in a way the process tree makes precise: the ceiling
51+
# SIGKILLs the shell process alone — Chainsaw runs it under exec.CommandContext
52+
# whose default cancel is Process.Kill() on the shell PID, not a process-group
53+
# kill — so every later step in the script is skipped, but any collector the
54+
# shell already spawned is orphaned rather than killed and keeps running. It
55+
# also keeps the script's stdout/stderr pipe open, and cmd.Wait() does not
56+
# return until that pipe closes, so the op does not even come back at its
57+
# ceiling until the orphan exits on its own (#4268). An inner `timeout` instead
58+
# kills that read at a known budget, exits 124, leaves a partial capture on
59+
# disk and lets the remaining steps run — which is why every read below is
60+
# itself wrapped in `timeout`, not left to the op ceiling. Keep each op's
61+
# `timeout:` above the sum of the inner budgets it contains.
5562
#
5663
# Accepted tradeoff, so the arithmetic does not have to be rediscovered: this
57-
# raises the worst-case catch from ~5m per failed test (the old SIGKILL was the
58-
# de-facto cap) to ~19m, tests run sequentially, and the E2E job is capped at
59-
# 215 timeout-minutes. A cascade reddening many suites can therefore spend a
60-
# large share of the job in diagnostics. That is deliberate — the old ceiling
64+
# raises the worst-case catch to ~19m per failed test. The old design had no
65+
# inner caps and leaned on the op ceiling, which does not reliably cut a busy
66+
# script: it SIGKILLs the shell alone, orphaned children hold the pipe open,
67+
# and the op overruns (#4268 measured 606s under a 300s ceiling), so the
68+
# nominal ~5m was a figure a busy catch could exceed, not a cap. Tests run
69+
# sequentially, and the E2E job is capped at 215 timeout-minutes. A cascade
70+
# reddening many suites can therefore spend a large share of the job in
71+
# diagnostics. That is deliberate — the old ceiling
6172
# bought its speed by collecting nothing at all — and it is bounded: both legs
6273
# only approach their ceilings on a genuinely degraded cluster, a systemic
6374
# failure usually reds the install gate and skips the E2E step entirely, and
@@ -66,8 +77,10 @@ spec:
6677
# grace window is consumed by the earlier `Collect report` step, so both
6778
# cozyreport.tgz and the job log are lost (measured on runs 29557003429 and
6879
# 29568562337). If this ever does start truncating runs, bound the number of
69-
# snapshotted tests rather than shrinking these timeouts back to a size that
70-
# guarantees a kill.
80+
# snapshotted tests rather than shrinking these timeouts back down: the op
81+
# ceiling firing does not cleanly cut a busy script (it SIGKILLs the shell
82+
# alone and orphaned children hold the pipe open, so the op overruns), so a
83+
# smaller timeout does not guarantee a kill.
7184
error:
7285
catch:
7386
# Ordered cheapest-and-most-decisive first: if anything downstream overruns,

0 commit comments

Comments
 (0)