Skip to content

test(e2e): surface where a conformance test stalls and keep logs that cover it #5333

Open

Description

@elezar

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:

  1. The per-command timeout never fires first. CLI_TIMEOUT is 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 hung openshell call never reaches testkit's own error (timed out after ... with run <command> context). The failure shows only nextest's generic TIMEOUT, with no command name and no partial stderr.
  2. 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.
  3. Gateway log tails are too short. tests/tmachine/ansible/roles/openshell_diagnostics/files/collect-k3s.sh:77-78 collects kubectl logs --tail=300 --timestamps per 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/runner is 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=300 with the existing collect_log helper, 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 from junit.xml). Pass kubectl logs --since-time=<RFC3339>, and fall back to a fixed --since window 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

  1. matthewgrossman commented on Nov 9, 2026

    @matthewgrossman
    Member

    Two notes from reviewing #5332: the prebuilt program writes junit.xml only 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 as nextest.log. Both are in scope here or in #5416.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions