Skip to content

feat(core): log SQLite write-lock holds and lock-stop call sites - #201

Merged
brentyates-swx merged 22 commits into
swxtchfrom
fm/opencode-stop-instrument-180
Oct 10, 2026
Merged

feat(core): log SQLite write-lock holds and lock-stop call sites#201
brentyates-swx merged 22 commits into
swxtchfrom
fm/opencode-stop-instrument-180

Conversation

@brentyates-swx

@brentyates-swx brentyates-swx commented Oct 10, 2026

Copy link
Copy Markdown

Summary

This adds diagnostic logging only. When a session next stops on SQLITE_BUSY, the log will name who held the write lock and where the failing write was raised. Retry schedules, timeouts, SQL, transaction behaviour and return values are unchanged. It uses the existing Effect logger, and each line is bounded to one per event.

It follows #194.

  • Lock holds (effect-drizzle-sqlite session). A top-level BEGIN IMMEDIATE or BEGIN EXCLUSIVE transaction that holds the write lock for more than 250 ms logs sqlite write lock held. The line carries pid, purpose, span, outcome (commit or rollback) and durationMs.

    • purpose comes from the new TransactionPurpose reference, which commitDurableEvent sets to the event type. Where it is unset, the enclosing span's name is used.
    • The hold is timed from the moment BEGIN succeeds, so time spent waiting for the lock is not counted.
    • Savepoints and deferred transactions never log.

  • Retry exhaustion (retryLocked). One line is logged each time a lock failure leaves the retry gate. It carries pid, statement, attempts, elapsedMs, sqlite.code and sqlite.errcode.

    • statement is only the operation keyword (insert, update, begin immediate, ...). Comments, literals, identifiers and parameters are never logged.
    • The extended code tells SQLITE_BUSY (5) from SQLITE_BUSY_SNAPSHOT (517) on both the bun and node drivers.
    • A stale snapshot, which is not retried, logs sqlite lock failed without retry.

  • Stop call site (SessionProcessor.halt). When a failure reaches halt, its existing process error line gains a failure field. It carries:

    • event: the durable event type that failed to commit;
    • stage (handler or stream) and case (the processor event type);
    • callSite: the chain of runtime stack frames captured where the failure was raised (for example Session.updatePart < SessionProcessor.finishReasoning).

    The new FailureOrigin module records this in a WeakMap keyed by the failure object, so the failure itself is never modified.

Tests

  • packages/core/test/sqlite-lock-diagnostics.test.ts (new, 12 tests). Everything runs on real SQLite.
    • Holds: commit, rollback, quiet below 250 ms, span fallback, a nested savepoint, and a failed deferred-FK commit.
    • Exhaustion on the bun, core-node and standalone-node drivers, including attempt counts when one effect runs concurrently.
    • Redaction of seven hostile statements.
    • Stale snapshot on all three drivers.
  • packages/opencode/test/session/processor-effect.test.ts: halt tests under a real held lock, for both a reasoning-end failure and a step-finish failure, plus a failure inside a named provider-stream callable. They assert the event, stage, case and innermost call-site frame.
  • Each fix was shown to turn its test red when reverted.
  • sqlite-busy and queue-admission pass unchanged, and bun typecheck is clean in all four affected packages.

Follow-up

🤖 Generated with Claude Code

https://claude.ai/code/session_01QuyVZfg7zCF6ZJmDUf8BnB

@brentyates-swx
docs(core): plan the SQLite snapshot-loss fix for #162
ef663e2 
Plan for fixing forward accepted-prompt loss under concurrent writers on top
of the reverted base (60f779b). Evidence: data/opencode-fixed-binary-155/
report.md sections 5 and 6, and data/opencode-revert-155/report.md section 7.

Mechanism, from the code (not yet measured):

- The admission transaction is SessionQueue writable() in
  packages/opencode/src/session/queue.ts. It reads first (EventV2.assertWritableIn)
  and then writes (sequence upsert and queue insert). It begins as a deferred
  transaction, so its read snapshot exists before its write lock is taken.
- A plain-busy wait inside a deferred transaction can only end in
  SQLITE_BUSY_SNAPSHOT when another connection commits during the wait: the
  snapshot goes stale, and the driver does not restart the transaction. This is
  the mechanism that predicts the report's section 6.3 observation that the
  snapshot class grew when the wait was added. It is not measured yet.
- The admission and promotion writes are the deferred read-then-write
  transactions found on the accepted-prompt path by grepping its call sites.
  The EventV2 append that persists the user message already begins with
  behavior immediate (event.ts:467). The proof decides whether that is complete.

Correction to #162. Its option 2 names Client.make beginTransaction, which the
production path never reaches. opencode runs transactions through
effect-drizzle-sqlite, whose withTransaction issues "begin <behavior>" itself
(packages/effect-drizzle-sqlite/src/effect-sqlite/session.ts), default deferred.
Effect's SqlClient.withTransaction, which reads beginTransaction, has no caller
in opencode. The mechanism that works is the existing per-transaction option,
behavior immediate, which the codebase already uses in event.ts and project.ts.

Choice: (a) BEGIN IMMEDIATE on write-capable transactions, not (b) restart.
- (a) takes the write lock before any read snapshot exists, so the failing
  class cannot occur for that transaction. The lock wait happens at BEGIN,
  where a retry is safe because nothing has been read yet.
- (b) restarts a body that has already run. The admission body is pure SQL,
  but restart needs a per-site audit of every transaction body for duplicated
  side effects, and it leaves the stale-snapshot race in place.

Steps:

1. Restore the #155 plain-busy wait and the #154 fail-fast on
   SQLITE_BUSY_SNAPSHOT in packages/core/src/database/sqlite.bun.ts,
   sqlite.node.ts and packages/effect-sqlite-node/src/index.ts. The three
   copies stay identical, as #162 requires. Dedupe stays with #165.
   sqlite.node.ts is outside the brief's named scope; it is named here
   because it is the third copy of the same rule.
2. Begin writable() with behavior immediate in queue.ts. This covers every
   queue write: the callers are admit, reserve, withdraw, restore, and update.
3. Restore the #155 test versions that cover the wait and the fail-fast:
   packages/core/test/sqlite-busy.test.ts, and the opencode lock fixture
   and consumer bounds, which #155 raised for the 5 s window.
4. Add a regression at the admission path. A second connection holds the
   write lock across the admission read, then commits. The admission must
   succeed and persist its row. Red proof: revert writable() to deferred.
   Also run the restored core tests against the reverted driver for red.
5. Proofs, in the brief's order: focused suites with CI commands; the
   candidate against the reverted parent, concurrently on separate DBs, same
   load, several pairs, raw counts; fresh-store proof. The parent is the
   reverted build (tree equal to bf5180a).

Not in this change: session queue consumption (#167); the CHANGESET entry
(needs the PR number at publication); the snapshot-tracking PATH issue (#164).

Claude-Session: https://claude.ai/code/session_01LrS7BTRTnc6eYrSxBFoWAo
@brentyates-swx
fix(core): restore the SQLite lock-wait window for busy statements
e6461df 
Restores the plain-busy wait that #155 added. A statement that meets a lock
retries asynchronously for 5 seconds of elapsed contention. A stale-snapshot
failure (SQLITE_BUSY_SNAPSHOT) is still not retried (#154). The three retry
copies stay identical in sqlite.bun.ts, sqlite.node.ts and effect-sqlite-node.

Red on the reverted driver: the restored sqlite-busy suite fails 14 of 23.
The 250 ms window cannot absorb a 1.5 s hold, and a stale-snapshot statement
is executed more than once. Green with the window: 23 of 23. The opencode
lock-consumer suites pass 36 of 36 with their #155 bounds.

Refs #162

Claude-Session: https://claude.ai/code/session_01LrS7BTRTnc6eYrSxBFoWAo
@brentyates-swx
fix(opencode): admit queue writes under BEGIN IMMEDIATE
1948f9d 
SessionQueue writable() runs its read (EventV2.assertWritableIn) and then its
write in one transaction. Begun deferred, that transaction pins a read
snapshot before it takes the write lock. If another writer commits while the
write waits on the lock, the snapshot goes stale, and the write fails with
SQLITE_BUSY_SNAPSHOT, which is not retried. The prompt was already accepted
(204), so it was lost with no user message.

With behavior immediate the write lock is taken at BEGIN, before any read.
The lock wait then happens where a retry is safe, and no snapshot can go
stale inside the transaction. The restored lock-wait window absorbs the wait.

The regression holds the write lock from a second connection across the
admission read, then commits. Red with the deferred writable: the sequence
upsert fails with SQLITE_BUSY_SNAPSHOT after the commit. Green with immediate.

Refs #162

Claude-Session: https://claude.ai/code/session_01LrS7BTRTnc6eYrSxBFoWAo
@brentyates-swx
Merge origin/swxtch into fm/opencode-lock-fix-162
ac9eadd 
Brings in 8d536e3 (#159) so the branch is current with the default branch.
It does not touch the SQLite driver, the queue, or the lock tests.

Refs #162

Claude-Session: https://claude.ai/code/session_01LrS7BTRTnc6eYrSxBFoWAo
@brentyates-swx
refactor(core): give the SQLite busy-retry gate one owner
9e088df 
The busy-retry schedule and the stale-snapshot gate were copied into three
statement paths: sqlite.bun.ts, sqlite.node.ts and effect-sqlite-node. #155
changed all three, so a rule change had to land three times, and nothing said
which copy was authoritative.

effect-sqlite-node/src/retry.ts now owns both. It exports retryLocked, which
every driver routes its statements through, and it recognizes the stale-snapshot
class in both native error shapes: bun:sqlite reports it by code and node:sqlite
by errcode. The module imports only effect, so the Bun binary can consume it
without loading node:sqlite. The drivers no longer carry a schedule or a gate.

Behavior is unchanged. The core busy suite is 23 of 23 across the three
clients. Removing the snapshot exclusion from the gate turns the three
stale-snapshot tests red. Dropping the node error shape turns two of them
red (core-node, standalone-node), and dropping the bun shape turns one red
(bun). Removing the retry turns the six lock-wait tests red.

statementError, the native error classification, is still copied in the same
three files. It is not part of this change, and #87 tracks it.

Refs #162
Refs #165

Claude-Session: https://claude.ai/code/session_01LrS7BTRTnc6eYrSxBFoWAo
@brentyates-swx
test(opencode): wait on the admission's busy attempt, not a sleep
381667f 
Review round 1. The admission test held the write lock for a fixed 1500 ms,
then committed. An admission that started late ran after the commit and
passed even with a deferred write, so the test did not prove the fix.

The test now counts the admission's statement attempts at bun:sqlite's query
path, as the core sqlite-busy test does, and records the native codes of the
attempts that throw SQLITE_BUSY. It commits only after the admission has met
the held lock, asserts the admission is still pending, then checks the
persisted row. The timeout is a backstop, not the signal. On failure, the
message lists the admission's attempts and busy codes.

Checked locally:
- writable() immediate: pass, with and without a 1600 ms delay before the fork
- writable() reverted to deferred: fail with SQLITE_BUSY_SNAPSHOT after the
  commit, with and without the 1600 ms delay

No product code changes in this commit.

Claude-Session: https://claude.ai/code/session_01LrS7BTRTnc6eYrSxBFoWAo
@brentyates-swx
test(opencode): read the admission probe's query method through its d…
d71e35e 
…escriptor

Referencing prototype.query unbound tripped the unbound-method lint rule. Reading
the descriptor's value keeps the method unbound and adds no behavior change.

Claude-Session: https://claude.ai/code/session_01LrS7BTRTnc6eYrSxBFoWAo
@brentyates-swx
docs(opencode): require queue writes to go through writable()
53c96a3 
The #162 fix makes writable() open every queue write with BEGIN IMMEDIATE. The
rule lived only in a code comment, so a future queue write could bypass it. The
V1 Prompt Queue section now states it where contributors and agents read queue
rules.

Claude-Session: https://claude.ai/code/session_01LrS7BTRTnc6eYrSxBFoWAo
@brentyates-swx
test(core): one statement-attempt counter for the busy tests
8d2e350 
The core sqlite-busy test and the opencode admission test each patched bun:sqlite's
query method to count statement attempts. That job now has one owner, the
fixture-only module packages/core/src/database/sqlite-attempts.ts. Both tests import
it, and the core test's node branches count through its countStatement.

No runtime module imports the new file. It sits in core's src because opencode tests
reach core through its wildcard export, and no shared test-support package exists.

Checked: core sqlite-busy (23 pass); admission green with and without a 1600 ms delay
before the fork; admission red with writable() reverted to deferred, with and without
the delay (busy codes end in SQLITE_BUSY_SNAPSHOT).

Claude-Session: https://claude.ai/code/session_01LrS7BTRTnc6eYrSxBFoWAo
@brentyates-swx
docs: record the #162 lock fix in CHANGESET.md
7b0ea4a 
Adds the fork changeset entry for PR #194 (#162 and #165)
as the first item under Runtime fixes. Nothing else changes.

Claude-Session: https://claude.ai/code/session_01LrS7BTRTnc6eYrSxBFoWAo
@brentyates-swx
docs(core): plan SQLite lock-hold and stop-site diagnostics (#180)
33237dd 
Diagnostic-only logging on candidate 7b0ea4a (fm/opencode-lock-fix-162) so
the next SQLITE_BUSY session stop names its lock holder and its call site.
Every new line goes through the existing Effect logger; no value, cause, SQL,
schedule, timeout or transaction behaviour changes.

1. Write-lock hold timing (effect-drizzle-sqlite session.withTransaction).
   For a top-level BEGIN IMMEDIATE/EXCLUSIVE that succeeds, time from BEGIN
   returning to a successful COMMIT or ROLLBACK (including the rollback after
   a failed commit). Over 250 ms, log "sqlite write lock held" with pid,
   transaction purpose, current span and duration. Savepoints, deferred
   transactions and failed BEGINs are not holds. Purpose comes from a new
   TransactionPurpose context reference, falling back to the current span.
   event.ts commitDurableEvent provides the event definition type.

2. Retry exhaustion (effect-sqlite-node retryLocked, given the statement SQL
   by all three drivers). Per execution, count attempts and elapsed time;
   when a lock failure leaves the gate, log once: statement head, attempts,
   elapsed ms, and the native cause code and full errcode (item 4), with
   separate messages for an exhausted window and a stale snapshot that
   fails without retry. Recovering statements log nothing.

3. Stop call site. A core side table keyed by the failure object records
   where a failure came from without changing it: commitDurableEvent records
   the event type and the span chain at the failed commit; the processor
   records the stream case (handler) or the provider stream (stream).
   halt's existing "process" error line adds those fields.

Tests (focused, producer-driven, removal-to-red proven):
- packages/core/test/sqlite-lock-diagnostics.test.ts: long vs short holds,
  commit and rollback, wait-then-short-hold, nested savepoints; one
  exhaustion summary with observed attempt count; none on recovery;
  BUSY vs BUSY_SNAPSHOT native codes on bun, core-node, standalone-node.
- packages/opencode/test/session/processor-effect.test.ts: halt line names
  event, case and call site for reasoning-end (finishReasoning helper) and
  step-finish (message.updated); provider-stream failure has no event.
Preservation: core sqlite-busy and opencode queue-admission suites unchanged.
Live proof: env -i scratch store run whose file log shows the hold line.

Claude-Session: https://claude.ai/code/session_01QuyVZfg7zCF6ZJmDUf8BnB
@brentyates-swx
feat(core): log long SQLite write-lock holds and lock retry give-ups
db87d48 
Diagnostic logging only (#180); every value, cause, SQL statement, retry
schedule and transaction step is unchanged.

- effect-drizzle-sqlite withTransaction times a top-level immediate or
  exclusive BEGIN from its success to the successful COMMIT or ROLLBACK
  (including the rollback after a failed commit) and logs "sqlite write lock
  held" with pid, purpose, span, outcome and duration over 250 ms. A new
  TransactionPurpose reference names the purpose, else the caller's span.
- retryLocked takes the statement SQL from all three drivers and, per
  execution, logs one summary when a lock failure leaves it: statement head,
  attempts, elapsed ms, and the native code and full errcode, so SQLITE_BUSY
  and SQLITE_BUSY_SNAPSHOT stay distinguishable.
- A core FailureOrigin side table records a failure's event type and span
  chain at the durable-event commit without changing the failure.
- commitDurableEvent supplies its definition type as the purpose.
- SessionProcessor records the stream case (or the provider stream) on a
  failure, and halt's "process" line adds the recorded event, case and
  call site.

Claude-Session: https://claude.ai/code/session_01QuyVZfg7zCF6ZJmDUf8BnB
@brentyates-swx
Merge origin/swxtch at b18e7ff into fm/opencode-lock-fix-162
cebd89f 
Brings in b18e7ff (PR #161) so CI runs on the current base before the merge.
No other changes.

Claude-Session: https://claude.ai/code/session_01LrS7BTRTnc6eYrSxBFoWAo
@brentyates-swx
test(opencode): prove halt names the failed write's event, case and c…
3010fba 
…all site

Adds focused processor tests driving real lock failures into halt (#180):
- reasoning-end: the finishReasoning helper's message.part.updated commit
  meets a held lock; halt names the event, the case and a call-site chain
  running Session.updatePart < SessionProcessor.finishReasoning.
- step-finish: the message.updated write meets the lock instead, so the
  same case path reports a different event identity.
- a provider stream that dies after its handled cases succeed is attributed
  to the stream, with no invented event or case.

The held-lock fixture gains a trigger choosing which write takes the lock;
its default keeps the existing tests' reasoning-end behaviour.

The core nested-savepoint hold test now nests an immediate transaction long
enough to log on its own, and withTransaction drops a guard that was dead:
only the top-level COMMIT and ROLLBACK report a release.

Claude-Session: https://claude.ai/code/session_01QuyVZfg7zCF6ZJmDUf8BnB
@brentyates-swx
fix(core): omit an absent span from the lock-hold line
3e8dbb5 
A hold with no caller span printed span=undefined in the file log. The bun
stale-snapshot and BEGIN exhaustion tests now also pin the extended errno
bun reports (517 and 5), alongside its code.

Claude-Session: https://claude.ai/code/session_01QuyVZfg7zCF6ZJmDUf8BnB
@brentyates-swx
Merge origin/fm/opencode-lock-fix-162 at cebd89f (swxtch b18e7ff) int…
f51188c 
…o fm/opencode-stop-instrument-180

Claude-Session: https://claude.ai/code/session_01QuyVZfg7zCF6ZJmDUf8BnB
@brentyates-swx
docs: record the stop-instrument diagnostics in CHANGESET.md
7312e44 
Adds the fork entry under Runtime fixes now, so review covers its text. The PR
number does not exist until publication; script/changeset-check.ts keys the
entry on it and fails the PR until `#PR` is replaced with that number.

Claude-Session: https://claude.ai/code/session_01QuyVZfg7zCF6ZJmDUf8BnB
@brentyates-swx
Merge origin/swxtch at dcf2c1a (#194 landed) into fm/opencode-stop-in…
46cc805 
…strument-180

Claude-Session: https://claude.ai/code/session_01QuyVZfg7zCF6ZJmDUf8BnB

# Conflicts:
#	CHANGESET.md
#	packages/core/src/database/sqlite.bun.ts
#	packages/core/src/database/sqlite.node.ts
#	packages/effect-sqlite-node/src/index.ts
#	packages/effect-sqlite-node/src/retry.ts
@brentyates-swx
docs: say the stop-instrument entry follows #194, which has landed
1cdb1bd 
Claude-Session: https://claude.ai/code/session_01QuyVZfg7zCF6ZJmDUf8BnB
@brentyates-swx
fix(core): name an exhausted statement by its operation only
261a931 
Review round 1, required 1: the retry gate's summary logged the first three
SQL tokens, so a leading comment such as /* secret */ or a quoted identifier
reached the log and the operation itself could be lost. It now logs only the
leading keyword (and a BEGIN's deferred/immediate/exclusive), after skipping
leading comments and whitespace; nothing after the operation is read.
Returned errors and parameters are unchanged.

The new focused test runs real statements through the retry gate on held
production connections (leading block and line comments, a string literal,
a quoted identifier, mixed case and whitespace, a multi-statement string and
a bound parameter) and asserts each summary names its operation and none
contains the payload. The first hold test gets an explicit 20 s timeout like
its siblings.

Claude-Session: https://claude.ai/code/session_01QuyVZfg7zCF6ZJmDUf8BnB
@brentyates-swx
fix(core): take the stop call site from where the failure was raised
4bb7f87 
Review round 1, required 2: FailureOrigin read the observing fiber's span
after the failing scopes had unwound, so a provider-stream failure recorded
only SessionProcessor.process. It now reads the stack-frame chain the Effect
runtime annotates onto the cause where the failure is raised
(Cause.StackTrace), leaving out Effect.fn's definition-site frames, so the
call site names the failing callable across the stream and helper boundary.

The provider-stream halt test now fails inside a named callable and asserts
the call site starts with it; the held-lock tests pin their innermost frame
to Session.updatePart and Session.updateMessage.

Claude-Session: https://claude.ai/code/session_01QuyVZfg7zCF6ZJmDUf8BnB
@brentyates-swx
docs: record the stop-instrument entry as #201 in CHANGESET.md
b8c1bba 
Claude-Session: https://claude.ai/code/session_01QuyVZfg7zCF6ZJmDUf8BnB
@brentyates-swx
brentyates-swx merged commit 6870336 into swxtch Oct 10, 2026
3 checks passed
@brentyates-swx
brentyates-swx deleted the fm/opencode-stop-instrument-180 branch October 10, 2026 21:21
brentyates-swx added a commit that referenced this pull request Oct 11, 2026
@brentyates-swx
Merge origin/swxtch into fm/opencode-consume-recovery-167
b415b4a 
Brings in #161, #194 and #201 on top of the reviewed commit 95672df.

Conflicts, all resolved with the swxtch side:
- packages/core/src/database/sqlite.bun.ts
- packages/core/src/database/sqlite.node.ts
- packages/effect-sqlite-node/src/index.ts
- packages/effect-sqlite-node/src/retry.ts (add/add)
- CHANGESET.md

This branch carries the unsquashed #162 commits; swxtch carries the same
change squashed as #194. For each conflicted code file the reviewed side
is byte-identical to #194's version, so the conflict is only #201's edits
on top of #194, and the swxtch side keeps both. CHANGESET.md's only
conflict hunk is the #201 entry, which this branch never touched. The
branch's own changes (session/queue.ts, test/session/prompt.test.ts)
merged cleanly and are byte-identical to 95672df.

Claude-Session: https://claude.ai/code/session_019DxEchLHHdPjd4GUE1EJAj
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

No reviews

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

1 participant

@brentyates-swx