Repository navigation
Description
User Story
I run OpenShell's E2E conformance lanes in CI. When a test times out or fails, I need the test output and the collected artifacts to show which step stalled and what the system was doing during the test, so I can diagnose it without re-running the lane.
Problem Statement
In Pre-release run 42222713989 (dispatch on main at 53b8eec), job 127919027697 (conformance-integration / E2E suites (conformance/conformance, ubuntu-k3s, k3s-ha)), file_transfer::upload_download_round_trip hit nextest's 120 s limit (TIMEOUT [120.005s]). It started at 13:38:22Z and was killed at 13:40:22Z. The other 14 tests passed, and the next test, upload_respects_gitignore, which also uploads and downloads, passed in 41 s. I found no earlier occurrence of this timeout in recent runs, so this issue is not about the flake itself. The artifact e2e-results-conformance-conformance-ubuntu-k3s-k3s-ha (nextest.log, junit.xml, diagnostics/gateway.log, diagnostics/k3s.txt) does not show where the test stalled. Three gaps cause this:
- The per-command timeout never fires first.
CLI_TIMEOUTis 5 minutes (tests/testkit/testkit/src/cli.rs:22, used at line 135). The nextest profile generated by the runner terminates a test after 30 s x 4 = 120 s (tests/runner/src/bundle.rs:26-31). A hungopenshellcall never reaches testkit's own error (timed out after ...withrun <command>context). The failure shows only nextest's generic TIMEOUT, with no command name and no partial stderr. - No progress output. Nextest runs with
--no-capture, but tests print only a banner and a run id. A multi-step test cannot show which step stalled. - Gateway log tails are too short.
tests/tmachine/ansible/roles/openshell_diagnostics/files/collect-k3s.sh:77-78collectskubectl logs --tail=300 --timestampsper gateway pod. On the three-replica k3s-ha gateway at INFO level, 300 lines cover about 40 s. In this run the tails began at 13:40:30Z, after the stalled test's window.
Impact / Why This Matters
A timeout in this lane produces no actionable evidence. The only option is to re-run and hope it reproduces, which is costly for a lane that takes tens of minutes. Diagnostics collection runs after the failure, so a window that is too short loses the evidence permanently.
Proposed Design
A. Propagate the test's outer budget into inner calls. testkit's Context should know the per-test deadline. For example, the runner exports the budget it wrote into the nextest profile, and testkit computes a deadline from the test start minus a safety margin. Every cli, exec, wait_ready and similar call then uses min(its own timeout, remaining budget). A stuck call then fails with its command name and any captured output before nextest kills the test.
- The alternative is a fixed shorter per-command ceiling. The propagated budget is better because it stays correct if the budget changes. It also needs no per-command tuning for slow commands such as sandbox creation.
- Open question: how the budget reaches the test process. An env var set by
tests/runneris the obvious route, since the runner generates the nextest config. Suites run outside the runner need a sensible default.
B. Low-volume progress output in Cli::run_with_env (tests/testkit/testkit/src/cli.rs), so it covers every suite:
- Log nothing for fast successful commands.
- Emit a line when a command is slow (above a threshold, e.g. 10-15 s) or exits non-zero.
- Print a periodic
still running after Ns: <command>line (e.g. every 30 s) for commands in flight. - That gives hang visibility at roughly zero cost for passing runs. The thresholds are suggestions.
C. Time-bounded gateway logs in collect-k3s.sh.
- Replace
--tail=300with the existingcollect_loghelper, which keeps the first 128 KiB and last 128 KiB and is already used for the Agent Sandbox logs. Bound it by time instead of line count. - Determine the start dynamically rather than using a fixed
--since=15m. Record the test run's start time (e.g. the runner writes a timestamp in the guest when the suite begins, or derive the failing test's start fromjunit.xml). Passkubectl logs --since-time=<RFC3339>, and fall back to a fixed--sincewindow when the timestamp is unavailable. - A fixed window that is too short loses the evidence. One that is too long is capped by the 128 KiB limits.
The journal and gateway.log gap is tracked separately in the follow-up issue (#5334).
Acceptance Criteria
- A hung CLI or exec call fails with its command name (and any captured output) before nextest's per-test limit.
- The per-test budget is derived from the runner's nextest configuration rather than a separately maintained constant, with a documented default outside the runner.
- A slow or failing command is visible in the test output while the test runs, and passing fast commands add no output.
- Gateway pod logs in the diagnostics artifact cover the whole failing test, using a dynamically determined start time with a fixed-window fallback.
Alternatives Considered
A fixed shorter CLI_TIMEOUT (see A). Logging every command start and end: rejected as too noisy. A fixed --since=15m for gateway logs: rejected in favor of a dynamic start time, as above.
Activity
matthewgrossman commentedon Nov 9, 2026
Two notes from reviewing #5332: the prebuilt program writes
junit.xmlonly after its last test finishes, so a run-level timeout (45 minutes) loses the report and only the log survives; and the program's output is saved asnextest.log. Both are in scope here or in #5416.