Skip to content

Commit da552a5

Browse files
committed
Add snapshot evidence to cancel-cascade MTF issue doc
Append "Snapshot evidence (2026-05-13)" section to `cancel_cascade_too_slow_under_main_thread_forkserver_issue.md` documenting `fail_after_w_trace` diag capture results for `test_nested_multierrors` under the MTF backend — reproduction cmd, ptree analysis, observed hang signature, and updated triage plan. (this commit msg was generated in some part by [`claude-code`][claude-code-gh]) [claude-code-gh]: https://github.com/anthropics/claude-code (cherry picked from commit 5372fd1)
1 parent c286fb9 commit da552a5

1 file changed

Lines changed: 112 additions & 0 deletions

File tree

ai/conc-anal/cancel_cascade_too_slow_under_main_thread_forkserver_issue.md

Lines changed: 112 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -182,6 +182,118 @@ Target: 0 failures across 5 runs ⇒ ship. 1–2 failures
182182
still rotating ⇒ apply (C). Same test failing twice
183183
⇒ escalate to (E).
184184

185+
## Snapshot evidence (2026-05-13)
186+
187+
After landing the `fail_after_w_trace` /
188+
`afk_alarm_w_trace` capture-on-timeout helpers
189+
(`tractor._testing.trace`), `test_nested_multierrors`
190+
on the `main_thread_forkserver` backend produces
191+
**reproducible diag snapshots** at
192+
`$XDG_CACHE_HOME/tractor/hung-dumps/test_nested_multierrors_start_method_main_thread_forkserver__<iso-ts>/`.
193+
194+
### Reproduction
195+
196+
```bash
197+
pytest \
198+
-v --verbose --durations=10 \
199+
--spawn-backend=main_thread_forkserver \
200+
--tpt-proto=uds \
201+
--capture=sys --show-capture=stderr -rxX \
202+
tests/test_cancellation.py::test_nested_multierrors
203+
```
204+
205+
The test is `xfail(strict=False)` for MTF — it RUNS
206+
each invocation so snapshots accumulate, but doesn't
207+
break `--lf` workflow.
208+
209+
### Consistent shape across runs
210+
211+
5+ snapshots taken back-to-back show the SAME pattern:
212+
213+
- **Timing:** ~10s wall-clock total. Inner
214+
`fail_after_w_trace(10)` fires at exactly T=10s;
215+
cascade's `nursery.__aexit__` takes ~0.6s more to
216+
gather + propagate the resulting
217+
`BaseExceptionGroup`. **Trio backend completes the
218+
SAME test in <6s** — so the MTF cascade is ~2x
219+
slower at minimum.
220+
221+
- **`BaseExceptionGroup` shape:** mixed
222+
`[RemoteActorError, Cancelled]`. The first
223+
subactor's natural error-propagation (`assert 0`
224+
raised → `RemoteActorError` portal-result)
225+
arrives before T=10s; the OTHER subactor's
226+
portal-wait is still in flight at T=10s, gets
227+
cancelled by `fail_after_w_trace`'s scope-cancel
228+
→ returns `Cancelled` instead.
229+
230+
- **Orphan-spawn skew:** snapshot's `orphans` bucket
231+
(after the `_is_tractor_subactor` cgroup-slice
232+
override fix) consistently shows 2-4 init-adopted
233+
procs at `depth_3` and `depth_1` levels — these
234+
are the leaves whose parent (`depth_2` spawner)
235+
was killed mid-cascade but who hadn't yet seen
236+
the cancel signal themselves.
237+
238+
- **UDS sock-leak:** 2-6 dead-orphan socks per run
239+
(varies with cascade timing). The
240+
`track_orphaned_uds_per_test` fixture reaps them
241+
post-test → contamination is isolated per-invocation.
242+
243+
### Capture mechanism
244+
245+
`fail_after_w_trace` covers two firing paths:
246+
247+
1. **`trio.TooSlowError`** raised at scope-exit
248+
(body returned cleanly past deadline) — direct
249+
`except` handler captures.
250+
251+
2. **Scope-cancel + body raises non-`Cancelled` exc**
252+
(e.g. `nursery.__aexit__` wraps timeout-induced
253+
`Cancelled` into a `BaseExceptionGroup` that
254+
escapes before `trio.fail_after`'s exit-check
255+
could fire `TooSlowError`) — body-raise `except`
256+
handler checks `scope.cancel_called` and
257+
captures if True. This path catches the
258+
`test_nested_multierrors` shape specifically (see
259+
"BaseExceptionGroup shape" above).
260+
261+
The snapshot dir contains:
262+
- `trace.txt``ptree` + `hung_state` (kernel
263+
`wchan`/`stack` + `py-spy dump --locals` when
264+
sudo cached), with `include_strays=True`
265+
surfacing any cross-test ghost subactor trees in
266+
the `orphans` bucket.
267+
- `bindspace.txt` — UDS bindspace classification
268+
(live-active / orphaned-alive / orphaned-dead).
269+
- `meta.json``{pid, label, captured_at, sudo_cached}`.
270+
271+
The end-of-session `pytest_terminal_summary` hook
272+
in `tractor._testing.pytest` lists every snapshot
273+
dir from the run so you don't have to scroll back
274+
through captured-stderr lines:
275+
276+
```
277+
========================= tractor hang-snapshot index ==========================
278+
N `fail_after_w_trace` / `afk_alarm_w_trace` snapshot(s) captured this session:
279+
<test-id>
280+
→ /home/.../.cache/tractor/hung-dumps/<label>__<ts>
281+
```
282+
283+
### Caveats
284+
285+
The snapshot fires AFTER the body-raise (not at the
286+
exact moment of scope-cancel), so the parent's
287+
py-spy frames show `_do_capture_snapshot` itself
288+
running, NOT the cancel-cascade hang frame. To see
289+
the actual hang state, manual `acli.ptree` /
290+
`acli.hung_dump` from a second terminal at T=10s
291+
would be needed — **not currently possible**
292+
because per-test reaper fixtures clean up ~0.6s
293+
post-timeout. See follow-up TODO in
294+
`tractor/_testing/trace.py` for a
295+
`TRACTOR_TRACE_HOLD=1` env-var pause mode.
296+
185297
## See also
186298

187299
- [#452](https://github.com/goodboy/tractor/issues/452)

0 commit comments

Comments
 (0)