fix: preserve JSON output for slow consumers at shutdown

[masenf]

A slow consumer can lose JSON log output when the supervised command exits: the macOS unit run received only 157 of 200 lines because the five-second drain limit also counted time blocked forwarding output.

Exclude completed and ongoing writes from the five-second active drain budget. Capture each pump's monotonic time and cumulative write duration together under a lock, so a write completing during shutdown cannot corrupt the cutoff. Keep the idle limit for silent descendants and add a shared 30-second wall deadline so a stalled consumer or lingering writer cannot prevent shutdown.

Cover slow stdout and stderr consumers with normal and shortened active budgets, snapshot accounting during and after writes, and lingering writers blocked by unread stdout or stderr pipes. The race and stalled-consumer regressions reproduced the review findings before the fixes. Add a reflex-base changelog fragment documenting the shutdown limit.

Type of change

• Bug fix (non-breaking)

Validation

• macOS, Python 3.14.8, Node 22: 11,258 unit tests passed, 159 skipped; 78.99% coverage.
• All 81 logging tests passed, including slow/stalled stdout and stderr consumers and silent/chatty lingering descendants.
• Repository Ruff lint and formatting checks passed; Pyright reported no errors or warnings.
• Commit hooks passed, including codespell, stub generation, Pyright, and ty.
• Adversarial review found no actionable issues.

[cubic-dev-ai]

All reported issues were addressed across 3 files

<sub>Reply with feedback, questions, or to request a fix.

Re-trigger cubic</sub>

[greptile-apps]

Confidence Score: 5/5

[Medium risk] Changes how the logging system drains output at shutdown.

The PR appears safe to merge; no new issues or outstanding previous findings were identified.

Summary

The PR preserves JSON log output for slow consumers during shutdown while bounding the drain with a 30-second wall deadline.

• Adds synchronized write-duration snapshots and a shared shutdown deadline.
• Expands stdout and stderr coverage for slow and stalled consumers and documents the shutdown limit.

_{Reviews (3) · Last reviewed commit: "ci: rerun PR checks"}

[codspeed]

Merging this PR will not alter performance

✅ 150 untouched benchmarks
⏩ 18 skipped benchmarks¹

---

_{Comparing codex/json-output-slow-consumer (0446d81) with main (e080fbf)}

Footnotes

1. 18 benchmarks were skipped, so the baseline results were used instead. If they were deleted from the codebase, click here and archive them to remove them from the performance reports. ↩

[masenf]

Addressed all four inline review findings in 7f65b46 and updated the PR description. Full macOS validation: 11,258 unit tests passed, 159 skipped, 78.99% coverage; Ruff, Pyright, and commit hooks (including ty) passed.

I also investigated the CodSpeed report for test_state_access[get_handler]. That benchmark does not enter the modified output-supervisor path: it passed locally with _OutputPump construction patched to raise if called. This PR changes no state-handler access code, and the CodSpeed comparison warns that its runtime environments differ. That evidence does not establish a regression caused by this change.

[FarhanAliRaza]

Review notes from running this branch (head 0446d81). Looks good to merge; nothing below needs to block it.

CI: the only red job is unit-tests (ubuntu-latest, 3.12), which fails in test_a_rate_limit_lets_through_a_burst_then_refills with assert 1.127 < 1 (test_runner.py:2027). That is the timing flake #7433 fixes, not this change. All 81 tests in test_log.py pass locally.

Finding: shutdown is only bounded once the child has exited. _DRAIN_WALL_SECONDS starts after proc.wait() returns. If the consumer never reads, the pump blocks in os.write and stops draining the child's pipe, so the child blocks on its own full pipe and never exits. In a quick run (child prints 300 x 1KB lines, parent never reads stdout) the supervisor had not exited after 60s here. I got the same result on main after 45s, so this predates the PR, but the changelog line ("limiting output draining to 30 seconds after the command exits") is accurate only because of "after the command exits". The main run is weaker evidence: my script's own 20s wait timeout never fired there, which I didn't track down.

Nits

• test_output_pump_write_snapshots_use_a_consistent_cutoff patches time.monotonic with Mock(side_effect=[10.0, 15.0, 20.0, 25.0]). Any extra monotonic call (pytest, another thread) raises StopIteration.
• drain budgets each pump from its own exited_at, and pumps drain one after another, so pump N is charged for the time spent draining pumps 1..N-1. The shared wall deadline still bounds the total.

Possible solution: the usual structure in supervisors is to split reading from writing. One thread reads the child's pipe into a bounded queue and a second thread writes the queue to the consumer. The reader never blocks on a slow consumer, so the child never stalls. Shutdown then becomes "read to EOF (or the existing idle limit), then flush the queue under one wall deadline". That would replace _write_state, _write_lock, writing_snapshot and the three-way cutoff in drain, and it would also cover the hang above. The queue needs a size cap so a dead consumer can't grow memory without limit. I haven't prototyped this, so treat it as a suggestion.

---

Generated by Claude Code