fix(tests): a swallowed SQL Server lock-timeout stranded an ADR 0070 lane in terminal IDLE (BACKLOG #344 instance 2) - #153
Open
wshallwshall wants to merge 10 commits into
Open
fix(tests): a swallowed SQL Server lock-timeout stranded an ADR 0070 lane in terminal IDLE (BACKLOG #344 instance 2)#153wshallwshall wants to merge 10 commits into
wshallwshall wants to merge 10 commits into
Conversation
…lane in terminal IDLE (BACKLOG #344 instance 2) The intermittent sqlserver-only `assert False` in test_stage_dispatcher.py was never the 8.0s bound. Proven, not argued. MECHANISM. claim_fifo_heads runs under SET LOCK_TIMEOUT 0, so a momentarily contended head raises native error 1222 instantly -- and the store CATCHES 1222 and returns a normal EMPTY result (store/sqlserver.py, the _is_lock_timeout branch; deliberate, the "never-block" yield, logged only at DEBUG). The dispatcher's EMPTY branch then takes T12: phase=IDLE with NO timer armed. Production's periodic sweep re-readies exactly such a lane; the ADR 0070 tests set sweep_interval=3600 with an empty lane_provider ON PURPOSE, so IDLE is TERMINAL there and the lane can never be re-claimed. No budget would have helped: the poll cannot succeed at any size. PROOF. Holding a conflicting row lock across the post-unpark re-claim on a live SQL Server reproduces it deterministically -- empty_claims (0,0,0) -> (1,0,1), lane IDLE, park_until=None, no armed timer, head still `pending` and DUE -- and releasing the lock does NOT recover it. The same stranding then appeared UNFORCED on a local full-file run (test_adr0070_1_retry_forever_never_stops_alerts_stuck[sqlserver]). So this is a test-rig gap, not an engine defect. SQLite's immunity is structural (in-process, no lock-timeout translation); Postgres's 119 observations are too few to exonerate it, so read "SQL Server-only" as "server-backed store". FIX, two halves. 1. _wait_until now RAISES on expiry (BACKLOG #344 proposal 6) with the lane's phase, park deadline, streak, task liveness/exception, the store row's status and next_attempt_at, the clock, and empty_claims -- plus a one-line VERDICT naming which hypothesis the reading proves, so no future occurrence is re-diagnosed from scratch. All 60 bare-assert call sites convert for free (the two that legitimately tolerate a timeout pass required=False; the one that carried a message passes note=). 2. The ADR 0070 phase waits go through _wait_lane, which stands in for the sweep those tests disable -- re-readying a lane found in TERMINAL IDLE, but COUNTED and capped at one, and warned about, so a genuine contention regression still fails loudly rather than being absorbed. The stand-in is disabled when IDLE is itself the target phase. FALSIFIED. With the stand-in budget forced to 0, the same injected EMPTY reproduces the original failure -- now carrying the full diagnostic instead of a bare `assert False`. A guard that passes against unpatched code would have measured nothing. Verified: ruff format + check, mypy strict, and the full file green on all three backends (sqlite + a live SQL Server 2022 container + a live Postgres 16), 76 passed per server leg. NOTE for the merge: PR #138 (claude/ci-margin-correction) also edits #344 instance 2 -- it ADDS a "RE-DIAGNOSED" block recording the mechanism as unresolved. That block is superseded by this one and the two will need a one-time reconciliation.
… fix
Adversarial verification of the mechanism (30 agents, 23 candidates, 20 refuted)
converged on the same diagnosis, but surfaced three things the first pass had wrong or
incomplete. All three verified against the source before being written down.
1. empty_claims is NOT a complete discriminator on its own. `> 0` is biconditional
with the T12 stranding only because the other EMPTY consumer (T11, EMPTY-with-dirty)
is unreachable under this topology; and `== 0` covers at least three distinct stuck
states -- CLAIMING (stalled claim), PROCESSING (hung serializer) and READY (claimer
not picking it up) -- which only the PHASE separates. _verdict now reads phase
alongside empty_claims and names what each combination means, including the
previously unhandled "EMPTY recorded but the lane is not IDLE" case.
2. There is a SECOND, quieter route to the same spurious EMPTY on SQL Server. The batch
claim's lock probe runs WITH (UPDLOCK, ROWLOCK, READPAST), so a contended head is
SKIPPED, and the head-pinned contiguity step then drops the whole lane ("rn=1 missing
drops the whole lane => EMPTY") -- with NO log line at all, not even the DEBUG one.
Same observable, strictly harder to see. The fix already covers it (identical T12
stranding); the ledger and the verdict now name it.
3. Postgres is NOT structurally immune, and saying "too few observations" understated
it. Its claim uses FOR UPDATE SKIP LOCKED (store/postgres.py) -- the same
head-of-line skip. Only SQLite's 0/1,105 is structural. The ledger now says so
instead of leaning on the sample size.
Also fixes a real shadowing bug introduced by the first commit: the store-row loop used
`for lane in ...`, rebinding the `lane` PARAMETER, so with two live dispatchers the
second one's verdict would have named a stale lane.
Measured while here: 12 consecutive full-file runs against a live SQL Server produced
ZERO sweep stand-ins (the one failing run was a concurrently-running experiment of mine
stealing DB time -- 56s vs the usual 27s), so the cap of 1 has comfortable margin.
Re-verified: ruff format + check, mypy strict, the full file green on sqlite + live SQL
Server + live Postgres, and both falsification arms still hold.
… the body #138's session declined my merged-banner proposal, and the argument is better than mine was. A banner asserting "instance 2 resolved" while main still carries "what is NOT settled is the mechanism" is a green signal ahead of its evidence -- the exact failure this item is about, and backlog_status_check.py cannot catch it because it counts banners rather than reading them. Their banner is accurate against the document that will be on main after #138; mine is accurate against the document that is on main after THIS branch. So the banner belongs in the same landing as the RESOLVED body, and that is here. I did NOT take their offered wording. They supplied instance 3's text so I could "name all three" -- but instance 3 and proposal 5 exist only on their branch, so naming them would recreate the mirror of what they just declined: a banner describing a body that is not there if this PR lands first. So the count is gone entirely, per CLAUDE.md §11 / Secure_Development_Standards §3 -- a completeness claim is a liability, and with concurrent PRs adding and closing instances an enumeration goes stale on whichever lands first. The banner now states only what this branch delivers (instance 2 resolved, with the mechanism named) and characterises the rest without counting, so it is true in either merge order. The reason is recorded in the banner itself so the next editor does not helpfully restore a tally. Also merges origin/main (dc0da09, #148's #345/#346 work). Both directions verified by CONTENT, not by the item count: my #344 text (RESOLVED, READPAST, "FOR UPDATE SKIP LOCKED", "not structurally immune") and main's new ##345/##346 all resolve in the merged file, and the merge touched no test files. Gate green at 270. KNOWN, and deliberately left: this still conflicts with #138 on exactly this one line (git merge-tree --write-tree reports a single hunk at :8328, banner only). That is the agreed division -- when #138 lands, take this banner and keep their two corrected sentences in the RE-DIAGNOSED paragraph.
…n exactly one place Paused on the owner's instruction via the coordinator session. Nothing is half-done; the four preceding commits are coherent and independently verified. Why this file exists: every other session's work is pushed to a remote branch. This is LOCAL ONLY -- no PR, no remote branch at all (`git rev-parse --verify origin/<branch>` fails outright). A resumer checking GitHub finds nothing and would reasonably conclude #344 instance 2 was never fixed. Records what is NOT recoverable from the diff: - The mechanism, which was expensive to prove: SET LOCK_TIMEOUT 0 -> native 1222 -> the store CATCHES it and returns a normal EMPTY (deliberate, DEBUG-logged only) -> T12 parks the lane in a TERMINAL IDLE because these tests disable the sweep on purpose. Plus the second, silent READPAST route, and why Postgres is not immune. - The deterministic reproduction recipe. The scratch harnesses were deleted and this is the part nobody should re-derive: hold a conflicting row lock across the post-unpark re-claim, watch empty_claims go (0,0,0) -> (1,0,1) with the head still pending AND due. Includes the signature to match and the [3] clause -- the lane does NOT recover when the lock is released -- which is what proves TERMINAL rather than slow. - That an ISOLATED repro loop cannot reproduce this (800/800 green): running the two tests alone is the one configuration that cannot generate contention. Force it. - Verification already done, including the falsification arm, so nobody redoes it blind. - How to rebuild the DB rigs, with the traps: the native MSSQLSERVER service owning 1434, the single shared MEFOR_STORE_* config that forbids both backends in one pytest invocation, and the silent skip that makes a green local run meaningless. - The #344 banner agreement with PR #138, which until now lived only in two sessions' heads and both are pausing -- including why the agreed order is preferable but NOT load-bearing, so a resumer neither panics about ordering nor restores an instance tally (instance 3 / proposal 5 exist only on #138's branch). - That the ledger claim on 344 is HELD ON PURPOSE and scoped to tests/ only. NOTE on what is deliberately absent: the branch name and worktree path. The leak guard blocked the first version of this file, correctly -- it matches worktree/branch slugs BY SHAPE, on the reasoning that a slug is whatever the task happened to be called and can therefore name a customer engagement, and this repo is public. Not a false positive and NOT allowlisted. Those two strings live in .git/mefor-coord/HANDOFF-344-instance-2.md, which is never published; the committed note points at it and is fully usable without it, since a reader is already on the branch. Docs-only: no code, no test, no ledger banner touched.
…t the tip Two additions from the #348 / ADR 0159 session, which reached the same 1222 from the opposite end and sent it over rather than sitting on it. Still paused -- this finishes the stopping note, it does not resume work. 1. A CANCELLED store call is a third route to the same EMPTY, and it refines how the fix commit words the cause. CancelledError derives from BaseException, so the store's `except Exception: await conn.rollback()` idiom never runs its rollback on cancellation, and aioodbc's Pool.release() returns the connection to the free deque with no rollback or reset. THEIR measurement (live container): cancelling release_claimed left 7 KEY X locks on `queue`, vs 0 for a claim_fifo_heads control, after which a real claim returned EMPTY-all and a raw writer got 1222. VERIFIED HERE before recording it, rather than relayed: store/sqlserver.py has 90 rollback sites guarded by `except Exception` and ZERO using `except BaseException` or a `finally`. So the gap is real in our source, not just in principle. Why it matters: 58f8f13's message reasons from MOMENTARY contention -- a live producer holding a head lock in flight. A connection poisoned this way holds its locks as long as it sits unclaimed in the pool, so the 1222 can repeat across successive sweep ticks instead of clearing on the next. The chain into T12 and the terminal IDLE is identical; the duration and origin of the contention are not. It does NOT change this branch's conclusion -- production still recovers via the sweep, so "test-rig gap, not an engine defect" stands, and that session explicitly declined to escalate severity on it. Recorded as: if you see a 1222 you cannot attribute to a live producer, look at #348 first. 2. Name the fix commit, not the tip. HEAD was circulated between sessions as "the fix"; it is a banner edit plus this note and touches no code. THE FIX IS 58f8f13. The handoff now says so in a callout above the commit table, because the mis-relay already happened once and a tip SHA moves every time this note is amended. Cross-referenced by LEDGER NUMBER (#348 / ADR 0159), never by SHA -- that work is also unpushed and may be rebased. Docs-only.
wshallwshall
enabled auto-merge (squash)
August 2, 2026 18:20
…1648a # Conflicts: # docs/BACKLOG.md
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Test-rig gap, not an engine defect. Stated up front because the one-line summary reads like a production stranding and it is not.
claim_fifo_headsruns underSET LOCK_TIMEOUT 0. A contended head raises native 1222; the store catches it and returns a normal EMPTY (DEBUG-logged only); the dispatcher's T12 then parks the lane in IDLE with no timer armed. Production's periodic sweep re-readies exactly such a lane — the ADR 0070 tests setsweep_interval=3600with an emptylane_provideron purpose, which is what makes IDLE terminal there.Forced deterministically on a live SQL Server.⚠️ An isolated repro loop cannot reproduce it (800/800 green) — running the two tests alone is the one configuration that cannot generate contention. Force it; do not sample for it.
Verified: ruff, mypy strict, ledger green, suite green on sqlite + live SQL Server + live Postgres, plus a falsification arm.
Related: BACKLOG #348 / ADR 0159 identifies a third route to the same 1222 — a cancelled store call, since
CancelledErroris aBaseExceptionand theexcept Exception: rollback()idiom never fires. Independently confirmed in-source from this branch: 90 rollback sites onexcept Exception, zero onBaseException/finally. That does not change this PR's conclusion, and neither session escalated severity on the other's finding.HANDOFF-344-instance-2.mdat the repo root. A sibling session deliberately left its equivalent untracked on the grounds that no HANDOFF has ever been tracked at the root. Say the word and I will drop it from the branch — the rest of the diff is the fix.Authored by the
keen-mclarensession; pushed and opened by the coordinator at the owner's instruction, so that pushes are serialised through one place. Merge remains the owner's call.🤖 Generated with Claude Code