Add structured timeout and teardown observability (#284) - #271
Conversation
|
Note Reviews pausedIt looks like this branch is under active development. To avoid overwhelming you with review comments due to an influx of new commits, CodeRabbit has automatically paused this review. You can configure this behavior by changing the Use the following commands to manage reviews:
Use the checkboxes below for quick actions:
Summary
WalkthroughThe change adds structured timeout and teardown-error reporting for subprocesses and pipelines. It adds timeout metadata to execution events, preserves primary exceptions during cleanup, extends metrics and tracing projections, and adds tests and documentation. ChangesTimeout observability
Sequence Diagram(s)sequenceDiagram
participant Pipeline
participant SubprocessWait
participant TimeoutReporting
participant MetricsHook
participant TracingHook
Pipeline->>SubprocessWait: apply deadline and wait for stages
SubprocessWait->>TimeoutReporting: report expiry or drain failure
TimeoutReporting->>MetricsHook: emit timeout or teardown_error phase
TimeoutReporting->>TracingHook: emit ancillary span event
SubprocessWait-->>Pipeline: preserve primary exception
Possibly related PRs
Suggested labels: Suggested reviewers: Poem
Important Pre-merge checks failedPlease resolve all errors before merging. Addressing warnings is optional. ❌ Failed checks (1 warning, 2 inconclusive)
✅ Passed checks (17 passed)
✨ Finishing Touches📝 Generate docstrings
🧪 Generate unit tests (beta)
Comment |
Reviewer's GuideAdds structured, best-effort observability for subprocess timeouts and teardown drain failures across logging, observe events, metrics, and tracing, refactors subprocess execution timeout handling to be caller-owned via asyncio.timeout, and hardens cleanup so telemetry and hook failures cannot mask primary errors, while updating documentation and tests to lock the contracts in place. Sequence diagram for subprocess timeout observability pairsequenceDiagram
actor User
participant SafeCmd_run
participant _execute_subprocess
participant _wait_for_exit_code_within_timeout
participant _report_timeout_expiry
participant _log_timeout_expiry
participant _emit_timeout_event
participant _StageObservation
User->>SafeCmd_run: run(timeout)
SafeCmd_run->>_execute_subprocess: _execute_subprocess(execution)
_execute_subprocess->>_wait_for_exit_code_within_timeout: _wait_for_exit_code_within_timeout(process, execution)
alt timeout <= 0 (non_positive_immediate)
_wait_for_exit_code_within_timeout->>_report_timeout_expiry: _report_timeout_expiry(observation, pid, configured_timeout, "non_positive_immediate")
else timeout > 0 (elapsed_deadline)
_wait_for_exit_code_within_timeout-->>_wait_for_exit_code_within_timeout: asyncio.timeout(timeout) expires
_wait_for_exit_code_within_timeout->>_report_timeout_expiry: _report_timeout_expiry(observation, pid, configured_timeout, "elapsed_deadline")
end
_report_timeout_expiry->>_log_timeout_expiry: _log_timeout_expiry(pid, configured_timeout, mode)
_report_timeout_expiry->>_emit_timeout_event: _emit_timeout_event(observation, pid, configured_timeout, mode)
_emit_timeout_event->>_StageObservation: emit("timeout", _EventDetails(...))
_wait_for_exit_code_within_timeout-->>_execute_subprocess: raise TimeoutError
_execute_subprocess-->>SafeCmd_run: propagate TimeoutError
SafeCmd_run-->>User: TimeoutExpired with partial output
File-Level Changes
Tips and commandsInteracting with Sourcery
Customizing Your ExperienceAccess your dashboard to:
Getting Help
|
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: a17a1241e6
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
a17a124 to
8f78f0c
Compare
1080793 to
bf1e879
Compare
bf1e879 to
41f6ec7
Compare
41f6ec7 to
a9c8eff
Compare
a9c8eff to
a4d04a8
Compare
Complete the developer-facing documentation for the flake8-async work and the timeout telemetry contract, and lock the required wording with documentation- contract tests. - Developers' guide: add a "Ruff `ASYNC` (flake8-async) policy" subsection explaining why the family is selected, the narrowly scoped public-API `# noqa: ASYNC109` on `SafeCmd.run` / `Pipeline.run`, and the test-scaffolding per-file-ignore for `ASYNC109` / `ASYNC240`, linked to the `pyproject.toml` comments. Add a "Subprocess timeout observability" section documenting the `cuprum.timeout` records and their stable `cuprum_*` fields. - ADR-007: add a dated addendum recording the `_wait_for_exit_code` / `_wait_for_exit_code_within_timeout` split, caller-owned `asyncio.timeout` deadlines, the non-positive fast path, the shared `_terminate_and_drain_consumers` teardown, and the invariant that no pending stream-consumer task is left behind on cancellation, expiry, or immediate expiry. - Add `test_async_timeout_docs.py` asserting the required ASYNC-policy and timeout-observability wording, mirroring the repo's documentation-contract test conventions. Regenerate the maturin wheel-manifest snapshot for the new test module. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
Extend the public ExecEvent observe contract with two ancillary phases and two fields so callers can distinguish subprocess timeout conditions through the existing sh.observe() stream rather than a parallel telemetry framework: - `timeout` — a run exceeded its deadline; - `teardown_error` — a stream consumer drained with an unexpected error; - `timeout_s` — the configured timeout in seconds; - `timeout_mode` — `elapsed_deadline` versus `non_positive_immediate`. Wire the new phases through the adapters. The metrics adapter must handle them (its dispatch raises on unknown phases): both increment counters (`cuprum_timeouts_total`, `cuprum_teardown_errors_total`) via a new counter dispatch table that also keeps `__call__` under the complexity ceiling. The tracing adapter records them as ancillary span events that leave the span open for the subsequent `exit`. The logging adapter's existing default path handles them. Regenerate the adapter projection snapshot for the two new phases and add metrics/tracing unit coverage. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
Emit the new `timeout` and `teardown_error` observe events from the subprocess timeout paths, alongside the existing best-effort `cuprum.timeout` log records (mode values unified to `elapsed_deadline` / `non_positive_immediate`). `_wait_for_exit_code_within_timeout` emits `timeout` on both the elapsed and non-positive immediate expiry routes; `_terminate_and_drain_consumers` emits `teardown_error` when a drained consumer surfaces an unexpected exception. The observation is threaded through `_wait_for_exit_code` to the shared teardown solely for this reporting; it never changes control flow. Emission is best-effort via `_safe_emit`, which swallows a synchronous observe-hook failure (including a hook raising `CancelledError`) so telemetry can never mask `TimeoutExpired` or `CancelledError`; `_StageObservation.emit` records scheduled async-hook tasks before raising, so they are still drained. The existing `start`/`exit` events and the public `TimeoutExpired` mapping are unchanged. Add deterministic tests: unit-level recording-observation tests for elapsed and immediate `timeout` events and the `teardown_error` event; end-to-end `sh.observe()` tests driving the non-positive fast path (`run_sync(timeout=0)`) that assert the event contract, the preserved start/exit events, and that a hook failing on the timeout event does not mask `TimeoutExpired`. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
Document the public timeout observe-event contract and lock the required wording with documentation-contract tests. - Users' guide: add the `timeout` and `teardown_error` phases and the `timeout`-event fields (including `timeout_mode` of `elapsed_deadline` / `non_positive_immediate`) to the structured-events section, noting the preserved `start`/`exit` events and `TimeoutExpired`. - Developers' guide: rewrite the timeout observability section to describe the observe events, adapter handling, and the parallel `cuprum.timeout` log records, with the unified mode values. - ADR-007: record that the timeout paths emit best-effort `timeout` / `teardown_error` observe events whose emission failures cannot mask `TimeoutExpired`. - Extend `test_async_timeout_docs.py` with the observe-event terms and add users' guide contract tests for the public run()/run_sync() timeout contract and the timeout events. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
The rebase onto main adopted its "drain stream consumers exactly once" design (#226), which supersedes this branch's `_terminate_and_drain_consumers` helper: the wait helpers now terminate the process only, and the caller drains the consumers once via `_drain_stream_consumers`. Update the ADR-007 addendum and its documentation-contract test to describe that division of labour, replacing the shared terminate-and-drain bullet. The no-orphan invariant is unchanged in substance — it is now upheld by the single caller-side drain rather than by a combined helper. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
CodeScene flagged `_execute_subprocess` as a "Bumpy Road Ahead": the direct (no-capture, no-echo) branch inlined a whole stdin-writer lifecycle — spawn, timeout/cancellation cleanup, and post-exit await — inside the outer timeout-translation `try`, nesting four levels deep and mixing strategy selection with strategy implementation. Move that lifecycle into `_run_subprocess_without_streams`, placed beside its `_run_subprocess_with_streams` sibling so the two execution strategies share a shape. `_execute_subprocess` now only spawns, emits `start`, selects a strategy, translates timeouts, emits `exit`, and builds the `CommandResult`. This is a pure extraction. Preserved unchanged: `TimeoutError` and `CancelledError` propagation from the direct path; stdin-writer cancellation and draining before timeout translation or cancellation propagates; unexpected stdin-writer failures after normal exit; immediate expiry for non-positive timeouts via `_wait_for_exit_code_within_timeout`; `_handle_subprocess_timeout` and its `_SubprocessTimeoutContext` (still `None`/`None` for the direct path and captured partial output for the stream path); timeout and teardown telemetry; and the `start`/`exit` observe events. Existing integration tests already exercise the extracted helper end-to-end (direct stdin delivery, timeout escalation, the parametrized blocked-writer timeout, and cancellation cleanup), so no test was added for moved code. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Verify each review finding against the current code and fix the still-valid ones. Fixed: - `_subprocess_execution`: extract `_report_timeout_expiry`, which pairs the `cuprum.timeout` log record with the `timeout` observe event. Both expiry branches reported through an identical two-call sequence differing only in timeout value and mode. - `events`: move the paragraph describing the `timeout` and `teardown_error` phases out of the `duration_s` attribute docs, where it was misfiled, and into the `phase` docs. `duration_s` is again limited to elapsed duration. - `users-guide`: the non-positive timeout paragraph said the process was terminated "without waiting on it", implying cleanup was skipped. It is not: the path runs the normal terminate / `cancel_grace` / `SIGKILL` escalation and drains consumers before raising `TimeoutExpired`. Only the unbounded wait for a self-exit is skipped; say so. - `test_tracing_adapter`: merge the near-identical `stdin_error` and `timeout` span-event tests into one parametrized test that also covers `teardown_error`, which had no tracing coverage at all — a broken dispatch there passed the suite. Verified by mutation: dropping `teardown_error` from the adapter's dispatch now fails the new case. - `test_metrics_adapter`: the timeout fixture used `timeout_mode="elapsed"`, a value the code never emits. Use `elapsed_deadline`. Inert for the assertion, but misleading as documentation. - Split `test_subprocess_timeout` (674 lines) into cleanup, structured-logging, and observe-event modules over a shared `_timeout_test_helpers` doubles module, each well under the 400-line ceiling. This branch caused the overage. Test count is unchanged at 18. - Give the previously bare timeout/teardown field assertions failure messages naming the expected field and value, matching both files' prevailing style. The two repeated five-field clusters became message-bearing helpers. Skipped: - Converting `MetricsHook.__call__` back to `match`/`case`: the if/elif shape exists precisely because the earlier match/case version failed ruff `C901 (10 > 8)`. A guard-based rewrite reproduces the same decision count, so it would reintroduce the failure for no readability gain. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Verify each review finding against the current code and fix the still-valid ones. All nine were valid; two needed reshaping once measured. Correctness: - `_run_subprocess_with_streams` / `_run_subprocess_without_streams` only ran their cleanup for `TimeoutError` and `CancelledError`, so any other escape leaked the stdin writer and, in the streamed path, the stream consumers. Broaden both to `except BaseException`, after the timeout-specific clause so precedence is unchanged. The reachable escapes are an unguarded `wait_for_exit()` inside `_terminate_process` and a `BaseException` past the best-effort telemetry; the `_SubprocessInvariantError` route the review cited is in fact unreachable, since a `None` timeout never schedules a deadline. Deduplication: - Consolidate the teardown drain-failure log and observe event into `_report_teardown_drain_failure`, mirroring `_report_timeout_expiry`. The comma-joined error-class list was previously built twice from the same tuple; it is now built once and shared, with the event emitted only when an observation is available. - Convert `MetricsHook.__call__` dispatch to `match`/`case`. This was skipped once before on the grounds that match/case tripped ruff `C901 (10 > 8)` — measured again here, the guard-based form that keeps delegating to the existing helpers passes C901 comfortably. The earlier failure came from a different shape that gave every counter phase its own case. Observability: - Record `timeout_s` and `timeout_mode` on tracing span events, so a consumer can tell an elapsed deadline from an immediate non-positive expiry. The fields were dropped from this adapter earlier because the module hit pylint's 400-line ceiling; hoisting the field list into a one-line `_SPAN_FIELDS` constant fits them back in. Verified by mutation: removing the pair now fails the timeout case. Tests: - `test_observe`: assert the lifecycle ORDER (start before timeout, timeout before exit), not just membership, so a regression emitting them out of order is caught. - `test_subprocess_timeout_logging`: give the drain-failure assertions explanatory messages, matching `_assert_timeout_log_fields`. Lint scope: - Narrow the ASYNC109/ASYNC240 per-file-ignores from the blanket `**/test_*.py` to the two modules that actually poll a PID/marker file with asyncio-only helpers. The other suppressions stay broadly scoped. Verified the ASYNC group still passes repo-wide under the narrower exemption. Docs: - `events`: the `pid` entry claimed availability for `start` and `exit` only. It is populated for every phase except `plan`; say that rather than enumerating a list that has now gone stale twice. - ADR-007: the addendum asserted no observable timeout semantics changed while the bullet above it documented new observe events and diagnostics. Narrow the claim to the public API, `TimeoutExpired` and its payload, and timeout/exception precedence, and name the telemetry as additive. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
CodeScene flagged `test_records_ancillary_event_without_ending_span` with "Excess Number of Function Arguments (Arguments = 5)": the parametrized test carried `expected_operation`, `expected_error_type`, and `expected_extras` alongside `phase` and `extra_fields`, so every case had to thread three separate expectation slots — two scalars plus a catch-all mapping that only the timeout case populated. Fold the three into a single `expected_attributes` mapping per case and assert it with one loop, keyed by attribute name. The split between "the two every phase has" and "the extras only one phase has" was an artefact of how the timeout fields were added later, not a real distinction: every asserted attribute is just an expected span-event attribute. No production code, tracing behaviour, or tested contract changes. All three phases still assert their full attribute set — `operation` and `error_type` throughout, plus `timeout_s` and `timeout_mode` for `timeout`. Verified by mutation: dropping the timeout pair from `_SPAN_FIELDS` fails only the timeout case, and dropping `operation` fails all three. `cs check` on the file goes from 9.68 with the warning to 10.00 clean, with no suppression added. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
`_execute_with_hooks` drained the pending observe-hook tasks by awaiting `_wait_for_exec_hook_tasks` directly inside its `except` clauses. That helper re-raises the first failed task, so the `raise` on the following line was never reached: a failing background hook replaced the very exception the cleanup was unwinding. A caller writing `except TimeoutExpired` would instead see the hook's error, with the timeout demoted to `__context__`. Only async hooks are affected. A synchronous hook failure is swallowed at emit time by `_safe_emit`; a hook returning an awaitable is scheduled as a task whose failure surfaces later, during the drain, where `_safe_emit` cannot see it. That is why the existing "hook failure does not mask TimeoutExpired" test passed while the bug was live — it used a synchronous hook. The pipeline path already solved this with `_drain_tasks_during_cleanup`, which aggregates the drain failure with the active error into a `BaseExceptionGroup`. Reuse it for the single-command path rather than inventing a second mechanism; the helper gains a `message` parameter so each path names its own finalization, defaulting to the existing pipeline text. Add regression tests for both cleanup branches, driving real executions: an immediate `timeout=0` expiry and a cancellation gated on the real `start` event. Both fail against the previous code with the hook's `_ObserveTaskError` in place of the primary exception, and pass now with it aggregated alongside. Also add Hypothesis coverage for the telemetry-pairing invariant that `_report_timeout_expiry` and `_report_teardown_drain_failure` exist to uphold: over generated pids, timeouts, modes and error-class lists, the log record and the observe event must fire exactly once each and agree field for field. The existing per-channel tests each pin one channel for one fixed case and would not catch the two drifting apart. Records are captured with a per-example handler because Hypothesis does not reset function-scoped fixtures such as `caplog` between generated inputs. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
`_drain_tasks_during_cleanup` defaulted `message` to `_PIPELINE_FINALIZATION_ERROR`. That default made sense while the helper was pipeline-only, but it became a footgun once the single-command path started sharing it: a caller that forgot the keyword would silently report "pipeline finalization failed" from a non-pipeline context. Drop the default so the parameter is required, and name the label at each of the four pipeline call sites and the one test call site. `message` was already keyword-only, so only the default changed; aggregation behaviour is untouched. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
The users' guide named the `timeout` and `teardown_error` phases but stopped short of the contract a consumer needs to act on them. - `teardown_error` fields: `operation="drain"`, `pid`, and the comma-joined failure classes in `error_type`, plus the fact that only unexpected (non-`CancelledError`) drain failures are reported. - The `cuprum.timeout` log channel, which reaches an operator with no observe hook registered: both record messages, their `cuprum_*` extra fields, and the best-effort emission guarantee. Notes that both channels are populated from one shared set of values so they cannot disagree. - The metrics counters: `cuprum_timeouts_total` and `cuprum_teardown_errors_total`, and the two stdin counters the list had also omitted. Records that the metrics hook rejects an unknown phase rather than ignoring it, unlike the tracing and logging adapters. - Ancillary tracing span events: the `cuprum.<phase>` naming, the fields carried, and the span-lifecycle guarantee that the span is neither ended nor marked so `exit` still closes it. - Corrects the stale `cuprum_phase` list in the logging adapter section, which stopped at `exit`. Five parametrized doc-contract tests pin the new wording. Verified load-bearing: 19 of the 27 new parameters fail against the pre-edit guide. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
`ExecEvent` is a public, frozen — but not `kw_only` — dataclass, so callers may construct one positionally. `timeout_s` and `timeout_mode` were inserted between `error_type` and `exec_id`, which silently rebinds such a call: the correlation token lands on `timeout_s` and `exec_id` falls back to `None`. Consumers then treat the event as uncorrelatable — `TracingHook` drops it outright — so the failure is silent at both ends. Append the two fields after `exec_id` instead, restoring its slot, and record the rule in the class docstring so the next optional field goes to the end rather than beside the field it relates to. All in-tree construction sites already pass keywords, so nothing internal changes; this is for external callers. `test_exec_id_keeps_its_positional_slot` pins both the field order and a positional construction, and is mutation-verified to fail against the previous ordering. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
`Pipeline.run(..., timeout=...)` enforces its deadline once for the whole run, so `_collect_pipeline_inputs` translated `TimeoutError` straight into `TimeoutExpired` and never passed through the single-command reporting call in `_wait_for_exit_code_within_timeout`. A pipeline expiry was therefore silent on all three channels: no `timeout` observe event, no `cuprum.timeout` log record, and no `cuprum_timeouts_total` increment — while the users' guide promised that every expiry emits them. Route the pipeline path through the same reporting helper. Events are emitted per stage, as every other pipeline phase is, so each carries its own `pid`. `timeout_mode` is derived the same way as for a single command: a non-positive timeout is `non_positive_immediate`, since the pipeline's `max(0.0, deadline - now)` plus `wait_for`'s zero semantics also expire without suspending. Reporting runs while `TimeoutExpired` is already propagating, so it is wrapped in a suppression: telemetry must not displace the exception a caller is waiting to catch. Extract `cuprum/_timeout_reporting.py` to hold the now-shared surface — the `cuprum.timeout` logger, the `_log_*`/`_emit_*` helpers, and the three `_report_*` pairing helpers. A separate module rather than a home in `_subprocess_timeout` because the pipeline caller cannot import that module without closing an import cycle; for the same reason it takes `_EventDetails` from `_pipeline_types`, which defines it, rather than `_pipeline_internals`, which re-exports it. The split also returns `_subprocess_timeout` (510 lines) and `_pipeline_internals` (417) to the 400-line ceiling, at 264 and 382. `test_pipeline_timeout_telemetry` covers all three channels and both timeout modes; four of its five tests are mutation-verified to fail without the reporting call, the fifth being the exception-precedence guard. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
The `ExecEvent.phase` docstring claimed both ancillary phases are "emitted
before the existing exit event and the public TimeoutExpired, which are
preserved". That is true of `timeout`, but wrong of `teardown_error`. Cleanup
also runs on external cancellation and on an unexpected stdin-writer failure
(`_run_subprocess_with_streams`, the `except BaseException` and stdin-await
clauses), and on those paths the original exception propagates unchanged: no
`exit` event follows and no `TimeoutExpired` is raised, so a `teardown_error`
can be the last event a consumer sees. Keep the guarantee for `timeout`, and
document `teardown_error` as carrying none.
`_emit_timeout_log` suppressed only `Exception`, while its sibling
`_safe_emit` suppresses `asyncio.CancelledError` too. Since `CancelledError`
derives from `BaseException`, a logging handler raising it would escape and
replace the timeout the record describes. The asymmetry was undocumented and
looks like an oversight rather than a decision. Worth being precise about the
severity: the body has no `await`, so task cancellation cannot land inside it
on its own — the reachable case is a handler that raises, which is what the
new test does. Mutation-verified: restoring the narrower suppression fails it
with `CancelledError` in place of `TimeoutError`.
Test scaffolding gains a structural `_Observation` protocol. The doubles were
previously reconciled with casts, including
`typ.cast("_RecordingObservation", _RaisingObservation())` — a cast to the
wrong double entirely, which happened to work only because the callee touches
nothing but `emit`. Typing `_DeadlineObservation` against the protocol removes
that lie and the three `typ.cast("typ.Any", ...)` casts; where a test still
crosses into a production signature the cast now names the real type.
Also from the same review: assert the finalization label reaches
`BaseExceptionGroup.message` rather than only checking it was passed; assert
ancillary phases leave `metrics.histograms` empty, not just that the counter
moved; name the deliberately-failing observe hook's exception
`_ObserveHookError` so the assertion cannot pass on an unrelated
`RuntimeError`; correct two docstrings that named `mode="elapsed"` /
`mode="immediate"` instead of the emitted `elapsed_deadline` /
`non_positive_immediate`; state that `cuprum_timeouts_total` counts pipeline
as well as subprocess expiries; and correct the developers' guide, which said
the metrics reducer is total over "seven phases" when `ExecPhase` has nine and
the reducer already handles all of them.
Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Two `_terminate_process` calls in `_subprocess_execution` bypassed the shielding that protects every other termination fan-out: the `CancelledError` branch of `_wait_for_exit_code`, and the non-positive fast path in `_wait_for_exit_code_within_timeout`. Both now route through `_terminate_all_shielded`. The first is a live process leak, reproduced end to end. A deadline expiry already consumes one cancellation to reach that teardown, so a caller's own `cancel()` is delivered straight to the grace-period wait inside it. Against a `SIGTERM`-immune child with `timeout=0.3` and `cancel_grace=4.0`, cancelling at 0.6s ended the run at 0.62s with the child **still alive** — the `SIGKILL` escalation never ran. With the shield the run takes the full 4.31s and the child is reaped. Worth being precise about what the review claimed versus what holds. Its framing — that cleanup awaits in `_run_subprocess_with_streams` and `_run_pipeline` are exposed — is right for the timeout-triggered branches, where an internal deadline (not the caller's cancellation) is what entered the handler, so the caller's first `cancel()` can land on the cleanup. It is overstated for the `except BaseException` branches: asyncio does not redeliver a cancellation a coroutine has already caught and run past, so interrupting those needs a second, distinct `cancel()` that no ordinary caller issues. The sharpest and most concrete gap was neither of the two functions named, but the unshielded `_terminate_process` calls above — the ones that can leave a live child rather than merely skip a drain. The remaining unshielded drains (`_cancel_stdin_writer`, `_drain_stream_consumers`, `_reconcile_pipe_tasks`, `_gather_pipeline_outputs`, `_drain_tasks_during_cleanup`) lose observability and completion guarantees rather than leaking a process, since `asyncio.gather` propagates cancellation to its children. Left alone for now and reported separately. `test_cancellation_during_grace_still_escalates_to_kill` pins the fix with a `SIGTERM`-immune double, coordinating on an `asyncio.Event` set by `terminate()` so the cancellation lands inside the grace period rather than being timed by a sleep. Mutation-verified: restoring the bare `_terminate_process` fails it. Documentation, from the same review: - `docs/cuprum-design.md` still claimed `ExecPhase` has seven phases in three places, including a `Literal` sample; it has nine. The metrics-reducer list was also missing `start`, predating this branch. The §8.1.5 module enumeration omitted `_timeout_reporting.py` and `_subprocess_context.py`. - `docs/developers-guide.md` attributed the direct-path stdin cleanup to `_execute_subprocess`; it moved to `_run_subprocess_without_streams` when that helper was extracted. - `CHANGELOG.md` gains an Unreleased `Added` entry for the telemetry, stating that adoption is additive. The guide's own "seven phases" claim was already corrected on this branch, so that half of the review finding no longer applied. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
`_subprocess_execution` carried `# pylint: disable=too-many-lines` at 441 lines, with a TODO pointing at issue #30 — which is closed, and was about adding stdin support rather than about this refactor. The suppression was being carried rather than earned, and the reference had rotted. Extract `cuprum/_subprocess_wait.py`: `_cancel_pending_consumers`, `_wait_for_exit_code`, `_drain_stream_consumers`, and `_wait_for_exit_code_within_timeout`. That is a real seam rather than a cut to hit a number — the runner module is about orchestration (spawn, wire streams, assemble the result), while these four are the rules for *ending* a run: how a deadline is applied, when the process is terminated, and how the consumers are drained exactly once. `_subprocess_execution` drops to 295 lines, so the suppression and the stale TODO both go. Direct pylint now flags only `cuprum/sh.py` (701 lines), which is pre-existing and untouched here. Three details worth recording: - `_spawn_stream_consumers` deliberately stays put. `test_safe_cmd_streams` patches it by module path, and moving it would have broken that silently. - Importers are repointed at the new module rather than re-exported through the old one. A facade would have kept the diff smaller but left `__all__` advertising names the module no longer defines. - The split necessarily lands on this branch, not the parent: the extracted code imports `_report_timeout_expiry` and `_report_teardown_drain_failure` from `_timeout_reporting`, which only exists here. Pure move, no behaviour change: 955 Python tests pass, both modules score 10.00 on code health, and the `_SubprocessExecution` back-reference is TYPE_CHECKING-only so no import cycle forms. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Rebased onto main now that #223 has merged, so this branch sits directly on trunk. Then a review round: A pipeline stage that timed out reported its `timeout` event and then went silent. The success path emits each stage's terminal `exit` from `_build_pipeline_stage_results`, which a timeout never reaches — it raises out of `_collect_pipeline_inputs` first. The single-command path has no such gap, since `_handle_subprocess_timeout` emits `exit` before raising. That asymmetry leaked spans, not just symmetry: `TracingHook` ends a span only on `exit`, so every timed-out stage left one open for the tracer's lifetime. `_emit_timeout_exit_events` closes it, emitted after the timeout reports and before `TimeoutExpired` propagates, preserving the documented timeout → exit → TimeoutExpired ordering. Mutation-verified: without it the new tests fail with two spans still open. The review also suggested narrowing the `events.py` ordering guarantee to paths that emit `exit`. Not done, deliberately — emitting the event makes the existing guarantee true rather than something to hedge, and a hedged contract is the weaker outcome for consumers. Adding the helper pushed `_pipeline_internals` to 434 lines against the 400 ceiling, so `_pipeline_results` splits out the per-stage reporting: the terminal event a stage owes its observers and the `CommandResult` assembled alongside it. Both the success and timeout paths now emit that event from one module. The adapter-projection snapshot could not have caught an adapter dropping the timeout fields. Its "fully populated" event left `operation`, `error_type`, `timeout_s` and `timeout_mode` at `None` for the ancillary phases, so their absence downstream proved nothing. Populating them alone would not have helped: `_build_extra` and `_build_attributes` both project through `_event_common_fields`, which carries only lifecycle fields, so the review's suggestion to assert these in `logging_extra`/`tracing_attributes` would have failed against correct code. Tracing carries them through `span.add_event` instead, so the snapshot gains a `tracing_span_event` projection that pins them — and now shows plainly that the other two channels do not. Verified by dropping `timeout_s`/`timeout_mode` from `_SPAN_FIELDS`: the snapshot fails. Smaller items from the same review: - `_ObserveTaskError` inherits `Exception`, matching its identically named sibling in `test_cqrs_hook_behaviour` and every other test-local error class bar one. - The CHANGELOG claimed both phases carry `timeout_s`/`timeout_mode`; only `timeout` does. `teardown_error` carries `operation="drain"` and the comma-joined failure classes, with both timeout fields unset. - `docs/cuprum-design.md` §8.1.3 still listed seven phases as "the full `ExecPhase` set". §7.1 had been corrected earlier; this second list was missed. Skipped: the `sh.py` "finalisation" spelling fix. The word does not appear — there or anywhere in the repo. It already reads "finalization", so there is nothing to change. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
4cce54c to
7b10be8
Compare
|
Note GitHub couldn't provide a complete incremental comparison for this pull request, so CodeRabbit is performing a full review instead. This review may take a little longer. |
There was a problem hiding this comment.
Actionable comments posted: 8
Caution
Some comments are outside the diff and can’t be posted inline due to platform limitations.
⚠️ Outside diff range comments (1)
cuprum/_pipeline_types.py (1)
71-83: 📐 Maintainability & Code Quality | 🔵 Trivial | ⚡ Quick winUse
ExecPhaseinemit().Import it alongside
ExecEventand remove the duplicatedLiteral[...]declaration. The two declarations contain the same nine phases.🤖 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 `@cuprum/_pipeline_types.py` around lines 71 - 83, Update emit() to accept the shared ExecPhase type instead of its duplicated Literal declaration, and import ExecPhase alongside ExecEvent. Preserve the existing nine-phase API values while removing the redundant inline declaration.
🤖 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 `@cuprum/_pipeline_results.py`:
- Around line 51-61: Guard each stage’s obs.emit call in
_emit_timeout_exit_events with per-stage best-effort suppression of Exception
and asyncio.CancelledError, ensuring one hook failure does not replace
TimeoutExpired or stop later exit emissions; move asyncio to runtime imports as
needed. No direct change is required in cuprum/_pipeline_internals.py lines
319-328 once this guard is added; confirm the original TimeoutExpired is still
re-raised. Add coverage for a synchronous exit hook failure during timeout,
verifying TimeoutExpired reaches the caller and every stage emits exit.
In `@cuprum/_timeout_reporting.py`:
- Around line 234-246: Update the timeout reporting loop around
_report_timeout_expiry so asyncio.CancelledError from process.pid access is
suppressed at the pipeline boundary, while preserving propagation of the
original TimeoutExpired. Ensure the guard covers the entire
per-observation/process reporting operation, including evaluating process.pid,
rather than relying only on inner telemetry suppression.
In `@cuprum/adapters/tracing_adapter.py`:
- Around line 253-254: Update event handling in
cuprum/adapters/tracing_adapter.py lines 253-254 so teardown_error uses
lifecycle handling that supports either event order and records the failure
without losing valid lifecycle data. Finalize and remove active spans for
teardown-only executions in lines 324-330, while safely handling teardown_error
after exit; replace the assertion requiring ancillary events to leave spans
open. Add tests in cuprum/unittests/test_tracing_adapter.py lines 147-234
covering both final teardown_error and teardown_error-after-exit orderings.
In `@cuprum/events.py`:
- Around line 155-158: Define and export a public TimeoutMode alias in
cuprum.events covering the two supported literal values, then annotate
ExecEvent.timeout_mode and _EventDetails.timeout_mode with it. Update
_timeout_reporting._TimeoutMode to alias the public TimeoutMode instead of
defining a separate type, preserving existing behavior.
In `@cuprum/sh.py`:
- Line 26: Move the _drain_tasks_during_cleanup definition from its current
module into _observability.py beside _wait_for_exec_hook_tasks, export it there,
and update imports in cuprum/sh.py, cuprum/_pipeline_internals.py, and the unit
tests to use the new location.
In `@cuprum/unittests/test_pipeline_timeout_telemetry.py`:
- Around line 188-191: Update the ordering assertion in the pipeline timeout
telemetry test to group events by pid and, for each stage with a timeout, verify
that its timeout event occurs before the corresponding exit event. Replace the
global phases.index checks while preserving the failure context in assertion
messages.
In `@docs/users-guide.md`:
- Around line 999-1010: Update the “Ancillary span events” documentation to
state that the execution’s open span remains unended and unmarked until an exit
event is emitted, and that exit closes it when present; remove the implication
that exit always follows teardown_error. Preserve the existing event-field and
exec_id correlation details.
- Around line 397-410: Update docs/users-guide.md lines 397-410 to document
cuprum_operation as "drain" instead of "teardown", keeping the teardown_error
event description consistent. In cuprum/unittests/test_async_timeout_docs.py
lines 232-255, strengthen the documentation assertion to verify that
cuprum_operation is specifically associated with "drain", rather than asserting
the terms independently.
---
Outside diff comments:
In `@cuprum/_pipeline_types.py`:
- Around line 71-83: Update emit() to accept the shared ExecPhase type instead
of its duplicated Literal declaration, and import ExecPhase alongside ExecEvent.
Preserve the existing nine-phase API values while removing the redundant inline
declaration.
🪄 Autofix
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: Organization UI
Review profile: ASSERTIVE
Plan: Pro Plus
Run ID: 4e9f58ae-8daf-49c8-b362-82ea370f38a6
📒 Files selected for processing (34)
CHANGELOG.mdcuprum/_pipeline_internals.pycuprum/_pipeline_results.pycuprum/_pipeline_types.pycuprum/_subprocess_execution.pycuprum/_subprocess_timeout.pycuprum/_subprocess_wait.pycuprum/_timeout_reporting.pycuprum/adapters/metrics_adapter.pycuprum/adapters/tracing_adapter.pycuprum/events.pycuprum/sh.pycuprum/unittests/__snapshots__/test_adapter_projection.ambrcuprum/unittests/__snapshots__/test_maturin_build.ambrcuprum/unittests/_adapter_test_support.pycuprum/unittests/_timeout_test_helpers.pycuprum/unittests/test_adapter_projection.pycuprum/unittests/test_async_timeout_docs.pycuprum/unittests/test_cqrs_hook_behaviour.pycuprum/unittests/test_metrics_adapter.pycuprum/unittests/test_observe.pycuprum/unittests/test_observe_async_hook_failure.pycuprum/unittests/test_pipeline_timeout_telemetry.pycuprum/unittests/test_public_api.pycuprum/unittests/test_subprocess_timeout.pycuprum/unittests/test_subprocess_timeout_logging.pycuprum/unittests/test_subprocess_timeout_observe.pycuprum/unittests/test_subprocess_timeout_properties.pycuprum/unittests/test_timeout_telemetry_pairing.pycuprum/unittests/test_tracing_adapter.pydocs/adr-007-subprocess-execution-module-boundaries.mddocs/cuprum-design.mddocs/developers-guide.mddocs/users-guide.md
🔗 Linked repositories identified
CodeRabbit considers these linked repositories for cross-repo context during reviews:
leynos/shared-actions(auto-detected)leynos/pylint-pypy-shim(auto-detected)leynos/whitaker(auto-detected)
| # Appended after exec_id to keep its positional slot stable; see the note | ||
| # in the class docstring. | ||
| timeout_s: float | None = None | ||
| timeout_mode: str | None = None |
There was a problem hiding this comment.
📐 Maintainability & Code Quality | 🔵 Trivial | ⚡ Quick win
🧩 Analysis chain
🏁 Script executed:
#!/bin/bash
set -euo pipefail
# Locate any existing public alias for the timeout modes.
rg -nP --type=py 'TimeoutMode|elapsed_deadline|non_positive_immediate' -g '!**/unittests/**'
# Map the public event surface to check what is already exported.
fd -t f 'events.py' -p cuprum --exec ast-grep outline {} --items all
# Find consumers that compare timeout_mode against a string literal.
rg -nP --type=py -C3 'timeout_mode\s*(==|!=|in)\s'Repository: leynos/cuprum
Length of output: 151
🏁 Script executed:
set -u
printf '%s\n' '--- target files ---'
sed -n '1,230p' cuprum/events.py
printf '%s\n' '--- pipeline types ---'
sed -n '1,100p' cuprum/_pipeline_types.py
printf '%s\n' '--- timeout reporting ---'
sed -n '1,100p' cuprum/_timeout_reporting.py
printf '%s\n' '--- timeout identifiers and exports ---'
rg -n -P --type=py 'TimeoutMode|elapsed_deadline|non_positive_immediate|timeout_mode' cuprum || true
printf '%s\n' '--- package exports ---'
fd -t f -d 2 -e py . cuprum | sort | xargs -r rg -n 'events|ExecEvent|__all__' || trueRepository: leynos/cuprum
Length of output: 50369
🏁 Script executed:
python3 - <<'PY'
import ast
from pathlib import Path
root = Path("cuprum")
files = tuple(root.rglob("*.py"))
mode_values = {"elapsed_deadline", "non_positive_immediate"}
string_uses = []
aliases = []
exports = {}
for path in files:
tree = ast.parse(path.read_text(), filename=str(path))
for node in ast.walk(tree):
if isinstance(node, ast.AnnAssign) and isinstance(node.target, ast.Name):
text = ast.unparse(node.annotation)
if "timeout_mode" in node.target.id or node.target.id in {"_TimeoutMode", "TimeoutMode"}:
aliases.append((str(path), node.lineno, node.target.id, text))
if isinstance(node, ast.Assign):
for target in node.targets:
if isinstance(target, ast.Name) and target.id in {"_TimeoutMode", "TimeoutMode"}:
aliases.append((str(path), node.lineno, target.id, ast.unparse(node.value)))
if isinstance(node, ast.Call) and isinstance(node.func, ast.Name) and node.func.id == "ExecEvent":
for keyword in node.keywords:
if keyword.arg == "timeout_mode":
string_uses.append((str(path), node.lineno, ast.unparse(keyword.value)))
for node in tree.body:
if isinstance(node, ast.Assign):
for target in node.targets:
if isinstance(target, ast.Name) and target.id == "__all__":
try:
exports[str(path)] = ast.literal_eval(node.value)
except Exception:
exports[str(path)] = ast.unparse(node.value)
print("aliases:")
for item in aliases:
print(item)
print("timeout_mode annotations/call values:")
for item in string_uses:
print(item)
print("events exports:", exports.get("cuprum/events.py"))
print("mode literals used in ExecEvent calls:",
sorted({value for _, _, value in string_uses if value in {repr(v) for v in mode_values}}))
PY
printf '%s\n' '--- public package exports and relevant internal tails ---'
sed -n '45,110p' cuprum/__init__.py
sed -n '85,120p' cuprum/_pipeline_types.py
sed -n '250,285p' cuprum/_timeout_reporting.pyRepository: leynos/cuprum
Length of output: 4235
🏁 Script executed:
python3 - <<'PY'
import re
from pathlib import Path
mode_pattern = re.compile(r'"(elapsed_deadline|non_positive_immediate)"')
for name in ("cuprum/events.py", "cuprum/_pipeline_types.py", "cuprum/_timeout_reporting.py"):
text = Path(name).read_text()
print(name)
for line_no, line in enumerate(text.splitlines(), 1):
if "TimeoutMode" in line or "timeout_mode" in line or mode_pattern.search(line):
print(f"{line_no}: {line}")
print("\nmode literals outside tests:")
for path in sorted(Path("cuprum").rglob("*.py")):
if "unittests" in path.parts:
continue
for line_no, line in enumerate(path.read_text().splitlines(), 1):
values = mode_pattern.findall(line)
if values:
print(f"{path}:{line_no}: {values}")
print("\npublic alias/export indicators:")
events = Path("cuprum/events.py").read_text()
print("TimeoutMode declaration:", bool(re.search(r"(?m)^type TimeoutMode\s*=", events)))
print("__all__ contains TimeoutMode:",
bool(re.search(r'(?m)^\s*"TimeoutMode",?', events)))
print("_timeout_reporting imports from events:",
bool(re.search(r"from cuprum\.events import[^\n]*TimeoutMode", Path("cuprum/_timeout_reporting.py").read_text())))
PY
printf '%s\n' '--- project Python target and typing conventions ---'
rg -n -C2 'requires-python|python_version|type [A-Za-z_]+ =' pyproject.toml setup.cfg tox.ini Makefile 2>/dev/null || trueRepository: leynos/cuprum
Length of output: 2292
Export and reuse a public TimeoutMode alias.
Define TimeoutMode in cuprum.events for the two supported literals, add it to __all__, and use it for ExecEvent.timeout_mode and _EventDetails.timeout_mode. Replace _timeout_reporting._TimeoutMode with an alias to the public type.
🤖 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 `@cuprum/events.py` around lines 155 - 158, Define and export a public
TimeoutMode alias in cuprum.events covering the two supported literal values,
then annotate ExecEvent.timeout_mode and _EventDetails.timeout_mode with it.
Update _timeout_reporting._TimeoutMode to alias the public TimeoutMode instead
of defining a separate type, preserving existing behavior.
Source: Coding guidelines
| If cleanup then fails to drain a stream consumer, a second record is written at | ||
| `ERROR` — `subprocess_teardown_drain_failed pid=… errors=…` — carrying | ||
| `cuprum_operation` (`"teardown"`), `cuprum_teardown_outcome` | ||
| (`"drain_error"`), `cuprum_pid`, and `cuprum_error_type` set to the | ||
| comma-joined class names of the failures. The drain failure itself is absorbed | ||
| so it cannot displace the `TimeoutExpired` (or `CancelledError`) the caller is | ||
| waiting to catch; this record, and the `teardown_error` observe event, are how | ||
| it stays visible. | ||
|
|
||
| Logging is best-effort: a failure inside the logging stack is suppressed rather | ||
| than allowed to change what the caller sees. The same facts are emitted as | ||
| `timeout` and `teardown_error` observe events (see *Structured execution | ||
| events* below) from one shared set of values, so the two channels cannot | ||
| disagree. |
There was a problem hiding this comment.
🎯 Functional Correctness | 🟡 Minor | ⚡ Quick win
Keep the teardown diagnostic operation value consistent.
Replace "teardown" with "drain" for cuprum_operation. The guide states
that logging and observe events use shared values, while the teardown_error
event schema defines its operation as "drain". Add an assertion that binds
cuprum_operation specifically to "drain".
docs/users-guide.md#L397-L410: document
cuprum_operationas"drain".cuprum/unittests/test_async_timeout_docs.py#L232-L255: assert the
cuprum_operationand"drain"association, not only independent terms.
Triage: [type:docstyle]
📍 Affects 2 files
docs/users-guide.md#L397-L410(this comment)cuprum/unittests/test_async_timeout_docs.py#L232-L255
🤖 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 `@docs/users-guide.md` around lines 397 - 410, Update docs/users-guide.md lines
397-410 to document cuprum_operation as "drain" instead of "teardown", keeping
the teardown_error event description consistent. In
cuprum/unittests/test_async_timeout_docs.py lines 232-255, strengthen the
documentation assertion to verify that cuprum_operation is specifically
associated with "drain", rather than asserting the terms independently.
Source: Coding guidelines
|
@coderabbitai Have the following failed checks now been resolved? If further work is required, please provide an AI agent prompt for the remaining work to be done to address these failures. Do not treat warnings as optional or aspirational. Where a change is out of scope for this PR, propose a GitHub issue unless one exists already. (Treat o11y, code safety, documentation and validation coverage as in scope). ❌ Failed checks (3 warnings)
|
This comment was marked as resolved.
This comment was marked as resolved.
Cancelling a task propagates cancellation to whatever future it is awaiting, so the bare `await termination` in `_await_teardown_shielded`'s cancellation handler was itself cancellable. A second `cancel()` landing there tore down the termination task, and `asyncio.gather` passed that on to each `_terminate_process`, skipping the SIGKILL escalation and the reap. A SIGTERM-immune child then outlived the run that spawned it — a probe confirmed it was never reaped, even after the grace period elapsed. Every wait, including the retries, is now shielded, and the handler re-enters it until the termination task reports done. The loop is bounded by the grace period rather than by the caller's patience, because termination always settles: it escalates to SIGKILL and awaits the exit. Also reconcile the inter-stage pumps from a `finally` in `_collect_pipeline_inputs` so every exit path is covered, not just the deadline branch. The timeout branch keeps its explicit call, because the pumps must reach EOF after the stages are terminated but before the outputs are gathered; `_reconcile_pipe_tasks` is safe to run twice. Strengthen `test_drain_absorbs_failures_without_replacing_primary_error`, which never exercised a consumer failure at all: the drain cancels its consumers synchronously before awaiting them, so a `failing` task that had not yet run was torn down as a plain cancellation and never reached its `raise`. One slot is now always `failing` and is awaited to completion first. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
`asyncio.shield` alone does not protect cleanup. It keeps the cancellation off the inner coroutine, but the *awaiting* coroutine resumes immediately, so a run unwinds in parallel with its own cleanup and propagates `CancelledError` while the tasks it owns are still live — leaking exactly what the cleanup exists to reconcile. `sh._execute_with_hooks` relied on a bare `await asyncio.shield(...)` for precisely that reason. Generalise the retry rules already proven for teardown into `_shielded_cleanup`: own the cleanup in a task, await it shielded, and re-enter that shielded wait until the task reports done. Awaiting the task directly would not do, since cancelling a task propagates to whatever future it is blocked on. Route every cleanup path through it — the timeout, cancellation and stdin-failure paths of both subprocess runners, the spawn-failure, timeout and run-failure paths of `_run_pipeline`, `_finalize_pipeline_execution`, and `_execute_with_hooks`. Two helpers keep multi-step cleanup atomic under one shield, since shielding the halves separately lets a cancellation landing between them abandon the second: `_reconcile_run_tasks` and `_reconcile_pipeline_run_failure`. Guard each stage's terminal `exit` emission during a pipeline timeout. `emit` re-raises a synchronous hook failure and this runs inside the `except TimeoutExpired` handler, so one failing hook both replaced the `TimeoutExpired` the caller was owed and abandoned the remaining stages — stranding the open spans those exit events exist to close. Widen the sibling guard in `_report_pipeline_timeout_expiry` to `CancelledError` too, matching `_safe_emit`. Bound `TracingHook`'s registry of open spans. Only `exit` evicts, and not every execution emits one: cleanup also runs on external cancellation and on a stdin-writer failure, where the original exception propagates and a `teardown_error` may be an execution's last event. Ending the span on `teardown_error` is not the answer — on the timeout path an `exit` does follow — so the registry evicts its oldest entry instead, ending it as failed. Assert timeout-before-exit per stage rather than globally: `phases.index` reports only the first occurrence, so across two stages it compared one stage's timeout with the other's exit and accepted an interleaving where a stage reported its exit first. Also export a public `TimeoutMode` alias from `cuprum.events` and annotate `ExecEvent.timeout_mode` with it, share `ExecPhase` with `_StageObservation.emit` instead of redeclaring the nine values, move `_drain_tasks_during_cleanup` beside `_wait_for_exec_hook_tasks` in `_observability`, and split the `Span` / `Tracer` protocols out of the tracing adapter to keep it under the module-size ceiling. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Summary
Closes #284.
Stacked on top of #223 (base:
issue-221-…). Splitting out at maintainerrequest — the observability and documentation work grew beyond the ASYNC lint
enablement that #221 asked for, so it now ships as its own reviewable change.
Merge #223 first; this PR's base will retarget to
mainautomatically.Timeout and teardown failures were previously invisible: a
TimeoutExpiredtold a caller that a command timed out, but nothing recorded how (an
elapsed deadline versus an immediate non-positive expiry), and a stream-drain
failure during teardown was swallowed entirely. This adds structured
diagnostics on both existing channels — the
cuprum.timeoutlogger and theExecEventobserve stream — without introducing a parallel telemetryframework.
Changes
Event contract
ExecPhasegains two ancillary phases,timeoutandteardown_error.They are ancillary in the sense that they do not participate in the
plan → start → exitlifecycle: they may fire zero or one times and neverreplace a lifecycle phase.
ExecEventgainstimeout_s: float | Noneandtimeout_mode: str | None,populated on the
timeoutphase.timeout_modedistinguisheselapsed_deadlinefromnon_positive_immediate.pidis now documented as populated for every phase exceptplan, ratherthan enumerating a list that had gone stale twice.
Emission
_report_timeout_expiryand_report_teardown_drain_failureeach pair onelog record with one observe event from a single set of facts, so the two
channels cannot drift.
test_timeout_telemetry_pairingpins that invariantas a property test over generated pids, timeouts, and modes.
_emit_timeout_logsuppressesException, and_safe_emitsuppressesExceptionandCancelledError, so a brokenconsumer cannot change what a caller sees.
Exception precedence
_run_subprocess_with_streamsand_run_subprocess_without_streamsnowclean up on
except BaseException, after the timeout-specific clause, so anon-
TimeoutErrorescape no longer leaks the stdin writer or the streamconsumers.
run — a hook raising during cleanup could stand in for the
TimeoutExpiredor
CancelledErrora caller was waiting to catch._execute_with_hooksnowdrains through
_drain_tasks_during_cleanup, which aggregates the hookfailure with the active error into a
BaseExceptionGroup. Only async hookswere affected (synchronous ones are swallowed by
_safe_emit), which is whythe pre-existing test passed while the bug was live; both new tests are
mutation-verified to fail against the pre-fix code.
_drain_tasks_during_cleanup'smessagelabel is required rather thandefaulted, so a non-pipeline caller cannot silently inherit the pipeline's
finalization label.
Adapters
match/case.span, and carries
timeout_s/timeout_modeso a consumer can tell the twoexpiry modes apart.
Refactoring
_execute_subprocess's direct path is extracted to_run_subprocess_without_streams(CodeScene).Documentation
docs/users-guide.md: theteardown_errorcontract, the new metricscounters, the
cuprum.timeoutlog fields, and the tracing span-eventbehaviour.
docs/developers-guide.md: the emission helpers and the pairing invariant.API,
TimeoutExpiredand its payload, and timeout/exception precedence,naming the telemetry as additive.
test_async_timeout_docspins the documented contract against the code, sothe docs cannot drift silently.
Verification
make check-fmt,make lint,make typecheck,make test,markdownlintand
nixieall pass.coderabbit review --agentreports zero findings against this branch's ownbase (the
issue-221-…branch, notmain).split moved commits without altering the result.
test_async_timeout_docsfail against the pre-edit users' guide.Notes for the reviewer
The stack order is forced, not a preference. This PR cannot be moved
below Enable the ASYNC (flake8-async) ruff rule group (#221) #223 without re-implementing it. The timeout telemetry is emitted from
inside
_wait_for_exit_code_within_timeout, and that helper is created bythe ASYNC refactor (
c6e7427) — it does not exist onmain, where_wait_for_exit_codestill callsasyncio.wait_for(process.wait(), timeout)directly. Cherry-picking these commits onto
mainfails at Emit timeoutobserve events from the wait path with
_wait_for_exit_code_within_timeout: deleted in ours, modified in theirs.Inverting the stack would mean rewriting the observability against the
pre-refactor
wait_forcode and then re-deriving the refactor on top of it,so please review this as landing after Enable the ASYNC (flake8-async) ruff rule group (#221) #223 rather than alongside it.
One commit message on this branch (
Action review findings on cleanup, telemetry and lint scope) describes apyproject.tomlASYNC scopenarrowing that now lives in Enable the ASYNC (flake8-async) ruff rule group (#221) #223 instead; the change itself was not lost,
only relocated to the parent PR where it belongs.
cuprum/adapters/tracing_adapter.pysits at exactly 400 lines, pylint'senforced
max-module-lines. There is no headroom: the next line added tothat file breaks the build. Extracting its two
Protocolclasses (~88lines) into their own module would be the natural remedy, but that is out of
scope here.
References
#271#284🤖 Generated with Claude Code