Skip to content

fix(smoke-tests): don't let a log-fetch timeout mask the real failure - #129

Open
spal1 wants to merge 1 commit into
mainfrom
samiksha/dont-let-log-fetch-timeout-mask-failures
Open

fix(smoke-tests): don't let a log-fetch timeout mask the real failure#129
spal1 wants to merge 1 commit into
mainfrom
samiksha/dont-let-log-fetch-timeout-mask-failures

Conversation

@spal1

@spal1 spal1 commented Aug 4, 2026

Copy link
Copy Markdown
Contributor

What

Makes the smoke test report the actual training failure instead of a timeout from the log-dump command that runs afterward.

Why

When a job reaches a terminal failure, poll_job_status dumps its logs via truss train logs for debugging. That call is best-effort (check=False), but check=False only covers a nonzero exitsubprocess.run raises TimeoutExpired, which propagated out of poll_job_status and aborted main before the summary was written.

So every failing run reports only this:

FAIL: Command '['uv', 'run', 'truss', 'train', 'logs', '--job-id', 'w5ov4mq', ...]' timed out after 300 seconds
Traceback (most recent call last):
  File ".../bin/test_example.py", line 821, in main
    final_status = poll_job_status(
subprocess.TimeoutExpired

and never the TRAINING_JOB_FAILED status and error message it had already successfully fetched one line earlier.

These smoke tests have been red on every scheduled run since 2026-06-23 (last green on main: run 28016797245), and not one of those runs named the cause. Finding it required querying Loki by hand: the training container dies with OSError: Can't load the model for 'Qwen/Qwen3-0.6B' after a 403 Forbidden from the HF Xet CDN on model.safetensors. Same failure on both accelerators and across two clusters (neb-eunorth1-prod-1, ori-dfw-prod-1).

This PR does not fix that 403 — it makes the next occurrence of any failure self-diagnosing.

How

  • run_truss_cli catches subprocess.TimeoutExpired, echoes whatever the command emitted before hanging, and then either raises a clear RuntimeError (check=True, an operation the test depends on) or returns a synthetic CompletedProcess with exit 124 (check=False, a best-effort dump) so the caller carries on and reports the real outcome.
  • Extracted the stdout/stderr echo into _echo_cli_output so the timeout path prints partial output the same way the normal path does.
  • The two log dumps get timeout=LOG_FETCH_TIMEOUT (120s) rather than the default 300s, since they are diagnostics rather than something the test depends on. This also cuts ~3 minutes off each failing run.

Testing

Exercised both branches by stubbing subprocess.run to raise TimeoutExpired:

--- check=False (best-effort log dump): must return, not raise ---
  partial log line
  CLI command timed out after 120s: uv run truss train logs --job-id w5ov4mq --non-interactive
returncode: 124 | partial output kept: 'partial log line\n'
--- check=True (depended-on op): must raise a clear error ---
RuntimeError: CLI command timed out after 30s: uv run truss train view --non-interactive

I have not run the full smoke test against a live remote; that needs the workflow's credentials.

Related

  • Root cause of the hang is fixed upstream in fix(cli/train): bound the training log fetch with a deadline truss#2594, which adds a wall-clock deadline to the CLI's log pagination. That fix will not reach this repo until it ships and pyproject.toml moves off the truss==0.18.16 pin, which is why this harness-side guard is worth having on its own.
  • The underlying HF Xet 403 needs its own fix and is unrelated to this change.

When a training job fails, poll_job_status dumps its logs via
`truss train logs` for debugging. That call is best-effort (check=False),
but check=False only covers a nonzero exit: subprocess.run raises
TimeoutExpired, which propagated out of poll_job_status and aborted main
before the summary was written.

The result is that every failing run reports only

    subprocess.TimeoutExpired: Command '[... 'train', 'logs' ...]'
    timed out after 300 seconds

and never the job status or error it had already fetched. The smoke tests
have been red since 2026-06-23 and none of those runs named the cause;
it took a manual Loki query to find it (an HF weights download 403).

Catch TimeoutExpired in run_truss_cli: echo whatever the command emitted,
then either raise a clear RuntimeError (check=True, an operation the test
depends on) or return a synthetic CompletedProcess with exit 124
(check=False, a best-effort dump) so the caller reports the real outcome.
Give the two log dumps a 120s budget instead of 300s, since they are
diagnostics rather than something the test depends on.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant