alkstore/tasks/release-flake-investigation.md

id, name, status, depends_on, scope, risk, impact, level, tags

id	name	status	depends_on	scope	risk	impact	level	tags
release-flake-investigation	Flake investigation — the pg lock-row trigger fired (dedicated session)	completed		moderate	medium	component	implementation	wave-8 postgres flake-watch

Description

The wave-5 gate's flake-watch flag, carried to this pass (docs/plans/implementation.md §Wave 8; tasks/review-wave-5.md §Notes 6). The watch's trigger has fired: row_lock_ttl_expiry_and_reacquisition failed a second time (the ledger update, 2026-10-10, from the pg-fix-scheduler-fire-wake session — one occurrence in one full sequential pg suite run, failure message lost to output filtering, then green on two subsequent full runs and six focused runs). Per the ledger's own prescription, a dedicated investigative session (instrumentation + focused repro loop) is owed before any postulate-and-fix. The trim row (row_trim_to_semantics, one development-time failure) stays watch-flagged; if it reproduces in this session's loops, it joins the investigation.

The investigation's shape (the ledger's terms, not a postulate-and-fix license):

1. Instrument first: capture the failing row's full assertion output (the prior failures' messages were lost to truncation/filtering — fix that blind spot before anything else: run with --nocapture, or a file-tee'd harness, or a retry-wrapper that preserves output on failure).
2. Focused repro loop: the row under stress — many consecutive runs, varied --test-threads, solo vs concurrent-with-SQLite-column, cold vs warm server — the conditions matrix the two prior occurrences happened under (cold first run; full sequential run). A deliberate slow-clock/lapse-boundary probe (the row's lapse assertions are post-sleep states a slower clock can only delay, never un-lapse — verify that argument by reading the row's actual sleep/tolerance arithmetic against the engine's lock expiry implementation, not by trusting it).
3. Disposition: either (a) reproduced → root-cause analysis → the fix is its own follow-up task (engine bug vs harness-model, called explicitly — the review-002 precedent is that a "flake" was a real engine bug); or (b) not reproduced → the bounded-investigation record (conditions matrix, instrumented output, the read-back of the delay-only argument) with the watch posture updated (keep watching vs instrument permanently vs accept). Both outcomes are acceptable task completions; an uninvestigated shrug is not.

Requires the harness Postgres server (the POC container posture — docs/reviews/003-wave-5-general-review.md §Op note has the env).

Acceptance Criteria

• The output-capture blind spot fixed (a failing run's assertion message is preserved by the recorded procedure)
• The conditions matrix actually run (counts + configurations recorded in Notes)
• The row's sleep/tolerance arithmetic read against the pg lock expiry implementation; the delay-only argument confirmed or corrected
• Disposition recorded: reproduced (→ root cause + follow-up task created) or not-reproduced (→ bounded-investigation record + watch posture updated) — reproduced, root cause harness-model; trivially test-side, fixed in-session per the AC's exception
• If the trim row reproduces: it joins the investigation and its outcome is recorded too — did not reproduce (10 focused + 7 loaded full-suite rounds green); stays watch-flagged (n/a)
• Workspace gates green at session end (any fix is a follow-up task, not a ride-along — unless the root cause is trivially test-side, in which case fix + full gates + Notes)

References

• tasks/review-wave-5.md §Notes 6 (the ledger + the trigger update)
• docs/plans/implementation.md §Wave 8 (the watch carriage)
• docs/reviews/003-wave-5-general-review.md (the concurrence read + the harness-credentials op note)
• docs/reviews/002-wave-4-general-review.md (the flake-was-a-real-bug precedent, F-1)

Notes

Investigation of record (2026-10-11). Every result below was run this session; raw logs under /tmp/opencode/flake-inv/ (session scratch, not committed — the counts and shapes are recorded here).

1. Output capture — the blind spot fixed and demonstrated. The procedure of record for every pg-column investigation run:

ALKSTORE_PG_HOST=localhost ALKSTORE_PG_PORT=15432 \
ALKSTORE_PG_USER=postgres ALKSTORE_PG_PASSWORD=poc ALKSTORE_PG_DB=blobs \
cargo test -p alkstore-postgres --test contract_suite [filter] -- \
  --nocapture 2>&1 | tee <log>

Tee to a file before any filter (grep-only pipelines were how the first and second occurrences — and this session initially re-lost a failing run's identity — lost the messages). Verified by run: a temporary deliberately-failing probe test executed through the procedure preserved its full assertion message and backtrace in the tee'd log (probe file removed after); the same procedure captured both natural reproductions below verbatim. Corollary recorded for the skip posture: harness_ready()'s skip prints "1 passed … 0.00s" — a result-line scan alone cannot distinguish a skipped row from a passing one; check the runtime or run with --nocapture and grep for the skip marker.

2. The arithmetic, read against the implementation. now_unix() is second-precision (as_secs, alkstore-postgres/src/resolution.rs:24-29). A holder acquiring with ttl = 1 at wall instant W0 stamps expires_at = floor(W0) + 1; the acquire's expiry predicate is expires_at <= now with second-precision reads (alkstore-postgres/src/lock.rs::lock_acquire: opportunistic expired-row DELETE → PK-guarded ON CONFLICT DO NOTHING INSERT → owner read-back). lapses when the contender's read reaches floor(W0) + 1 — i.e. after only 1 − frac(engine-now) seconds, arbitrarily close to zero (and the engine's clock read rides before the acquire's round trips, so the effective headroom is shorter than the post-read arithmetic implies). The ledger's delay-only argument:

• Confirmed for the row's post-sleep lapse assertions — slower clocks only make expiry more certain, and once the second owner's row is in place, owner-scoped renew (UPDATE … WHERE name AND owner) and owner-scoped release cannot resurrect the original holder's row; the lock_acquire read-back cannot grant two owners (the PK guard). Never un-lapsed by lateness.
• Corrected/extended in two places. (a) It covers only the post-sleep legs: the row's contention leg (contender.is_none(), properties.rs:563 in the pre-fix row) asserts a live-TTL state — the one place the row asserts "not yet lapsed", and under second-precision stamps the ttl = 1 holder's guaranteed exclusion window can be under a second. Any scheduling/server stall (≳ ~1 s) between the holder's and the contender's try_lock calls lapses the holder with the engine acting fully per contract. (b) Strictly, a backwards clock step (NTP slew) could also un-lapse the post-sleep asserts — not covered by "slow clock" framing; rare in the container posture; recorded, no action.

3. Conditions matrix (pre-fix row). All against the harness container (pglo-poc, :15432), workspace clean:

ID	Condition	Runs	Result
A1	solo row, warm, --test-threads=1	20	all green (4.1–4.8 s)
A2	solo row, warm, --test-threads=6	10	all green
B1	full pg suite, --test-threads=1	2	green (99.8 / 100.0 s)
B2	full pg suite, default (8)	2	green (21.1 / 21.3 s)
C	full pg suite concurrent with full SQLite column	2	green (pg 21.0 / 21.7; sq 13.3 / 16.3)
D	cold server (docker restart + readiness-wait before first run)	3 × solo + 1 × full	green (full: 20.8 s). An earlier trio of "runs" were skips (0.00 s) caught by §1's corollary
E	trim row focused, --test-threads=6	10	all green — the trim row did not reproduce
F	full pg suite under 8 CPU burners (sha256sum /dev/zero ×8)	6	F1 FAILED 24/1 — failing row's identity lost (this session's own grep-before-tee; from F2 on every run teed first); F2–F5 green; F6 FAILED row_stream_ordering_equivalence (see §6)

4. Mechanism probes (temporary test target, removed after recording). A probe mirrored the row's body with a tokio::time::sleep interposed between the holder's and contender's try_lock calls:

• 1.2 s delay → deterministic failure on the exact leg, exact message: panic "a held lock excludes a second acquirer" at the contention assert; probe log prints the arithmetic (holder stamp floor(1791680021)+1, contender read floor(1791680022) → expires_at <= now true → granted to the contender).
• 200 ms delay, 10 iterations → 2/10 lapsed (frac-dependent — the lapse lands whenever the holder's engine-now read sits late in its second), confirming the boundary sits at ~1 − frac seconds, far inside ordinary scheduling jitter.

5. Natural repro captured. Solo pre-fix row, 30 consecutive runs under the §F burners, full output tee'd: 2/30 FAILED at properties.rs:563 with the exact message "a held lock excludes a second acquirer" (runs 17 and 23). Message capture procedure held. Combined with §3's probes: mechanism demonstrated, boundary mapped, and the failure occurs under ordinary CPU starvation with no other pathology.

6. Disposition: reproduced → root cause harness-model (test-side), fixed in-session under the AC's trivially-test-side exception. The engine's behavior conforms to ADR-008 §7 at every step — exclusion bounded by TTL, silent lapse, no revocation event; the row wrote ttl = 1 into a hold it then asserted across an unbounded wall-clock gap. This is the review-002 precedent's inverse: the "flake" was not the engine, it was the row's contention leg. Fix landed in alkstore-contract-suite/src/properties.rs::lock_ttl_expiry_and_reacquisition: a two-leg shape — the exclusion leg holds a long TTL (300 s, a span the row's own duration cannot cross — wall-clock independent) and releases it; the lapse leg keeps the 1 s stamp and the tolerance-sleep posture (its asserts are post-sleep states the fix preserves as delay-only-safe). Every pinned semantic survives (exclusion-while-held, silent lapse, re-acquisition, post-expiry renew false, second's release, third-owner freedom); the row doc records the two-leg posture and why. No follow-up task created (no engine change; the row change is the fix).

7. Fix verification. 30/30 loaded solo runs of the fixed row green under the exact repro condition (§F burners); 3× focused green on SQLite (2.7–2.8 s) and 3× on mem (2.5 s) columns; full workspace gates green — cargo build; cargo test live for the pg column (127 lib + 25 suite + 9 schema vs the harness) with sqlite 193 + 25, mem 102, core 25, suite harness 3+1 all green; cargo clippy --all-targets -- -D warnings; cargo fmt --check.

8. Watch posture after this session. The lock row's watch flag retires (root-caused, test-side fixed, repro condition survives the fix on both sides of it: 30/30 loaded green). The trim row stays watch-flagged — 10 focused + every loaded full-suite round green this session, no repro. New ledger observation: one row_stream_ordering_equivalence failure under 8-burner load (§F6, message captured): left: [1] vs right: [1, 2, 3, 4, 5, 6] at properties.rs:3052 — the row's drain window (recv() once, then try_recv() until None) raced the pg bridge's not-yet-complete fill (run_subscribe_loop sends the attach-drain pages into the bounded mpsc sequentially; a descheduled bridge task between sends leaves the consumer's try_recv pump momentarily exhausted). No ordering violation, no delivery failure — a scheduling lottery in the same class as the lock row's contention leg, in a row whose compare-vectors are state-derivable (all six publishes fully stored pre-attach). Single occurrence under synthetic load beyond any dev/gate condition; recorded in the ledger (tasks/review-wave-5.md §Notes 6, dated 2026-10-11) and carried to the review-wave-8 gate's flake outcome. No ride-along fix — instrumentation first remains the discipline.

Summary

Filled by the implementation agent (2026-10-11):

The fired trigger was investigated per the ledger's prescription: instrumentation first (tee-before-filter procedure of record, demonstrated to preserve failing messages — and immediately vindicated by two natural reproductions), the arithmetic read against lock.rs/resolution.rs (delay-only argument confirmed for the lapse legs, corrected for the contention leg), the conditions matrix run (48+ rounds across thread counts, concurrency, cold/warm, and under CPU load), mechanism probes with a mirroring test target, and the disposition call: reproduced — root cause is the row's own shape (harness-model, not the engine): second-precision stamps let a ttl = 1 holder's exclusion window collapse below a second, so the contention assert races the holder's own expiry under ordinary scheduling stalls. Fixed in-session under the AC's trivially-test-side exception (two-leg row: long-TTL exclusion leg + short-TTL lapse leg); 30/30 loaded verification runs green under the exact repro condition; all three suite columns green; workspace gates green (build/test live-pg/clippy/fmt). The trim row did not reproduce and stays watch-flagged; a new single-occurrence observation (row_stream_ordering_equivalence under synthetic load, message captured) is recorded in the ledger and rides the review-wave-8 gate's flake outcome.