diff --git a/docs/BACKLOG.md b/docs/BACKLOG.md index a3d1e438..f8ef7697 100644 --- a/docs/BACKLOG.md +++ b/docs/BACKLOG.md @@ -8573,3 +8573,26 @@ The `startswith(MARKER_PREFIX)` half stays in every case. **ADR 0158 — the taxonomy, and where this item sits in it.** Cited by **rule**, not just by number, because the rule is what transfers: *"An equality check satisfiable by coincidence is not an equality check."* That is this defect exactly. By the ADR's own one-line test for **Class 2** — *a control that cannot observe or act on its own failure*: **if this control were broken, what would tell me?** If the encryption were replaced tomorrow with a weak encoding, `"DOE" not in raw` would still go green. The answer is the control, which is the defect. *(Deliberately unlinked: the ADR is on PR #145's branch and not yet on `main`, so a relative link would render broken. Guessing its filename from its title is the same failure mode this item is about — it was guessed, checked, and was wrong.)* **Follow-up, deliberately not done here:** file this against ADR 0158 **once 0158 is on `main`**. Padding a document at merge time with instances its author did not choose is its own defect, and the ADR's instances are attributed by convention. **Source:** PR #142 (BACKLOG #323 layer 3, SMTP TLS), 2026-08-02 — observed on that PR's CI and deliberately **not** fixed there, because it is unrelated to the SMTP change and widening the PR would have obscured it. **Provenance is itemised, not aggregated** — "produced by N sessions" is a confidence claim, and an unsourced one of exactly that shape is what this item is about. **Rates:** derived here exactly, reproduced independently by the #142 session at N=144, recomputed analytically by #344's owner; the 200k-trial simulation came with the originating report. **Sibling audit:** derived twice from different scopes and reconciled. **Instrument-first framing, the ≥6 rule, the leave-the-rest-alone scoping:** from the #142 session's review. **The "infinitely fast machine" discriminator:** from #344's owner. **The demand to falsify the banner gate before trusting its green:** from the #346 session. No claim here rests on a count of who agreed. **Verification of this filing's own instruments:** every probability recomputed by two methods that agree (`Fraction` and `-expm1(N*log1p(-x))`), the audit counts re-derived from the working tree rather than quoted, and `backlog_status_check.py` **falsified against this item** — a deliberately doubled banner made it fail at `BACKLOG.md:8429` naming #347, so its green is evidence that it can see this item rather than evidence it skipped it. +## 348. SQL Server: a cancelled store call returns a pooled connection mid-transaction holding X locks + +> ✅ **Status CLOSED (filed + fixed 2026-08-02, [ADR 0159](adr/0159-cancellation-safe-pooled-connection-release-mid-txn-discard-at-the-acquire-chokepoint.md)).** `SqlServerStore`'s write idiom is `except Exception: await conn.rollback(); raise` — used at **90 of the 91** `self._acquire()` sites. `asyncio.CancelledError` derives from `BaseException`, so on a cancellation **no rollback runs**, and aioodbc's `Pool.release()` appends the connection straight back onto the free deque with no rollback, reset or transaction check (0.5.0 `pool.py:196-205`; `_ContextManager.__aexit__` uses the *same* `release` on the exception path). The next borrower inherited an open transaction still holding X locks on `queue` rows. Fixed by quarantining the connection at the `_acquire` chokepoint. + +**Cluster:** Store & Reliability. **Priority:** P2. **Verdict:** built. **Severity:** medium (pool integrity + a silent stall), low (likelihood: needs a cancellation to land inside a pooled write). + +**Reproduced on a live SQL Server 2022 before the fix**, cancelling each call mid-body and inspecting the server: `release_claimed` **7** X locks on `queue`, `reschedule_claimed` **7**, `mark_done` **9**, `enqueue_ingress` **11** — and `claim_fifo_heads` **0** (the control). The connection was back on the free list (`size=1 freesize=1`), a raw writer got **error 1222**, and a real second `claim_fifo_heads` returned **EMPTY-all**. After the fix: **0** locks, no open-transaction session, writer unblocked, connection dropped from the pool rather than re-lent. + +**Why it was invisible.** Under [ADR 0066](adr/0066-pooled-stage-claimers.md) §9 the claim runs `SET LOCK_TIMEOUT 0`, so a blocked claimer raises 1222 and the claim path translates that to a **sanctioned** EMPTY-all yield. The symptom is therefore silence — a lane that quietly claims nothing — not an error anyone would see. `enqueue_ingress` is the pre-ACK ingress commit, the engine's hottest path. + +**The path that bites is demotion, not shutdown.** `engine.stop()` closes the store shortly after cancelling, so the poisoned connection dies at teardown. Loss of leadership ([`engine.py:1242-1252`](../messagefoundry/pipeline/engine.py), `_stop_graph`) runs the identical cancel chain but **does not close the store** — the pool stays live and shared with the coordinator/convergence loops, so the connection sits in `_free` and is re-borrowed by unrelated callers. + +**Two corrections to the lead that opened this.** (1) It is **not** a two-method asymmetry: an AST census found 90 of 91 `_acquire` bodies share the idiom, and `mark_done`/`enqueue_ingress` were measured leaking identically — a two-method patch would have fixed an arbitrary slice. (2) `claim_fifo_heads` does **not** shield against this; its guard is a `SET LOCK_TIMEOUT` *reset* guard, [ADR 0114](adr/0114-phase-4-claim-path-call-complexity-reduction-driver-interface-redesign-ingress-routed-reset-fold.md) §2 states there is **no rollback** on its cancellation path, and `test_adr0114_claim_fold.py::test_ac3_cancellation_at_body_await_no_rollback_guard_runs` freezes that. It ends clean because the guard **commits**. + +**Not a data-integrity bug.** At-least-once was never at risk — a cancelled `release_claimed` leaves rows `INFLIGHT` and `reset_stale_inflight` re-pends them, which [`stage_dispatcher.py:491-492`](../messagefoundry/pipeline/stage_dispatcher.py) already declares the intended outcome. What was broken is pool integrity. + +**Backend scope: SQL Server only.** Postgres is safe twice over (asyncpg's `Transaction.__aexit__` rolls back on any `BaseException`; its pool also resets under `asyncio.shield`). SQLite shares the code shape but has one writer connection under an `asyncio.Lock` and no pool, so there is no next borrower. + +**Related:** ADR 0159, [ADR 0066](adr/0066-pooled-stage-claimers.md) §9, ADR 0114 §2, §1 of this file (the original H-6/H-7/H-8/M-6 concurrency-safety work — M-6 was scoped to `_fetchall`/bootstrap rollback hygiene and never covered the cancellation path). + +**Meets #344 instance 2 at the 1222.** That item (found independently and concurrently) traces the far end of this same chain: a contended head raises 1222, the store swallows it as a normal EMPTY, and the dispatcher goes to phase IDLE with no timer armed — **a test-rig gap, not an engine defect**, since production's periodic sweep re-readies such a lane and the ADR 0070 tests disable that sweep deliberately. Nothing here contradicts that and this item's severity is **not** escalated on it. What this adds is a **duration profile**: #344 assumes momentary producer contention, whereas a connection poisoned by *this* defect holds its `queue` X locks for as long as it sits unclaimed in the pool's free deque, so the 1222 can repeat across successive sweep ticks instead of clearing on the next. Cited by ledger number, not SHA — that branch is unpushed and may be rebased. + +**Source:** secondary lead from a PR #138 CI diagnosis, 2026-08-02; confirmed by live reproduction rather than by the reasoning in the lead, two of whose premises proved false. diff --git a/docs/adr/0159-cancellation-safe-pooled-connection-release-mid-txn-discard-at-the-acquire-chokepoint.md b/docs/adr/0159-cancellation-safe-pooled-connection-release-mid-txn-discard-at-the-acquire-chokepoint.md new file mode 100644 index 00000000..f2857cad --- /dev/null +++ b/docs/adr/0159-cancellation-safe-pooled-connection-release-mid-txn-discard-at-the-acquire-chokepoint.md @@ -0,0 +1,212 @@ + + + +# ADR 0159 — Cancellation-safe pooled-connection release: quarantine at the `_acquire` chokepoint + +- **Status:** Accepted (2026-08-02) +- **Date:** 2026-08-02 +- **Related:** [BACKLOG #348](../BACKLOG.md) · [ADR 0066](0066-pooled-stage-claimers.md) §9 (the `SET LOCK_TIMEOUT 0` never-block claim, whose 1222→EMPTY translation is what made this silent) · [ADR 0114](0114-phase-4-claim-path-call-complexity-reduction-driver-interface-redesign-ingress-routed-reset-fold.md) §2 (the shielded finally-guard — **explicitly not** a rollback guard; see §3 below) · [ADR 0001](0001-staged-pipeline-architecture.md) (the staged queue whose at-least-once contract bounds the damage) + +--- + +## Context + +`SqlServerStore`'s house idiom for a write is: + +```python +async with self._acquire() as conn, self._cursor(conn) as cur: + try: + await cur.execute(...) + await self._commit(conn) + except Exception: + await conn.rollback() + raise +``` + +An AST census over `messagefoundry/store/sqlserver.py` finds **91** `self._acquire()` call sites, and in +**90** of them the `async with` body is a single top-level `try` whose only handler is `Exception`. This is +the dominant idiom of the file, not a slip at one or two sites. + +`asyncio.CancelledError` derives from `BaseException`, not `Exception` (Python 3.8+). So on a cancellation +**none of those rollbacks run**. The body unwinds with its transaction still open and its row locks still +held, and nothing downstream compensates: + +- `_cursor` (`sqlserver.py:2957`) closes only the cursor. Its docstring records that it *deliberately* + bypasses aioodbc's own cursor context manager **because** that manager would commit/rollback and would + "override each caller's own explicit `commit`/`rollback`". +- `_acquire` (`sqlserver.py:2891`) had no `try` at all — it applied the STORE-3 statement timeout and + yielded. +- aioodbc's pool does not reset. `Pool.release()` (0.5.0 `pool.py:196-205`) is `self._used.remove(conn)` + then, `if not conn.closed`, `self._free.append(conn)` — no commit, no rollback, no transaction-status + check. `_ContextManager.__aexit__` (`utils.py:90-103`) calls `_release_on_exception`, which + `Pool.acquire()` never supplies, so it defaults to the same `release` (`utils.py:60-62`): **the + cancellation path and the success path release identically.** `create_pool` is called with no + `pool_recycle` and no `after_created`, so the recycle branch is dead. + +The pool is `autocommit=False` (`sqlserver.py:2244-2249`), so the transaction is real. The next borrower +inherits it: its own commit durably commits the stranger's statements, its rollback discards them. + +### What was measured + +Against a live SQL Server 2022 container, cancelling a call mid-body and then inspecting the server: + +| Method | X/U row locks left on `queue` | +| --- | --- | +| `release_claimed` | **7** | +| `reschedule_claimed` | **7** | +| `mark_done` | **9** | +| `enqueue_ingress` | **11** | +| `claim_fifo_heads` (control) | **0** | + +The connection was back on the pool's free list (`size=1 freesize=1`), a raw writer against the locked row +got **error 1222**, and a real second `claim_fifo_heads` returned **EMPTY-all**. Under ADR 0066 §9 that 1222 +is translated to EMPTY-all by design — a *sanctioned* outcome — which is exactly why this never surfaced as +an error: **the failure mode is silence, not a stack trace.** + +**`@@TRANCOUNT` is not a usable discriminator here** and was nearly mistaken for one. Under ODBC +manual-commit a connection sits at `@@TRANCOUNT=1` with **zero** locks as its normal resting state (a fresh +empty transaction opens after each commit). The clean control reports `@@TRANCOUNT=1` too. Only **held X/U +row locks** distinguish poisoned from clean; a guard keyed on `@@TRANCOUNT` would report a leak on every +healthy connection and prove nothing. + +### Reachability + +`StageDispatcher.stop()` cancels the lane tasks (`stage_dispatcher.py:509-511`); `_run_lane` is the body +that awaits `reschedule_claimed` (:739) and `release_claimed` (:751), and both call sites are themselves +guarded `except Exception`, so the `CancelledError` propagates. A third site is +`wiring_runner.py:4266`. + +Two driving paths, and they differ in consequence: + +- **Full shutdown** — `engine.stop()` closes the store shortly after, so the poisoned connection is closed + at teardown. Bounded. +- **Loss of leadership** (`engine.py:1242-1252`, `_stop_graph`) — runs the identical cancel chain but + **does not close the store**. The pool stays live and shared with the coordinator and convergence loops, + so the poisoned connection sits in `_free` and is re-borrowed by unrelated callers. **This is the path + that bites.** + +## Decision + +Contain the poison at the **`_acquire` chokepoint**, where all 91 sites funnel, rather than at individual +methods. + +```python +try: + yield conn +except BaseException as exc: + if not isinstance(exc, Exception): + await self._release_dirty(conn) + raise +``` + +`_release_dirty` does two things, **in an order that is itself the guarantee**: + +1. **Synchronously** drop the driver handle — `conn._conn = None` — with **no await in front of it**. + aioodbc derives `Connection.closed` from `_conn` (`connection.py:89-93`) and `Pool.release()` re-adds a + connection only `if not conn.closed`, so this one attribute write makes it unlendable. Because it cannot + suspend, no cancellation can skip it. +2. **Then**, best-effort and time-boxed, close the raw handle off the event loop + (`asyncio.to_thread(raw.close)` under `wait_for(shield(...), _DIRTY_CLOSE_TIMEOUT)`). pyodbc's `close()` + rolls back uncommitted work per DBAPI, which is what actually frees the locks. + +`isinstance(exc, Exception)` is the discriminator: an ordinary error has **already** been rolled back by the +caller's own handler, so that path is left byte-identical and the connection is recycled as before. Only the +cancellation path — the one no handler saw — quarantines. + +### Why not a rollback in the same place + +The obvious fix, `await conn.rollback()` on the cancellation path, was **built and rejected on measurement**. +`Connection.rollback()` is `run_in_executor(self._executor, ...)` with `_executor is None`, i.e. the loop's +default thread pool, whose threads may still be occupied by the abandoned statement — bounded only by +`command_timeout` (default 30s). Nothing upstream bounds the wait: `stage_dispatcher.py:514` gathers with no +timeout and `_stop_graph` awaits `runner.stop()` with no timeout. Measured: a cancel returned in **1.005s** +against a 1.0s rollback, serialized across lanes. That trades a bounded, contract-legal row-level bleed for a +multi-second-to-minutes stall **on the demotion path**, which is the one case that matters most. + +A second defect killed the rollback draft outright: writing `await rb` on the `except CancelledError` arm +installs the rollback task as the outer task's `_fut_waiter`, so a **further** cancel cancels the rollback +itself — releasing the connection mid-transaction *and* with a rollback abandoned mid-flight, strictly worse +than today, while a single-cancel regression test stays green. The ordering rule in step 1 above exists +precisely to make that class of mistake unrepresentable, and the test suite pins it with an explicit +re-cancel arm. + +### 3. `claim_fifo_heads` is not the precedent it appears to be + +The lead that opened this investigation reasoned that `claim_fifo_heads` "already shields against precisely +this hazard". **It does not, and the record says so.** Its shielded finally is a `SET LOCK_TIMEOUT` *reset* +guard (the setting is session-scoped and would otherwise leak onto the next borrower). ADR 0114 §2 states +that on a cancellation at a body await "there is **no rollback**… This is **shipped** behavior", its +exit-path table row reads "**no rollback ran** on this path", and +`test_adr0114_claim_fold.py::test_ac3_cancellation_at_body_await_no_rollback_guard_runs` **freezes** it with +`assert "rollback" not in kinds`. + +`claim_fifo_heads` ends on a clean boundary because the guard **commits**, not because it rolls back — which +is why it measures 0 locks in the table above while its siblings measure 7-11. Copying "what +`claim_fifo_heads` does" would therefore have copied a guard that does not roll back. This section exists so +the next reader does not re-derive the wrong precedent from the same comment. + +## Consequences + +- **All 91 `_acquire` sites** are covered, including `enqueue_ingress` — the pre-ACK ingress commit, the + engine's hottest path — which the original two-method framing would have left leaking. +- **One reconnect per cancelled call.** The pool's `size` is derived (`freesize + len(_used) + _acquiring`), + so a dropped connection simply shrinks it and `_fill_free_pool` reopens on demand. Paid only on a path + that was previously corrupting the pool. +- **Shutdown/demotion stays bounded** by `_DIRTY_CLOSE_TIMEOUT` (5s), and on expiry the close completes + detached — the connection is already out of the pool, so expiry costs a slower reclaim and nothing else. +- **No behaviour change on the success or ordinary-error paths**, pinned by two control tests that pass + both before and after the change. +- **Not a data-integrity fix.** At-least-once was never at risk: a cancelled `release_claimed` leaves rows + `INFLIGHT` and `reset_stale_inflight` re-pends them, which `stage_dispatcher.py:491-492` already declares + the intended outcome. What is fixed is pool integrity and the silent EMPTY-all yield. +- **Backend scope: SQL Server only.** Postgres is structurally safe twice over — `async with + conn.transaction()` rolls back on any `BaseException` (asyncpg's `__aexit__` tests `extype is not None`, + with no `Exception` filter), and asyncpg's pool additionally resets under `asyncio.shield`. SQLite shares + the `except Exception` shape but has a single writer connection under an `asyncio.Lock` and no pool, so + there is no next-borrower to inherit anything. +- **A new *source* for a 1222 that was assumed to come only from producer contention** (BACKLOG #344 + instance 2, found independently and concurrently). That work traced the other end of this same chain: + a contended head raises 1222, the store swallows it as a normal EMPTY (the `_is_lock_timeout` branch), + and the dispatcher's EMPTY branch goes to phase IDLE with **no timer armed**. It correctly concludes + that this is a **test-rig gap, not an engine defect**, because production's periodic sweep re-readies + exactly such a lane — the ADR 0070 tests disable that sweep on purpose, which is what makes IDLE + terminal *there*. **Nothing in this ADR contradicts that**, and the severity above is deliberately not + escalated on the strength of it. + + The connection worth recording is the **duration profile**. That analysis assumes the contention is + momentary — a producer holding a head lock in flight. A connection poisoned by this defect holds its + `queue` X locks for as long as it sits unclaimed in the pool's free deque, so the 1222 it manufactures + can repeat across successive sweep ticks rather than clearing on the next one. Production still + recovers, but the mechanism supplies a *persistent* contention source where a momentary one was + assumed. Referenced by ledger number, not by SHA — that branch is unpushed and may be rebased. +- **Private-attribute coupling.** `conn._conn` is aioodbc-internal. This is pre-existing — `_acquire` + already reaches through it to apply the STORE-3 timeout — and aioodbc is hash-locked at 0.5.0, but a + version bump must re-check `Pool.release`'s `if not conn.closed` rule. + +## Acceptance Criteria + +- **AC-1** A cancellation delivered at any body await inside a pooled write leaves the connection + **unlendable** — verified as "not on the pool's free list", against a fake pool that mirrors aioodbc's + real `if not conn.closed` rule rather than an implementation detail. +- **AC-2** AC-1 holds under a **second** cancellation delivered during cleanup. +- **AC-3** An ordinary `Exception` still rolls back and **recycles** the connection (control: must pass + before and after, so AC-1 cannot be satisfied by blanket-discarding). +- **AC-4** The success path still commits and recycles, untouched. +- **AC-5** AC-1..AC-4 hold for `release_claimed`, `reschedule_claimed` **and** `mark_done` — a method the + original lead did not name — so the gate measures the chokepoint, not two patched call sites. +- **AC-6** ADR 0114's frozen no-rollback-on-cancellation test still passes unchanged. + +Verified: the gate failed 6/12 against unpatched code (both cancellation properties × all three methods) +with the four controls already green, and passes 12/12 after. On the live server the same cancellation now +leaves **0** locks, no open-transaction session, an unblocked independent writer, and a pool that dropped +the connection rather than re-lending it. + +## Options considered + +| Option | Verdict | +| --- | --- | +| **Quarantine at `_acquire` (chosen)** | Covers all 91 sites; sync containment is cancellation-proof; bounded cleanup | +| Patch `release_claimed` + `reschedule_claimed` only | **Rejected** — arbitrary slice; `mark_done` and `enqueue_ingress` were measured leaking identically | +| `await conn.rollback()` on the cancellation path | **Rejected** — unbounded await on the demotion path (measured 1.005s, capped only by `command_timeout`); and the `await rb` arm is defeated by a second cancellation | +| Widen the 90 bodies to `except BaseException` | **Rejected** — 90-site edit, each needing its own rollback semantics, with the same unbounded-await problem | +| Document only, fix nothing | **Rejected** — at-least-once holds, but pool poisoning on the demotion path is real and its symptom is silent | diff --git a/docs/adr/README.md b/docs/adr/README.md index fcb3bcd5..4b8f91f2 100644 --- a/docs/adr/README.md +++ b/docs/adr/README.md @@ -185,3 +185,4 @@ what is withheld and what you can request. | [0156](0156-asvs-scorecard-as-data-a-derived-count-verified-evidence-anchors-and-a-fail-closed-drift-gate.md) | **ASVS scorecard as data — a derived count, verified evidence anchors, and a fail-closed drift gate** — the ASVS score is maintained as prose, and nothing checks it. One re-anchoring session (2026-08-01) re-derived the headline count **6 times**, found **12 residuals of record factually false at HEAD** (five of them *absence* claims that had silently stopped being true), and found **10 cells missing from an enumeration described as "arithmetic-checked and complete"** — which survived because the arithmetic closed to 345 and closure was read as proof. **Closure only proves the four buckets sum, not that every cell landed in one.** Decision: hold one `[[cell]]` record per requirement (all 345) in `asvs-scorecard.toml`; **compute** the count so no document can state one; assert **every corpus id appears exactly once** (the check whose absence cost ten cells); machine-verify each cell's `evidence` anchor by asserting an expected **token** still resolves, so code movement reds a test instead of rotting a sentence; require an absence claim to record the **search that proved it plus a positive control that must still hit**, because a grep naming the wrong token returns zero and reads exactly like proof; make **`unverified` a first-class verdict** so inherited-versus-verified Pass is countable (~219 Passes have never been read against the requirement text); and **fail closed rather than skip**. Tool + schema + fixture tests live in this repo and run in public CI; the real scorecard lives in the vault with a vault-CI job — which closes **ASVS 15.1.3**, currently open precisely because six `*_doc_drift` modules assert against documents that `git ls-files docs/security/` shows are **not present** in the tree where CI runs. Rejected: *keep prose and review harder* (every false residual **read as true**; the project's own standard says the mitigation must be structural, not diligence), *one document to rule them all* (that is the current lineage, and it produces five documents asserting three counts), and *publish the vault documents so the guards see them* (attacker roadmap, `SECURITY-DOCS-POLICY.md`). Explicitly **does not** make the score correct — only consistent, derived and drift-detecting; adversarial verification remains the only cure for a wrong verdict | **Accepted (2026-08-01)** — built and merged the same day. **§7 was amended at ratification**: it proposed a vault CI job, and the actions API showed every vault workflow `disabled_manually` (last run 2026-07-27; two vault PRs merged that day with zero checks), so a CI-only design would have shipped dead. Built instead as a vault **pre-commit hook** plus one **narrow new workflow**. That §7 was a confident, unchecked claim about system state is the ADR own thesis applied to itself | | [0157](0157-demotion-safety-fence-scope-on-post-claim-writes-and-a-bounded-graph-stop.md) | **Demotion safety — fence scope on post-claim writes, and a bounded graph stop** — an HA re-check found the leadership lease itself **sound** (DB-clock expiry on both backends, atomic acquire/renew, a real `leader_epoch` token checked inside the claim transaction; scopes B and C were probed and cleared, not assumed) and two things wrong around it. **F1:** the epoch fence guards *some* claims and **nothing after them** — `claim_ready` (the UNORDERED path) carries no epoch predicate on either backend, and every post-claim disposition write (`mark_done`, `mark_failed`, `dead_letter_now`, `complete_with_response`, plus batch twins) resolves by bare `id` with no epoch, owner or status precondition, while `release_claimed` two methods away *does* carry `AND status=$4`. The sharp write is `dead_letter_now`: a demoted node assigning a **terminal** disposition and finalizing the message, breaching the store finalizer's single authority — and a DEAD row is never re-claimed, so H2 skip-and-complete cannot heal it. **F2:** demotion budgets **detection only, never the stop** — `_check_fence` flips a boolean and cancels no listener, worker or in-flight send; `engine.py`'s graph-poll interval is the *only* arithmetic consumer of `(ttl − fence)` in the package and it sizes a poll. Measured budget on stock defaults is **≈8.0 s** (fence 20 + a 1.0 s fence tick + a 1.0 s poll against a 30 s DB-clock expiry) *minus* the renew round trip, which is bounded only by `[store].command_timeout = 30` — **exactly equal** to `leader_lease_ttl_seconds`, so the margin can reach zero and `_fence_ordering` (ordering-only) never notices. Against that, teardown stops inbounds **sequentially** at up to 10.0 s per socket listener (5.0 client grace + 5.0 `wait_closed`, off a module constant unrelated to lease timing) and **unbounded** for file/DB/DICOM inbounds, at a 1,500-connection target. **Decision (6 clauses):** guard writes that make a row **TERMINAL**, never one that returns it to PENDING (fencing the L1 hand-over would convert a permitted duplicate into a forbidden **strand**); two predicates of **opposite polarity** (claim fail-closed, resolve fail-**open**, because a rejected resolve leaves the row INFLIGHT); no `status` conjunct; a demoted node **retains** its stale epoch (`None` means *no fence*, so clearing it disarms the guard); fence every claim path incl. `claim_ready`; and a `TeardownReason{SHUTDOWN,DEMOTE}` bounded, concurrent, edge-triggered demotion stop. Rejected: an `owner=` predicate (dead on SQL Server, which claims `owner=NULL`), a per-claim token (correct, but changes the `Store` protocol — filed, not folded in), fencing writes that ADMIT a message (converts a duplicate into a **loss**), a lease-anchored absolute deadline (makes the monotonic clock load-bearing on Windows, and degrades to an unconditional cancel at the 30/30 collision), and wrapping teardown in `wait_for` **from outside** — `self._running = False` is the last statement of `_teardown_unsafe`, so a cancelled teardown leaves the node **permanently un-re-promotable, silently**. Also records the sequencing asymmetry: Postgres bounds a stranded INFLIGHT row at ~90 s via its periodic sweep, while **SQL Server has no periodic in-flight recovery at all** (`reclaim_expired_leases` is Postgres-only; the runner's `hasattr` gate is the sole exclusion), so the same row is an **unbounded strand today**, with no HA scenario involved. Corrects a code comment attributing a teardown-ordering constraint to "ADR 0066 D3" — that decision does not exist (`grep -c D3` → 0). Single-node SQLite byte-identical (structurally: `set_leader_epoch` is a hard `return None`). #26-clean | **Accepted (2026-08-01)** — C1 (terminal writes only, fail-open) and C6 (bounded, abandon-don't-await) owner-decided; **increments 1, 4 and 5 built 2026-08-02**. Inc 1 fences `claim_ready` plus the eight terminal resolves on Postgres, a rejected resolve rolling the whole disposition back — queue flip, ledger row, event row and finalize together — and then **re-pending** the row. **Three drafted clauses were corrected during the build, each because the draft was strand-direction or false.** C3 said leave the fenced row INFLIGHT for recovery: on SQL Server there is no periodic in-flight recovery at all, so that is an unbounded strand *manufactured by the fence itself* — the one outcome the ADR forbids. C4 alone was a silent total halt: `_reconcile_graph` had only two branches, so `is_leader() and running` matched neither and a live leader held a stale epoch, claiming **nothing**, with no exception and no alert — closed by re-stamping the epoch every reconcile pass. And the cross-backend claim that a demoted SQL Server node "claims nothing" was **wrong**: `claim_ready` is unguarded there, so retaining the epoch covers only the three FIFO claim paths until Inc 3. Evidence is mutation-verified in both directions, which is how the *first* structural gate was caught being blind to its own subject — it keyed on whether a method **mentioned** the guard constant, so deleting the guard from `claim_fifo_heads`' emitted SQL left the mention intact and the gate stayed **green**. **Inc 0/2/3 not built, and Inc 2 is MIS-SPECIFIED in this ADR** — its owner-blind, age-based sweep has no populated `owner` column on SQL Server to discriminate with and would re-pend rows a live leader is working; the real defect is the absence of recovery at graph re-start. Do not build it as written | | [0158](0158-silent-controls-green-signals-that-mean-nothing-and-shape-over-detection.md) | **Silent controls -- green signals that mean nothing, and shape over detection** -- a defect class that recurred at least a dozen times across independent surfaces in one working day (2026-08-01), in at least two sub-classes: **(1) a bound or claim stated INDEPENDENTLY of the thing it bounds** (test: *what measurement backs this?*) and **(2) a control that cannot OBSERVE or ACT ON its own failure** (test: *if this control were broken, what would tell me?* -- if the answer is the control, that is the defect). Spine: **a signal that does not carry enough information to act on forces every reader to re-derive significance by hand, and eventually one of them derives it wrong**; a correct-but-useless RED costs what a silent green costs. Anchor instances: `ci.yml`'s unsourced "~2x headroom" against a real margin near 1.0x, after a PR was killed at 26:07 on the 26:00 step cap with no test failing and passed at 22:25 on a re-run of the same commit; a `UserPromptSubmit` hook that probed a script path this repo has never contained, printed a reassuring status message and exited 0; a gate shim with no `else` on the miss path; **a validator whose input is derived from its subject is satisfied by construction** (zizmor's paths filter excluded the lock its own pinned version arrives through); **an equality check satisfiable by coincidence is not one** (three copies of a hook at identical byte counts differing on one comment line by a 5-for-5-character substitution). Carries the worked inversion: **a measurement beats an estimate only when it measures THE SAME QUANTITY** -- a correct estimate was retracted for a stated "measurement" that was the JOB not the STEP, and a peer amplified it. Seven retractions are recorded **inside the ADR**, including of its own corrections (the pool size, the maximum's filter, the sizing criterion, a BACKLOG number, and line numbers copied from a commit message). Every instance and retraction carries a **found by:** tag, because **no retraction in this document's own production was made by the author of the claim it retracts** -- the bound on that finding is stated. **Shape over detection is reported as a RATIO, not flattered:** three fixes are covered by tests in required CI legs, two by tests that always skip in CI, one by a workflow change with a live residual, the rest corrected prose or still open. Decision splits ENFORCED rules (each naming its gate) from CONVENTION (unenforced, knowingly re-breakable); links rather than restates [CLAUDE.md](../../CLAUDE.md) section 11 and [Secure_Development_Standards](../Secure_Development_Standards.md) section 3; no engine behaviour changes | Proposed (2026-08-01) -- records a class; the coordination-layer fixes it cites are already built | +| [0159](0159-cancellation-safe-pooled-connection-release-mid-txn-discard-at-the-acquire-chokepoint.md) | **Cancellation-safe pooled-connection release — quarantine at the `_acquire` chokepoint** (BACKLOG #348) — `SqlServerStore`'s write idiom is `except Exception: await conn.rollback(); raise`, used at **90 of the 91** `self._acquire()` sites. `CancelledError` derives from `BaseException`, so on a cancellation **no rollback runs**, and aioodbc does not compensate: `Pool.release()` appends a non-closed connection straight back onto the free deque with no rollback, reset or transaction check (0.5.0 `pool.py:196-205`), and `_ContextManager.__aexit__` uses the *same* `release` on the exception path (`utils.py:60-62`). The next borrower inherits an open transaction still holding X locks. **Measured on a live SQL Server**: cancelling `release_claimed` left **7** X locks on `queue`, `reschedule_claimed` 7, `mark_done` 9, `enqueue_ingress` 11 (the pre-ACK ingress commit), against **0** for the `claim_fifo_heads` control; the connection returned to the free list, a raw writer got **1222**, and a real second claim yielded **EMPTY-all** — which ADR 0066 §9 sanctions, so the symptom is *silence*, not an error. Fix: at `_acquire`, on a non-`Exception` `BaseException` only, **synchronously** drop the driver handle (`conn._conn = None` — aioodbc derives `closed` from it and re-adds only `if not conn.closed`) **with no await in front of it**, then close the raw handle off-loop under a 5s bound. The ordering *is* the guarantee: a cleanup that awaits first is defeated by the **second** cancellation that shutdown's cancel-then-gather delivers. A plain `await conn.rollback()` was built and **rejected on measurement** — it runs in the default executor bounded only by `command_timeout` (30s) with no upstream timeout, and a cancel measured **1.005s** against a 1.0s rollback, stalling exactly the **demotion** path (`_stop_graph` cancels but does **not** close the store, so the poisoned connection is re-borrowed there). Corrects the lead that found it on two points: it is **not** a two-method asymmetry, and `claim_fifo_heads` does **not** shield against it — its guard is a `SET LOCK_TIMEOUT` *reset* guard and ADR 0114 §2 plus a frozen test record that **no rollback** runs on its cancellation path; it ends clean because the guard **commits**. Ordinary errors keep today's rollback-and-recycle behaviour, pinned by controls that pass before and after. SQL Server only — Postgres is safe twice over (asyncpg rolls back on any `BaseException` and its pool resets under `shield`), SQLite has no pool | Accepted (2026-08-02) — built and verified the same day; gate failed 6/12 pre-fix, passes 12/12 post-fix, live repro 7→0 locks | diff --git a/messagefoundry/store/sqlserver.py b/messagefoundry/store/sqlserver.py index e279f4ed..5e32f145 100644 --- a/messagefoundry/store/sqlserver.py +++ b/messagefoundry/store/sqlserver.py @@ -136,6 +136,14 @@ # transaction, so the all-or-nothing recovery pass is unchanged. _RESET_LANE_CHUNK = 500 +# BACKLOG #348 / ADR 0159: how long the quarantine of a cancellation-poisoned pooled connection waits +# for its off-loop close before giving up and leaving it to finish detached. A BOUND, not a deadline: +# the connection is already out of the pool before this wait starts, so expiring it costs nothing but +# a slower reclaim. It exists because the close runs on a worker thread that may still be occupied by +# the abandoned statement, which is bounded only by command_timeout (default 30s) — without a cap here +# an engine.stop()/demotion would block for that long, per lane. +_DIRTY_CLOSE_TIMEOUT = 5.0 + # SQL Server native error 1222 = "Lock request time out period exceeded" — raised by SET LOCK_TIMEOUT 0 # in the pooled claim (ADR 0066 §9) when a probe cannot IMMEDIATELY acquire a contended head lock. It is # the normal "head is contended, yield" signal, not an error, so it maps to the EMPTY-all fail-closed @@ -2913,7 +2921,60 @@ async def _acquire(self) -> AsyncIterator[Any]: raw = getattr(conn, "_conn", None) if raw is not None: raw.timeout = self._settings.command_timeout # seconds; 0 = no limit - yield conn + try: + yield conn + except BaseException as exc: + # BACKLOG #348 / ADR 0159. Every caller's own handler is `except Exception` (90 of + # the 91 _acquire sites), so an ordinary error has ALREADY rolled back by the time it + # reaches here — leave that path exactly as it was, connection recycled. A + # CancelledError derives from BaseException, so NONE of those handlers ran: the body + # is unwinding with its transaction still open and its X locks still held, and + # aioodbc's pool does not compensate (`Pool.release()` appends a non-closed + # connection straight back onto the free deque — 0.5.0 pool.py:196-205 — and + # `_ContextManager.__aexit__` releases identically on the exception path). Quarantine + # it so the next borrower can never inherit it. + if not isinstance(exc, Exception): + await self._release_dirty(conn) + raise + + async def _release_dirty(self, conn: Any) -> None: + """Quarantine a pooled connection whose transaction was abandoned by a cancellation, so it + can never be lent to another caller (BACKLOG #348, ADR 0159). + + **The load-bearing line is the synchronous one.** aioodbc derives ``Connection.closed`` from + ``self._conn`` (0.5.0 connection.py:89-93) and ``Pool.release()`` re-adds a connection to the + free deque only ``if not conn.closed`` (pool.py:200-204) — so dropping the handle is a plain + attribute write that makes the connection unlendable with **no await in front of it**. That + matters: shutdown cancels the lane task and the gather can cancel it AGAIN, so any cleanup + that awaits *before* containing the poison is defeated by the second cancellation and + silently restores the bug. Ordering here is the guarantee; the close below is only hygiene. + + Closing the raw handle is then best-effort, off the event loop, and time-boxed. pyodbc's + ``close()`` rolls back uncommitted work (DBAPI), which is what actually frees the X locks — + but it runs on a worker thread that may still hold the abandoned statement, so it is never + awaited unbounded on a shutdown/demotion path. On expiry the close finishes detached; the + pool has already lost the connection and reopens on demand (``size`` is derived, so the pool + simply shrinks). This costs one reconnect per cancelled call — paid only on a path that was + previously corrupting the pool. + """ + raw = getattr(conn, "_conn", None) + if raw is None: # already closed/quarantined — nothing lendable to contain + return + conn._conn = None # ← MUST stay first, and MUST stay await-free + closer = asyncio.ensure_future(asyncio.to_thread(raw.close)) + try: + await asyncio.wait_for(asyncio.shield(closer), _DIRTY_CLOSE_TIMEOUT) + except (TimeoutError, asyncio.CancelledError): + # Expired, or a further cancellation landed while we waited. Either way the connection is + # already out of the pool; let the close land on its own. Swallowed deliberately — the + # caller re-raises the ORIGINAL cancellation, which is the outcome that must propagate. + log.debug( + "sqlserver: quarantined connection close did not complete within %.1fs; it will" + " finish detached (the connection is already out of the pool)", + _DIRTY_CLOSE_TIMEOUT, + ) + except Exception: # noqa: BLE001 - a close failure must not mask the cancellation + log.debug("sqlserver: quarantined connection close failed", exc_info=True) def pool_status(self) -> PoolStatus | None: """The aioodbc pool snapshot (B11): size/idle occupancy + the PRIMARY acquire-wait percentiles. diff --git a/tests/test_backlog348_cancel_dirty_release.py b/tests/test_backlog348_cancel_dirty_release.py new file mode 100644 index 00000000..ccdc2797 --- /dev/null +++ b/tests/test_backlog348_cancel_dirty_release.py @@ -0,0 +1,264 @@ +# SPDX-License-Identifier: AGPL-3.0-or-later +# Copyright (C) 2026 MessageFoundry Organization and contributors +"""BACKLOG #348 / ADR 0159 — a cancelled store call must never hand the next borrower a pooled SQL +Server connection that is still MID-TRANSACTION. + +``asyncio.CancelledError`` derives from ``BaseException``, so the store's house idiom +(``except Exception: await conn.rollback(); raise`` — 90 of the 91 ``_acquire()`` sites) never runs +its rollback on a cancellation. Nothing downstream compensates: aioodbc's ``Pool.release()`` appends +the connection straight back onto the free deque with no rollback, no reset and no transaction check +(aioodbc 0.5.0 ``pool.py:196-205``), and ``_ContextManager.__aexit__`` releases identically on the +exception path (``utils.py:60-62``, ``:90-103``). The next borrower then inherits an open transaction +still holding X locks on ``queue`` rows; a claimer that blocks on them under ``SET LOCK_TIMEOUT 0`` +(ADR 0066 §9) raises error 1222, which the claim path translates into a *silent* EMPTY-all yield. + +Measured against a live SQL Server BEFORE the fix: cancelling ``release_claimed`` left 7 KEY X locks +on ``queue``, the connection went back onto the pool's free list, an independent ``claim_fifo_heads`` +returned EMPTY-all, and a raw writer got 1222. ``mark_done`` (9 locks) and ``enqueue_ingress`` (11) +leaked identically — this is the file's dominant idiom, not a two-method slip. + +NOT a claim_fifo_heads analogue. That method's shielded finally is a ``SET LOCK_TIMEOUT`` *reset* +guard, not a rollback guard: ADR 0114 §2 states there is **no rollback** on its cancellation path and +``test_adr0114_claim_fold.py::test_ac3_cancellation_at_body_await_no_rollback_guard_runs`` freezes +that. It ends on a clean boundary only because the guard COMMITS. + +The fake pool below mirrors aioodbc's REAL release rule (``if not conn.closed: free.append(conn)``), +so these tests assert the contract that actually matters — *can the next borrower be handed this +connection?* — rather than an implementation detail of how it was made safe. +""" + +from __future__ import annotations + +import asyncio +import types +from contextlib import asynccontextmanager +from typing import Any + +import pytest + +from messagefoundry.store.pool_metrics import AcquireWaitHistogram +from messagefoundry.store.sqlserver import SqlServerStore + +# The three methods are deliberately NOT the two the original lead named: mark_done is included to +# pin that the guarantee is a property of the _acquire chokepoint, not of two patched call sites. +_METHODS: list[tuple[str, dict[str, Any]]] = [ + ("release_claimed", {"ids": ["row-1"], "now": 100.0}), + ("reschedule_claimed", {"ids": ["row-1"], "next_attempt_at": 900.0, "now": 100.0}), + ("mark_done", {"outbox_id": "row-1", "now": 100.0}), +] + + +class _RawConn: + """Stands in for the underlying ``pyodbc.Connection`` that aioodbc wraps as ``conn._conn``. + + ``close()`` is synchronous and blocking, exactly like pyodbc's — the store must therefore not + perform it inline on the event loop. + """ + + def __init__(self, ops: list[str]) -> None: + self.ops = ops + self.timeout = 0 + self.closed = False + self.release_close = None # type: Any + + def close(self) -> None: + if self.release_close is not None: + self.release_close.wait() # a threading.Event — hold the close open mid-flight + self.ops.append("raw.close") + self.closed = True + + +class _FakeConn: + """An aioodbc-shaped connection. ``closed`` is derived from ``_conn`` exactly as aioodbc's is.""" + + def __init__(self, ops: list[str], *, gate: asyncio.Event | None = None) -> None: + self.ops = ops + self._conn: _RawConn | None = _RawConn(ops) + self._gate = gate + self.cursor_obj = _GatedCursor(ops, gate) + + @property + def closed(self) -> bool: + return self._conn is None + + async def cursor(self) -> _GatedCursor: + return self.cursor_obj + + async def commit(self) -> None: + self.ops.append("commit") + + async def rollback(self) -> None: + self.ops.append("rollback") + + +class _GatedCursor: + def __init__(self, ops: list[str], gate: asyncio.Event | None) -> None: + self.ops = ops + self._gate = gate + self.description = None + + async def execute(self, sql: str, params: object = None) -> None: + self.ops.append("execute") + if self._gate is not None: + await self._gate.wait() # suspend inside the method body; the test cancels here + + async def fetchall(self) -> list[object]: + return [] + + async def fetchone(self) -> object | None: + # mark_done SELECTs first; None makes it commit-and-return without the event/finalize path. + return None + + async def close(self) -> None: + self.ops.append("cursor.close") + + +class _FakePool: + """aioodbc's pool semantics, verbatim on the point that matters: a released connection rejoins + the FREE list — and so becomes lendable to the next borrower — only when it is not ``closed`` + (aioodbc 0.5.0 ``pool.py:200-204``).""" + + def __init__(self, conn: _FakeConn, ops: list[str]) -> None: + self._conn = conn + self.ops = ops + self.free: list[_FakeConn] = [] + + def acquire(self) -> Any: + conn = self._conn + ops = self.ops + free = self.free + + @asynccontextmanager + async def _cm() -> Any: + try: + yield conn + finally: + ops.append("release") + if not conn.closed: + free.append(conn) # lendable again + + return _cm() + + +def _make_store(conn: _FakeConn, ops: list[str]) -> SqlServerStore: + store = SqlServerStore.__new__(SqlServerStore) + store._pool = _FakePool(conn, ops) # type: ignore[assignment] + store._settings = types.SimpleNamespace(command_timeout=0) # type: ignore[assignment] + store._acquire_wait = AcquireWaitHistogram() + store.committed_txns = 0 + store.body_copies = 0 + return store + + +async def _cancel_inside( + store: SqlServerStore, method: str, kwargs: dict[str, Any] +) -> asyncio.Task: + """Drive ``method`` until it suspends inside its body, then cancel it there.""" + task: asyncio.Task = asyncio.create_task(getattr(store, method)(**kwargs)) + for _ in range(200): # let the task reach the gated execute + await asyncio.sleep(0) + if "execute" in store._pool.ops: # type: ignore[attr-defined] + break + assert "execute" in store._pool.ops, "never reached the gated execute" # type: ignore[attr-defined] + task.cancel() + return task + + +@pytest.mark.parametrize(("method", "kwargs"), _METHODS, ids=[m for m, _ in _METHODS]) +async def test_cancelled_call_never_returns_a_dirty_connection_to_the_pool( + method: str, kwargs: dict[str, Any] +) -> None: + """THE regression gate. Unpatched this fails on every arm: the body's ``except Exception`` does + not see CancelledError, so no rollback runs and the connection rejoins the free list holding its + X locks.""" + ops: list[str] = [] + conn = _FakeConn(ops, gate=asyncio.Event()) + store = _make_store(conn, ops) + pool = store._pool # type: ignore[attr-defined] + + task = await _cancel_inside(store, method, kwargs) + with pytest.raises(asyncio.CancelledError): + await task + + assert pool.free == [], ( + f"{method}: a cancelled call returned the connection to the pool's free list while its" + f" transaction was still open — the next borrower inherits its X locks (ops={ops})" + ) + assert conn.closed, f"{method}: the poisoned connection was not quarantined (ops={ops})" + + +@pytest.mark.parametrize(("method", "kwargs"), _METHODS, ids=[m for m, _ in _METHODS]) +async def test_second_cancellation_cannot_defeat_the_quarantine( + method: str, kwargs: dict[str, Any] +) -> None: + """A cleanup that *awaits* before making the connection unlendable is defeated by a second + cancellation — shutdown cancels, then the gather cancels again — and would silently restore the + original bug while the single-cancel gate above stayed green. So the quarantine must be + established with NO await in front of it.""" + import threading + + ops: list[str] = [] + conn = _FakeConn(ops, gate=asyncio.Event()) + assert conn._conn is not None + hold = threading.Event() + conn._conn.release_close = hold # block the raw close mid-flight + store = _make_store(conn, ops) + pool = store._pool # type: ignore[attr-defined] + + task = await _cancel_inside(store, method, kwargs) + for _ in range(50): # let the cleanup start while the raw close is held open + await asyncio.sleep(0) + task.cancel() # the SECOND cancellation, landing during cleanup + hold.set() + with pytest.raises(asyncio.CancelledError): + await task + + assert pool.free == [], ( + f"{method}: a second cancellation let the connection back into the pool mid-transaction" + f" (ops={ops})" + ) + + +@pytest.mark.parametrize(("method", "kwargs"), _METHODS, ids=[m for m, _ in _METHODS]) +async def test_ordinary_exception_still_rolls_back_and_recycles( + method: str, kwargs: dict[str, Any] +) -> None: + """The non-vacuous control. An ordinary error must keep today's behaviour — the body rolls back + and the connection is RECYCLED, not discarded — so the gate above cannot be satisfied by + blanket-discarding on every exit.""" + ops: list[str] = [] + conn = _FakeConn(ops, gate=None) + store = _make_store(conn, ops) + pool = store._pool # type: ignore[attr-defined] + + async def boom(sql: str, params: object = None) -> None: + ops.append("execute") + raise RuntimeError("execute boom") + + conn.cursor_obj.execute = boom # type: ignore[assignment] + + with pytest.raises(RuntimeError, match="execute boom"): + await getattr(store, method)(**kwargs) + + assert "rollback" in ops, f"{method}: the ordinary-error rollback regressed (ops={ops})" + assert pool.free == [conn], ( + f"{method}: an ordinary error must not discard the connection — only a cancellation, which" + f" leaves it mid-transaction, does (ops={ops})" + ) + assert not conn.closed + + +@pytest.mark.parametrize(("method", "kwargs"), _METHODS, ids=[m for m, _ in _METHODS]) +async def test_success_path_unchanged(method: str, kwargs: dict[str, Any]) -> None: + """The happy path must still commit and recycle the connection untouched.""" + ops: list[str] = [] + conn = _FakeConn(ops, gate=None) + store = _make_store(conn, ops) + pool = store._pool # type: ignore[attr-defined] + + await getattr(store, method)(**kwargs) + + assert "commit" in ops + assert "rollback" not in ops + assert pool.free == [conn] + assert not conn.closed