[None][infra] Echo test output to the console on post-merge multi-GPU stages - #16935
[None][infra] Echo test output to the console on post-merge multi-GPU stages#16935JunyiXu-nv wants to merge 2 commits into
Conversation
… stages Multi-GPU CI stages already run pytest with `-s`, but the S3 log plugin then points fd 1 and 2 at session spool files and publishes each test's slice only once that test finishes. A test that wedges never finishes: pytest's `--timeout=3600 --timeout-method=thread` ends the process with `os._exit`, so nothing that test -- or any MPI worker rank that inherited those fds -- wrote reaches the stage log. On `RTXPro6000D-4_GPUs-PyTorch-Post-Merge-2` in run 2220 that left a 749 KB node log with zero `[TRT-LLM]` lines for a 60-minute wedge. That is not specific to hangs: 61 of 63 sampled multi-GPU stage logs contain no `[TRT-LLM]` line at all, including 42 of 42 that passed. The output is not destroyed -- the spool ships inside `results-<stage>.tar.gz` -- but recovering it means knowing to download and unpack an artifact, which is not how a stage failure gets triaged. The change is about diagnostic reach: put the evidence where the failure is read. Teach `--s3-echo-stdout` to work with the default session capture mode by tailing the spool files onto the real console from a single session-scoped thread. Capture, per-test slicing and uploading are unchanged; only the console copy is best-effort, and the spool is still written synchronously by the producer, so an abrupt kill cannot lose more than one poll interval. `--s3-capture-mode=timestamped` already accepted `--s3-echo-stdout`, but its reader called `read(4096)` on a buffered *text* stream, which blocks until it has 4096 characters or sees EOF. The trailing partial chunk -- exactly where a hang dump lands, since the writer then stops producing -- was never drained. Read the raw pipe instead and decode incrementally. Enable the flag for post-merge multi-GPU stages only (22 stages). Those are where a lost stage costs the most GPU-hours per occurrence; pre-merge keeps its current, quieter console. PerfSanity stages are excluded. Measured cost is roughly 340-450 KB of extra console per executed test, so the increase tracks how much of a run actually executes rather than being a fixed multiple. Signed-off-by: JunyiXu-nv <219237550+JunyiXu-nv@users.noreply.github.com>
|
/bot run |
WalkthroughJenkins selectively enables ChangesS3 console echo
Estimated code review effort: 4 (Complex) | ~45 minutes Sequence Diagram(s)sequenceDiagram
participant Jenkins
participant PytestHooks
participant SessionCapture
participant SessionSpoolEchoer
participant ConsoleFD
Jenkins->>PytestHooks: pass --s3-echo-stdout
PytestHooks->>SessionCapture: set echo_to_console
SessionCapture->>SessionSpoolEchoer: start spool tailing
SessionSpoolEchoer->>ConsoleFD: write new spool bytes
SessionCapture->>SessionSpoolEchoer: stop and drain before closing spool fds
Suggested reviewers: 🚥 Pre-merge checks | ✅ 5✅ Passed checks (5 passed)
✨ Finishing Touches🧪 Generate unit tests (beta)
Comment |
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 1
🧹 Nitpick comments (1)
tests/unittest/test_s3_output.py (1)
458-560: 📐 Maintainability & Code Quality | 🔵 Trivial | ⚡ Quick winTest coverage summary (QA).
- Test functions added:
test_session_capture_echoes_output_to_console_before_the_test_ends,test_session_capture_does_not_echo_to_console_by_default,test_fd_redirector_echoes_a_partial_chunk_without_waiting_for_more(plus helper_drain_console_pipe).- Test list registration: these are standard
tests/unittest/pytest tests, which TensorRT-LLM CI collects and runs as a whole rather than via explicit entries intests/integration/test_lists/test-dborqa/(those lists gate GPU-specific integration test selection). No new list entries are required.- Verdict: sufficient — the three tests directly cover the PR's stated goals (live echo during a hang, default no-echo behavior, and prompt partial-chunk echo for the binary pipe change). One gap: none of the new tests exercise a broken echo destination (e.g.,
os.writeto a closed/broken console fd) — this matters given the major issue raised onFDRedirector._reader_loopintests/test_common/s3_output.py; consider adding that regression test once the write-failure handling is fixed there.🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@tests/unittest/test_s3_output.py` around lines 458 - 560, Add a regression test covering a broken echo destination for FDRedirector._reader_loop, such as closing the original console file descriptor before captured output is written. Verify the reader handles the write failure without hanging or crashing and still completes cleanup, using the existing FDRedirector test patterns.Source: Path instructions
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@tests/test_common/s3_output.py`:
- Around line 382-388: Update `_reader_loop` to isolate `os.write(self.saved_fd,
raw)` failures from the primary log-file capture: catch echo-specific `OSError`
without terminating the loop, while preserving per-test log writing. Replace the
single echo write with full-buffer retry behavior equivalent to
`SessionSpoolEchoer._write_all`, ensuring partial writes continue until all
bytes are flushed or the echo destination fails.
---
Nitpick comments:
In `@tests/unittest/test_s3_output.py`:
- Around line 458-560: Add a regression test covering a broken echo destination
for FDRedirector._reader_loop, such as closing the original console file
descriptor before captured output is written. Verify the reader handles the
write failure without hanging or crashing and still completes cleanup, using the
existing FDRedirector test patterns.
🪄 Autofix (Beta)
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Path: .coderabbit.yaml
Review profile: CHILL
Plan: Enterprise
Run ID: 3dfbb1d7-60f8-4a21-ab42-8ab2b961ac5b
📒 Files selected for processing (4)
jenkins/L0_Test.groovytests/test_common/s3_output.pytests/test_common/s3_output_hooks.pytests/unittest/test_s3_output.py
|
PR_Github #62129 [ run ] triggered by Bot. Commit: |
|
Converting to draft — an adversarial review found a blocker plus four real defects. Fixes in progress; I'll mark ready once they land and CI is clean. Blocker. This PR breaks an existing pre-merge test on every PR, not just post-merge ones: Also confirmed, with reproductions:
Open question for whoever reviews next: the gate enables full stdout+stderr echo on 22 stages, 3 of which are Slurm multi-node where the job log is Verified non-issues, so nobody re-checks them: incremental UTF-8 decode is correct across split multi-byte boundaries (0 replacement chars); no thread leak under |
…ariant test
Follow-up to the console echo change; five defects found in review.
Update `test_s3_stdout_echo_requires_explicit_opt_in`, which asserted that
every `--s3-echo-stdout` line is guarded by `if (ENABLE_S3_ECHO_STDOUT)`. That
invariant is what this feature deliberately widens, so the test now encodes the
new rule instead: echo must be reachable *only* from the build parameter or
from `shouldEchoTestOutputToConsole()`, and that gate must keep checking
post-merge, multi-GPU, not-PerfSanity, and the kill switch. Verified by
mutation that it still fails on each of those four regressions.
`SessionSpoolEchoer` fixes:
- A broken console (EPIPE) was retried every poll forever. Each warning went to
stderr, into the spool being read, and fed itself: 13 warnings in 3s, growing
without bound, injected into the very artifact this must not regress. Drop
the reader on the first read or write error and log once; 2 warnings total.
- `stop()` closed the readers even when the join timed out, so a still-running
thread hit `ValueError: closed file`, which is not an `OSError`, escaped
`_drain`, and printed a `threading.excepthook` traceback on the real stderr
where a triager reads. Catch `(OSError, ValueError)`, add a `_closed` flag the
thread checks, and leave the readers open when the thread outlives the join --
leaking two descriptors at process exit is the cheaper bug. Join timeout cut
to 2s: a graceful exit needs one poll interval, anything longer is a stuck
write and stalling teardown on it buys nothing.
- `start()` was outside the try/except that unwinds the spools, so
`RuntimeError("can't start new thread")` propagated out of
`pytest_load_initial_conftests` before the capture cleanup was registered,
leaving fd 1 and 2 pinned to the spool and pytest's own traceback inside it --
a silent nonzero exit. A best-effort diagnostic must never do that.
- Writes of up to 1 MiB are not atomic on a pipe and spliced pytest's progress
markers. Cap each write at PIPE_BUF.
- Bound total echoed bytes (128 MiB) and add the `disableStdoutEchoOnPostMerge`
build parameter, so console volume has a ceiling and an off switch that does
not need a merge.
Also correct the overstated claim in the Groovy comment and the class
docstring. Echo recovers everything written up to roughly a poll interval
before the process dies, which covers a HangDetector report. It does not
recover pytest-timeout's own stack dump, written immediately before
`os._exit`; that still reaches only the spool, exactly as it does today.
Signed-off-by: JunyiXu-nv <219237550+JunyiXu-nv@users.noreply.github.com>
|
All six review items addressed in Blocker fixed properly. The invariant test was rewritten to encode the new rule rather than working around the old regex, and renamed I independently mutation-tested the replacement to confirm it is protective rather than a rubber stamp:
Honest-claim correction (item 2). Rather than shim Other fixes: reader dropped on first read/write error, so the EPIPE storm is gone (measured 13 warnings → 2, spool injection 1633 B → 296 B, thread now exits); Log-volume concern addressed both ways: a 128 MiB session byte budget that stops echoing with a warning naming Verified locally: One caveat left on record by the author: a session-wide cap means a pathological test (e.g. the ~39 MB |
|
/bot run |
|
PR_Github #62137 [ run ] triggered by Bot. Commit: |
|
PR_Github #62129 [ run ] completed with state |
There was a problem hiding this comment.
Caution
Some comments are outside the diff and can’t be posted inline due to platform limitations.
⚠️ Outside diff range comments (1)
tests/test_common/s3_output.py (1)
512-519: 🩺 Stability & Availability | 🟠 Major | ⚡ Quick winEcho write is still unguarded; an EPIPE here kills the per-test log capture too.
os.write(self.saved_fd, raw)sits inside the sametrythat driveslog_file.write, so aBrokenPipeError/OSErroron the console copy falls through toexcept Exceptionat Line 548 and ends the reader loop — the timestamped log file stops being written as well.SessionSpoolEchoer._echodeliberately isolates this per reader; the same isolation is missing here. Partial writes (Line 516) are also only warned about instead of being flushed to completion, unlike_write_all.🐛 Proposed fix: isolate and fully flush the echo write
if self.echo_to_original and self.saved_fd is not None: - ret = os.write(self.saved_fd, raw) - if ret != len(raw): - logger.warning( - f"Partial write to original FD {self.target_fd}: {ret} != {len(raw)}" - ) + try: + view = memoryview(raw) + while view: + view = view[os.write(self.saved_fd, view) :] + except OSError as e: + logger.warning( + f"Echo to original FD {self.target_fd} failed, disabling echo: {e}" + ) + self.echo_to_original = False🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@tests/test_common/s3_output.py` around lines 512 - 519, Update the echo path in the surrounding reader method so writing to self.saved_fd cannot terminate log-file capture: isolate the console copy from log_file.write, handle BrokenPipeError/OSError without propagating it to the outer reader-loop exception handler, and replace the single os.write call with the existing _write_all-style behavior so partial writes are fully flushed while preserving the warning for genuine write failures.
🧹 Nitpick comments (1)
tests/unittest/test_s3_output.py (1)
539-659: 📐 Maintainability & Code Quality | 🔵 Trivial | ⚡ Quick winQA coverage summary (tests/** path instruction):
- Test functions added:
test_session_echo_drops_a_reader_whose_console_is_gone,test_session_echo_stops_after_the_byte_budget,test_session_capture_survives_an_echo_thread_that_cannot_start,test_session_echo_writes_are_atomic_sized,test_fd_redirector_echoes_a_partial_chunk_without_waiting_for_more(plus helper_drain_console_pipe).- These are unittest-level tests for
tests/test_common/s3_output.pyinternals, not integration tests; inclusion intests/integration/test_lists/test-db/orqa/doesn't directly apply — confirm they remain picked up by the generic unittest collection stage instead.- Verdict: insufficient for one specific hardening claim — the PR objectives call out "shutdown stalls and traceback risk" (the
_JOIN_TIMEOUT_SECONDSbranch inSessionSpoolEchoer.stop()where a still-alive thread is left with open readers rather than closed to avoid aValueErrorescaping intothreading.excepthook), but none of the shown tests exercise that branch. The rest of the hardening (EPIPE drop, byte budget, thread-start failure, atomic write chunking) is sufficient.Want me to draft a test for the join-timeout branch (e.g. monkeypatching
Thread.join/is_alivesostop()observes a still-running thread) and open a follow-up?🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@tests/unittest/test_s3_output.py` around lines 539 - 659, Extend the unittest coverage for SessionSpoolEchoer.stop so it exercises the _JOIN_TIMEOUT_SECONDS path when the worker thread remains alive after join. Use the existing SessionSpoolEchoer symbols and controlled thread behavior to verify stop closes or safely handles open readers without raising, while preserving the existing shutdown behavior for threads that terminate normally.Source: Path instructions
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Outside diff comments:
In `@tests/test_common/s3_output.py`:
- Around line 512-519: Update the echo path in the surrounding reader method so
writing to self.saved_fd cannot terminate log-file capture: isolate the console
copy from log_file.write, handle BrokenPipeError/OSError without propagating it
to the outer reader-loop exception handler, and replace the single os.write call
with the existing _write_all-style behavior so partial writes are fully flushed
while preserving the warning for genuine write failures.
---
Nitpick comments:
In `@tests/unittest/test_s3_output.py`:
- Around line 539-659: Extend the unittest coverage for SessionSpoolEchoer.stop
so it exercises the _JOIN_TIMEOUT_SECONDS path when the worker thread remains
alive after join. Use the existing SessionSpoolEchoer symbols and controlled
thread behavior to verify stop closes or safely handles open readers without
raising, while preserving the existing shutdown behavior for threads that
terminate normally.
ℹ️ Review info
⚙️ Run configuration
Configuration used: Path: .coderabbit.yaml
Review profile: CHILL
Plan: Enterprise
Run ID: a0b3c96d-6f9c-4a16-bddb-a1da7e57199a
📒 Files selected for processing (4)
jenkins/L0_Test.groovytests/test_common/s3_output.pytests/unittest/test_s3_output.pytests/unittest/tools/test_test_to_stage_mapping.py
|
PR_Github #62137 [ run ] completed with state
|
|
Pipeline #50315 (on the post-fix commit
This PR is not implicated:
Re-running CI. |
|
/bot run |
|
PR_Github #62158 [ run ] triggered by Bot. Commit: |
…n model YAML (NVIDIA#16935) Signed-off-by: yufeiwu-nv <230315618+yufeiwu-nv@users.noreply.github.com>
|
PR_Github #62158 [ run ] completed with state
|
|
Pipeline #50333 failed on This PR cannot affect that stage:
Being straight about what I cannot show: that exact test parametrization, and the wider So the case here is structural rather than statistical: the change is gated off for this stage and its code never executes there. Re-running CI. |
|
/bot run |
|
PR_Github #62180 [ run ] triggered by Bot. Commit: |
|
PR_Github #62180 [ run ] completed with state
|
|
Pipeline #50351 failed on A 0.18-point miss against the threshold — a borderline accuracy flake, not a functional failure. Not caused by this PR:
Re-running CI. |
|
/bot run |
|
PR_Github #62221 [ run ] triggered by Bot. Commit: |
|
PR_Github #62221 [ run ] completed with state
|
|
Pipeline #50389 failed on A PyTorch CUDA caching-allocator internal assert — a GPU memory refcount invariant inside PyTorch itself. Not caused by this PR:
For transparency, this is the fourth consecutive failure on this PR, each on a different stage with a different root cause: a Jenkins agent going offline mid-run; Re-running CI. |
|
/bot run |
|
PR_Github #62239 [ run ] triggered by Bot. Commit: |
|
PR_Github #62239 [ run ] completed with state
|
|
Pipeline #50408 failed on three stages — Three This is the same failure that dominated CI earlier today — 138 of 348 stage failures in a 24-hour window carried this exact For accuracy: OpenSearch shows 0 Re-running CI. |
|
/bot run |
|
PR_Github #62251 [ run ] triggered by Bot. Commit: |
|
PR_Github #62251 [ run ] completed with state
|
Pipeline #50420 — diagnosisOne test failed across the whole pipeline, on The other three stages that uploaded results ( Why this PR cannot reach it. The diff is Why this test flakes. Measured ambient rate. I scanned the last 60
So ~5%, on a single observed failure — the interval around that number is wide, and I want to be straight that "1 in 19" is an estimate from one event, not a well-sampled rate. What it does establish is that ours is not a systematically reproducing failure: 18 other executions of the same parameter set passed in the same window. The earlier failure on this PR (#50408) uploaded no test results at all, so it is a different class and not a repeat of this one. Re-running. |
|
/bot run |
|
PR_Github #62298 [ run ] triggered by Bot. Commit: |
|
PR_Github #62298 [ run ] completed with state
|
Pipeline #50467 — blocked by the same repo-wide
|
|
#16978 has merged, so Re-running. The underlying cause — mcp 2.0.0 removed |
|
/bot run |
|
PR_Github #62395 [ run ] triggered by Bot. Commit: |
|
PR_Github #62395 [ run ] completed with state |
| # Echo first: the whole point of echoing is live visibility, and | ||
| # the writer may be killed at any moment. | ||
| if self.echo_to_original and self.saved_fd is not None: | ||
| ret = os.write(self.saved_fd, raw) |
There was a problem hiding this comment.
If writing to the Jenkins console fails, this exception stops the whole reader thread. Could we catch the console write error here, disable echo, and continue writing to the log file?
| if self._closed: | ||
| return | ||
| try: | ||
| while True: |
There was a problem hiding this comment.
If stdout output is very large, this could hide an important error or hang report written to stderr.
4 participants
Problem
Multi-GPU CI stages already run pytest with
-s, but the S3 log plugin then points fd 1/2 at session spool files and publishes each test's slice only once that test finishes. A test that wedges never finishes — pytest's--timeout=3600 --timeout-method=threadends the process withos._exit— so nothing that test, or any MPI worker rank that inherited those fds, wrote ever reaches the stage log.Concretely:
RTXPro6000D-4_GPUs-PyTorch-Post-Merge-2in run 2220 produced a 749 KB node log with zero[TRT-LLM]lines for a 60-minute wedge. The stack dump that identified the root cause was only recoverable by downloading and unpackingresults-<stage>.tar.gzby hand.For calibration, zero
[TRT-LLM]is the norm rather than a hang signal: 61 of 63 sampled multi-GPU stage logs contain none, including 42 of 42 that passed.Change
SessionSpoolEchoer— makes--s3-echo-stdoutwork with the defaultsessioncapture mode by tailing the spool files onto the saved real fds from one session-scoped thread. Capture, per-test slicing and upload are untouched; only the console copy is best-effort, and the spool is still written synchronously by the producer, so an abrupt kill cannot lose more than one poll interval.Deliberately not switching stages to
timestampedmode: measured 0/5 runs preserved pytest-timeout's dump in that mode versus 5/5 in session mode.FDRedirectorreader fix —--s3-capture-mode=timestampedalready accepted--s3-echo-stdout, but its reader calledread(4096)on a buffered text stream (os.fdopen(pipe_read, "r", ...)), which blocks until 4096 characters or EOF. The trailing partial chunk — exactly where a hang dump lands, since the writer then stops producing — was never drained. Measured: 183/200 chatter lines echoed but 0/3 detector lines. Now reads the raw pipe and decodes incrementally.shouldEchoTestOutputToConsole(stageName)— post-merge ∧ >1 GPU ∧ ¬PerfSanity, reusing the existingparseTaskConfigFromStageName. Simulated against all 132 declared stages: 22 enabled, 13 PerfSanity excluded.Test evidence
Unit: 3 new tests in
tests/unittest/test_s3_output.py; 23/23 pass.A/B on real hardware (GB200, 4 GPUs, SLURM + pyxis): the shipped
HangDetectorrunning in a child process that inherits pytest's fd 1/2 — the shape of an MPI worker rank — terminated by a realos.kill(SIGKILL). Same container and same pytest flags CI builds;beforeuses pristineorigin/maintest_common.Before — stage log 687 B, ends mid-line, zero detector output. Spool (2,096 B) holds the whole dump.
After — stage log 3,275 B:
Spool unchanged at 2,097 B — capture/upload intact. The echo won the race against SIGKILL with zero injected delay.
Running
scan_hangkill_v2.py's verbatim patterns over the two real logs: beforehangkill=False; afterhangkill=True, timeout_s=[20], kill_path=self-SIGKILL.Cost
Roughly 340–450 KB of extra console per executed test. Deliberately not stated as a multiplier: the same measurement over two post-merge runs of the same 15 stages gave 14.8x and 0.75x, because one executed 71% of its tests and the other 5% (the rest reused). Console size is dominated by shell trace and barely moves; captured output does not.
Note this measurement method reads 0 captured bytes for stages that were hard-killed before publishing, so it is a lower bound precisely on the stages this targets.
Limitations, stated plainly
MPI_Comm_spawndoes not work under pyxis/enroot here, andmpirun -n 1reroutes worker stdout to mpirun, which is the exact property under test. The chain "MPI worker's fd 1 == pytest's fd 1" rests on code inspection (logger.py:188StreamHandler(sys.stdout)) plus the Jenkins invocation pattern, not on a TP=2 run.os._exit, so it usually lands in the spool but not the console. Unchanged by this PR; the spool copy is not regressed.Dev Engineer Review
jenkins/L0_Test.groovyvia newshouldEchoTestOutputToConsole(stageName)helper, excludingPerfSanity, and honoring a newDISABLE_POST_MERGE_STDOUT_ECHO/disableStdoutEchoOnPostMergekill switch to fully disable console echo in those stages.tests/test_common/s3_output.pywith a newSessionSpoolEchoerthread that tails session spool files and writes new bytes to the original console fds.SessionCapture(..., echo_to_console=False)), exposedSessionFDSpool.console_fd, and plumbed the early option throughtests/test_common/s3_output_hooks.py(--s3-echo-stdout).FDRedirector) to avoid UTF-8 boundary corruption, and ensured echoed output uses raw bytes when echoing to the original fd.--s3-echo-stdoutvalidation constraints to only reject--s3-capture-mode=direct, and updated CLI help text accordingly.QA Engineer Review
Test code added/updated:
tests/unittest/test_s3_output.pytest_session_capture_echoes_output_to_console_before_the_test_endstest_session_capture_does_not_echo_to_console_by_defaulttest_session_echo_drops_a_reader_whose_console_is_gonetest_session_echo_stops_after_the_byte_budgettest_session_capture_survives_an_echo_thread_that_cannot_starttest_session_echo_writes_are_atomic_sizedtest_fd_redirector_echoes_a_partial_chunk_without_waiting_for_moretests/unittest/tools/test_test_to_stage_mapping.py--s3-echo-stdoutwhen eitherENABLE_S3_ECHO_STDOUTis set or when the newshouldEchoTestOutputToConsole(stageName)post-merge / non-PerfSanity/ GPU-gated rules allow it, while still enforcing the disable kill switch.Coverage mapping (per provided instructions):
tests/(outsidetests/integration/test_lists/), so they are covered bytests/integration/test_lists/test-db/only if separately mapped by CI; no explicit updates to those lists are indicated in the provided change summary.