Scenario 11: synchronize cancel assertion on the worker cancel record (#143) #164

Merged
kilo merged 2 commits from fix/143-scenario11-cancel-race into develop 2026-09-30 23:58:02 +00:00
Member

Fixes #143. Test-only synchronization fix; zero production changes.

Root cause (reproduced, instrumented)

Both scenario-11 cancellation tests asserted worker.cancels immediately after the drain loop observed client-socket EOF. The production ordering is correct — the HTTP handler thread runs the dispatch synchronously, so when chunk 2 trips _client_gone(), the adapter writes the cancel message to the worker socket before the handler unwinds and the client connection closes. What is not ordered is the worker-side ScriptedWorker reader thread receiving, parsing and appending that cancel to worker.cancels.

Instrumented reproduction on this branch's base (2026-09-30, 17f4918a, otherwise-pristine CancellationTests loop): 6 failures across ~60 executions (1/8, 2/12, and 3 in a diagnostic loop), every one with:

exit_reason=eof; landed_after_eof=0.0011s; cancels_now=['wa-…']

The drain exited via the EOF break and the cancel landed in worker.cancels ~1.1 ms later. Valid asynchronous behavior observed too early — a test synchronization defect, not a production semantics defect. (Matches the original full-suite-load evidence on compat/logical-model-resolution and the 2026-09-28 contract/reasoning-effort-serialization variant recorded in the issue comment.)

Fix

tests/test_e2e_execution.py, both scenario-11 tests: after the drain, the assertion synchronizes on the real observable contract — wait_until(lambda: bool(worker.cancels), timeout=<remaining pre-existing 15 s budget>, message="cancel never reached the worker") — instead of inferring delivery from socket EOF. The drain (realistic client read-until-close) is kept; EOF is no longer load-bearing for the assertion.

Explicitly not done: no sleeps, no timeout bumps, no blind retries, no weakened assertion (the cancel must still reach the owning worker — and in the second test, only the owning worker — within the same 15 s budget, or the test fails with the same message), no production changes.

Validation

Check Result
Scenario 11 class, 30 consecutive runs (60 test executions) with the full test_e2e_execution module running concurrently as load 30/30 OK, 0 failures
Full test_e2e_execution module (12 tests, under that same concurrent load) 12/12 OK (57 s)
Full gate make check 2492 tests OK (585 s — the exact full-suite load condition that originally flaked)
uv run basedpyright 0 errors, 0 warnings, 0 notes
git diff --check clean

Discrimination: the old assertion failed ~10% of executions on this machine under the same conditions; the synchronized version passed 60/60 under equal-or-worse load, and the whole suite passed end to end.

Scope audit

  • Diff touches only tests/test_e2e_execution.py (+22/−5), entirely inside the two scenario-11 tests.
  • No protocol/API changes; no production code touched; cancellation semantics unchanged and still exercised end to end.
  • No arbitrary timing constants as the correctness mechanism (the 15 s budget pre-existed; wait_until's 20 ms poll is granularity, not the mechanism).
  • Normal successful requests unaffected (no other path touched).

Residual risk

Low. The wait is bounded and ordered after a production write that provably precedes the client close, so a genuine regression (cancel never sent) still fails the test — within the same 15 s budget, with the same message. An independent concurrency review should confirm the one remaining assumption: that _send_cancel_best_effort writes the cancel frame before the handler thread closes the client socket on every disconnect path (chunk-emission EOF, write-error/RST, and the coordinator's cancel_event route), not only the path exercised here.

UX impact: none (test-only).


  • Base: origin/develop @ 17f4918a49139c6f539dc073695308cc7516f50f
  • HEAD: 1176af3 (single commit, single file)
Fixes #143. Test-only synchronization fix; zero production changes. ## Root cause (reproduced, instrumented) Both scenario-11 cancellation tests asserted `worker.cancels` immediately after the drain loop observed **client-socket EOF**. The production ordering is correct — the HTTP handler thread runs the dispatch synchronously, so when chunk 2 trips `_client_gone()`, the adapter writes the cancel message to the worker socket **before** the handler unwinds and the client connection closes. What is *not* ordered is the worker-side `ScriptedWorker` reader thread receiving, parsing and appending that cancel to `worker.cancels`. Instrumented reproduction on this branch's base (2026-09-30, `17f4918a`, otherwise-pristine `CancellationTests` loop): **6 failures across ~60 executions** (1/8, 2/12, and 3 in a diagnostic loop), every one with: ``` exit_reason=eof; landed_after_eof=0.0011s; cancels_now=['wa-…'] ``` The drain exited via the EOF `break` and the cancel landed in `worker.cancels` ~1.1 **ms** later. Valid asynchronous behavior observed too early — a test synchronization defect, not a production semantics defect. (Matches the original full-suite-load evidence on `compat/logical-model-resolution` and the 2026-09-28 `contract/reasoning-effort-serialization` variant recorded in the issue comment.) ## Fix `tests/test_e2e_execution.py`, both scenario-11 tests: after the drain, the assertion synchronizes on the real observable contract — `wait_until(lambda: bool(worker.cancels), timeout=<remaining pre-existing 15 s budget>, message="cancel never reached the worker")` — instead of inferring delivery from socket EOF. The drain (realistic client read-until-close) is kept; EOF is no longer load-bearing for the assertion. Explicitly not done: no sleeps, no timeout bumps, no blind retries, no weakened assertion (the cancel must still reach the owning worker — and in the second test, only the owning worker — within the same 15 s budget, or the test fails with the same message), no production changes. ## Validation | Check | Result | |---|---| | Scenario 11 class, 30 consecutive runs (60 test executions) **with the full `test_e2e_execution` module running concurrently as load** | **30/30 OK, 0 failures** | | Full `test_e2e_execution` module (12 tests, under that same concurrent load) | 12/12 OK (57 s) | | Full gate `make check` | **2492 tests OK** (585 s — the exact full-suite load condition that originally flaked) | | `uv run basedpyright` | 0 errors, 0 warnings, 0 notes | | `git diff --check` | clean | Discrimination: the old assertion failed ~10% of executions on this machine under the same conditions; the synchronized version passed 60/60 under equal-or-worse load, and the whole suite passed end to end. ## Scope audit - Diff touches only `tests/test_e2e_execution.py` (+22/−5), entirely inside the two scenario-11 tests. - No protocol/API changes; no production code touched; cancellation semantics unchanged and still exercised end to end. - No arbitrary timing constants as the correctness mechanism (the 15 s budget pre-existed; `wait_until`'s 20 ms poll is granularity, not the mechanism). - Normal successful requests unaffected (no other path touched). ## Residual risk Low. The wait is bounded and ordered after a production write that provably precedes the client close, so a genuine regression (cancel never sent) still fails the test — within the same 15 s budget, with the same message. An independent concurrency review should confirm the one remaining assumption: that `_send_cancel_best_effort` writes the cancel frame before the handler thread closes the client socket on **every** disconnect path (chunk-emission EOF, write-error/RST, and the coordinator's `cancel_event` route), not only the path exercised here. UX impact: none (test-only). --- - Base: `origin/develop` @ `17f4918a49139c6f539dc073695308cc7516f50f` - HEAD: `1176af3` (single commit, single file)
Scenario 11: synchronize cancel assertion on the worker cancel record (#143)
All checks were successful
ci / check (pull_request) Successful in 9m26s
1176af342f
The client-disconnect cancellation tests asserted worker.cancels
immediately after the drain loop observed client-socket EOF. EOF only
proves the cancel was SENT (the handler thread writes it to the worker
socket before closing the client connection); the worker-side reader
thread records it asynchronously. Instrumented reproduction: the drain
exited via EOF with the cancel landing ~1.1 ms later — valid
asynchronous behavior observed too early, not a production defect.

The assertion now synchronizes on the real observable contract —
wait_until on worker.cancels for the remaining pre-existing 15 s
budget. No sleeps, no blind retries, no weakened assertion: the cancel
must still reach the owning worker, and only the owning worker, or the
test fails with the same message.
Review blockers: condition-first wait_until + exact-attempt cancel wait (#143)
All checks were successful
ci / check (pull_request) Successful in 9m25s
6c1517c7aa
Blocker 1: wait_until checked the clock before the predicate, so a zero
or exhausted remaining budget raised without ever evaluating an
already-satisfied condition — an already-recorded cancellation could
fail at deadline exhaustion. The helper is now condition-first: the
predicate always gets at least one evaluation, timeout failure is
decided only after a final check, and the deadline stays hard (no
extension, no sleep on the failure path). Deterministic boundary
coverage added in tests/test_wait_until.py (zero budget, near-zero
budget, exhausted-budget failure, becomes-true path).

Changed the shared helper rather than working around it locally: the
clock-first flaw belongs to the helper's contract, any caller passing a
computed remaining budget can hit it, and condition-first semantics are
strictly stronger for every caller (no false-pass risk: predicate and
deadline are unchanged). The full gate covers the four e2e suites that
import it.

Blocker 2: both scenario-11 tests now wait for THIS attempt's
cancellation (execute.attempt_id in worker.cancels), never for 'some
cancellation arrived'; an unrelated cancel cannot satisfy the wait.
Proven by a wrong-attempt diagnostic run: a bogus-ID predicate failed
the test even though the real cancellation arrived (diagnostic not
committed).

Note: one earlier gate run hit a PRE-EXISTING, load-sensitive flake in
tests/test_openai_codex_acquisition.py (the _feed feeder thread can
crash inside the harness's empty-stderr capture; see PR discussion).
Unrelated to this diff; not fixed here.
Author
Member

Both blocking findings remediated on HEAD 6c1517c7aae0a5aa4187279d3be87e7d7066f2a4 (reviewed head was 1176af3). PR left open; no merge performed.

Blocker 1 — condition-first bounded wait

wait_until (shared helper, tests/m10_fixtures.py) checked the clock before the predicate, so a zero or exhausted remaining budget raised AssertionError without ever evaluating an already-satisfied condition. The helper is now condition-first:

deadline = time.monotonic() + timeout
while True:
    if condition():
        return
    if time.monotonic() >= deadline:
        raise AssertionError(message)
    time.sleep(interval)

The predicate is evaluated before any timeout decision; an already-satisfied predicate succeeds even at zero remaining budget; a false predicate fails immediately at the original deadline (no extension, no sleep on the failure path). The 15 s scenario-11 budget is unchanged.

Why the shared helper rather than a local change: the clock-first flaw belongs to the helper's contract — any caller passing a computed remaining budget (exactly the pattern both scenario-11 tests use) can hit it; a local workaround would hand-roll a second bounded-wait implementation in two tests; and condition-first semantics are strictly stronger for every caller with no false-pass risk (predicate and hard deadline unchanged). Per the review instruction, the full gate was run for the other callers: all four e2e suites import this helper (test_e2e_execution, test_e2e_codex_acceptance, test_e2e_zcode_acceptance, test_e2e_sources_acceptance) and all are covered by the full make check (2496 tests OK). The three other module-local wait_until copies (test_worker_client.py, test_worker_endpoint.py, test_worker_bridged_adapter.py) are separate helpers, untouched.

Deterministic boundary coverage added in tests/test_wait_until.py (4 tests, 3 ms total): already-true predicate with zero budget (asserts exactly one evaluation — the old code raised without looking), already-true with near-zero budget, false predicate at exhausted budget failing immediately (asserts no budget-sized wait and message preserved), and the not-true-at-entry path becoming true (predicate-driven, clock-independent).

Blocker 2 — expected-attempt discrimination

Both scenario-11 tests now wait on lambda: execute.attempt_id in worker.cancels (drain-loop guard likewise), using the real attempt ID from that test's next_execute. An unrelated cancellation can never satisfy the wait — the test fails at the deadline with cancel never received if only unrelated cancels land. Proven by a wrong-attempt diagnostic run (not committed): with the predicate pointed at a bogus ID, the test FAILED with cancel never reached the worker even though the real cancellation for the actual attempt arrived in that window.

Validation

  • Both modified scenario-11 tests: pass (sanity + repeated).
  • Boundary tests: 4/4, deterministic.
  • Wrong-attempt diagnostic: fails as required (see above).
  • test_e2e_execution module: 12/12 under concurrent load.
  • Stress: 25/25 consecutive CancellationTests runs (50 executions), 0 failures, with the full module running concurrently as load — no reintroduced load sensitivity.
  • Full make check (exact gate commands): 2496 tests OK + basedpyright 0 errors/0 warnings/0 notes + git diff --check clean.

Pre-existing flake encountered (not fixed here — out of scope)

One intermediate make check run failed on tests/test_openai_codex_acquisition.py: the harness asserts captured stderr is empty (line 416), but the fixture's _feed feeder thread can crash inside the capture window — _close_write() joins the feeder with timeout=5.0; if the pipe is full the feeder is in its retry sleep, the join times out, the write fd is closed, and the feeder's next os.write raises EBADF, which threading prints as Exception in thread Thread-924 (_feed) into the redirected stderr. Evidence it is pre-existing and unrelated to this diff: the module imports nothing changed here; in-isolation loops pass 20/20 on BOTH pristine develop and this branch; and a full-suite run on pristine develop @ 17f4918a failed (1 failure) under concurrent load while this branch's suite passed 2496/2496 in the same conditions. Same load-sensitive family as #143, different module and mechanism. Left untouched per scope (no unrelated cleanup) — it merits its own issue.

Scope confirmation: the review's DEFER items (coordinator cancel_event timing, header-write BrokenPipeError, initial tool-suspension emissions, worker-connection-loss semantics) were NOT implemented. Diff: tests/m10_fixtures.py (+12/−3), tests/test_e2e_execution.py (+9/−4), tests/test_wait_until.py (new, +57). UX impact: none (test-only).

Both blocking findings remediated on HEAD `6c1517c7aae0a5aa4187279d3be87e7d7066f2a4` (reviewed head was `1176af3`). PR left open; no merge performed. ## Blocker 1 — condition-first bounded wait `wait_until` (shared helper, `tests/m10_fixtures.py`) checked the clock before the predicate, so a zero or exhausted remaining budget raised `AssertionError` without ever evaluating an already-satisfied condition. The helper is now condition-first: ```python deadline = time.monotonic() + timeout while True: if condition(): return if time.monotonic() >= deadline: raise AssertionError(message) time.sleep(interval) ``` The predicate is evaluated before any timeout decision; an already-satisfied predicate succeeds even at zero remaining budget; a false predicate fails immediately at the original deadline (no extension, no sleep on the failure path). The 15 s scenario-11 budget is unchanged. **Why the shared helper rather than a local change:** the clock-first flaw belongs to the helper's contract — any caller passing a computed remaining budget (exactly the pattern both scenario-11 tests use) can hit it; a local workaround would hand-roll a second bounded-wait implementation in two tests; and condition-first semantics are strictly stronger for every caller with no false-pass risk (predicate and hard deadline unchanged). Per the review instruction, the full gate was run for the other callers: all four e2e suites import this helper (`test_e2e_execution`, `test_e2e_codex_acceptance`, `test_e2e_zcode_acceptance`, `test_e2e_sources_acceptance`) and all are covered by the full `make check` (2496 tests OK). The three other module-local `wait_until` copies (`test_worker_client.py`, `test_worker_endpoint.py`, `test_worker_bridged_adapter.py`) are separate helpers, untouched. Deterministic boundary coverage added in **`tests/test_wait_until.py`** (4 tests, 3 ms total): already-true predicate with zero budget (asserts exactly one evaluation — the old code raised without looking), already-true with near-zero budget, false predicate at exhausted budget failing immediately (asserts no budget-sized wait and message preserved), and the not-true-at-entry path becoming true (predicate-driven, clock-independent). ## Blocker 2 — expected-attempt discrimination Both scenario-11 tests now wait on `lambda: execute.attempt_id in worker.cancels` (drain-loop guard likewise), using the real attempt ID from that test's `next_execute`. An unrelated cancellation can never satisfy the wait — the test fails at the deadline with `cancel never received` if only unrelated cancels land. Proven by a **wrong-attempt diagnostic run** (not committed): with the predicate pointed at a bogus ID, the test FAILED with `cancel never reached the worker` even though the real cancellation for the actual attempt arrived in that window. ## Validation - Both modified scenario-11 tests: pass (sanity + repeated). - Boundary tests: 4/4, deterministic. - Wrong-attempt diagnostic: fails as required (see above). - `test_e2e_execution` module: 12/12 under concurrent load. - Stress: **25/25 consecutive CancellationTests runs (50 executions), 0 failures**, with the full module running concurrently as load — no reintroduced load sensitivity. - Full `make check` (exact gate commands): **2496 tests OK** + basedpyright 0 errors/0 warnings/0 notes + `git diff --check` clean. ## Pre-existing flake encountered (not fixed here — out of scope) One intermediate `make check` run failed on `tests/test_openai_codex_acquisition.py`: the harness asserts captured stderr is empty (line 416), but the fixture's `_feed` feeder thread can crash inside the capture window — `_close_write()` joins the feeder with `timeout=5.0`; if the pipe is full the feeder is in its retry sleep, the join times out, the write fd is closed, and the feeder's next `os.write` raises EBADF, which `threading` prints as `Exception in thread Thread-924 (_feed)` into the redirected stderr. Evidence it is pre-existing and unrelated to this diff: the module imports nothing changed here; in-isolation loops pass 20/20 on BOTH pristine `develop` and this branch; and a full-suite run on **pristine `develop` @ `17f4918a` failed (1 failure) under concurrent load while this branch's suite passed 2496/2496 in the same conditions**. Same load-sensitive family as #143, different module and mechanism. Left untouched per scope (no unrelated cleanup) — it merits its own issue. Scope confirmation: the review's DEFER items (coordinator `cancel_event` timing, header-write `BrokenPipeError`, initial tool-suspension emissions, worker-connection-loss semantics) were NOT implemented. Diff: `tests/m10_fixtures.py` (+12/−3), `tests/test_e2e_execution.py` (+9/−4), `tests/test_wait_until.py` (new, +57). UX impact: none (test-only).
kilo merged commit db4e1bde28 into develop 2026-09-30 23:58:02 +00:00
Sign in to join this conversation.
No description provided.