Repository navigation
Conversation
…version A version past State:Retention:ConfigurationVersions was deleted with secure_delete, but the log still held the page as it was written: the masked document, who applied it and their note stayed readable in state.db-wal until an unrelated prune or the last connection closed. Record now reads changes() after the cap's DELETE and empties the log when it removed a version, as the prune and the activity cap do. Refs #185
siebe41
left a comment
There was a problem hiding this comment.
Needs changes: the fix is correct and the test proves it, but a capped Record can now block the configuration apply for twice the busy timeout (about 10 s by default), and a failed checkpoint makes Record report a version that is not the saved one.
Findings
1. Medium: a capped Record blocks for twice the busy timeout while another connection is reading, inside the runtime lock
src/SemanticRouter.Storage.Sqlite/SqliteRouterState.cs:1601 (new database.EmptyLog(connection)), together with SqliteRouterDatabase.Execute at :555 and TruncateLog at :596.
PRAGMA wal_checkpoint(TRUNCATE) does not give up at once when a reader pins the log. It calls the busy handler, and every connection here sets busy_timeout to BusyTimeout (5 s). So the doc comment on TruncateLog ("SQLite gives up at once (it reports busy rather than waiting)") is wrong. When the checkpoint inside Record fails, EmptyLog sets _logOwed. Execute then sees _logOwed straight after the operation returns and tries again on the same call (settleLog: true), against the same reader, and waits a second busy timeout.
I measured this in a scratch worktree with a connection holding an open deferred read transaction on state.db, with the history at its cap:
- default
BusyTimeout(5 s): the thirdRecordtook 11.3 s; BusyTimeout= 1 s: 2.3 s for theRecord, then 1.2 s for the nextList()(the owed retry, while the reader was still open).
RouterRuntime calls Record under lock (_gate) (src/SemanticRouter.AspNetCore/Runtime/RouterRuntime.cs:317, :440, :460, and on first build at :153/:159 through RecordStartup). So once the history holds 200 versions (the default cap), every apply, revert and reset deletes one and checkpoints. Whenever another reader holds a snapshot (the tray and the background service sharing the file, a second router, a SQLite browser or backup tool left open), the admin API call, and anything else waiting for _gate, stalls for about 10 s. Before this PR, Record never checkpointed, so this is new on this path. The prune pays the same cost, but on its timer and outside the lock.
Fix: make the "without waiting" checkpoint not wait. For example, in TruncateLog, when wait == default, run the checkpoint with PRAGMA busy_timeout=0 and restore the timeout afterwards. In Execute, skip the settle retry when the operation itself just tried to empty the log and failed. A capped Record then costs one failed attempt (milliseconds), and the owed retry runs on a later operation, as the PR body describes. A test like the existing A_purge_says_so_when_a_reader_keeps_the_log_past_the_busy_timeout…, with a reader open during a capped Record and an assertion on the elapsed time, would pin this down.
2. Low: an exception from the checkpoint makes Record return the in-memory fallback's id for a version that is already saved
src/SemanticRouter.Storage.Sqlite/SqliteRouterState.cs:1601 and :1607.
EmptyLog runs inside the Run lambda after the INSERT has committed (each statement autocommits). A busy log is reported in the pragma's result row, but any other error, such as SQLITE_IOERR or SQLITE_FULL while writing or truncating, is thrown. Execute then catches it and returns the fallback -1, and Record records the same document a second time in _fallback and returns that in-memory id. RouterRuntime stores it as runtime.HistoryVersion, but List()/GetVersion() read the database, so the version number shown for the running configuration points at a different row or none. The prune can afford this (an exception there only loses its count); Record cannot.
Fix: catch SqliteException around this EmptyLog call (as the settle path in Execute already does) and leave _logOwed set, so the saved id is still returned.
3. Low (same gap, not touched by this PR): the audit log's age cap has the same problem
src/SemanticRouter.Storage.Sqlite/SqliteRouterState.cs:2096 (SqliteAuditLog.Append).
Append deletes audit rows past AuditDays in the same statement as the insert and never empties the log. The hourly prune then finds nothing to delete in audit, so it does not checkpoint for it either. This is the failure mode the PR body describes for configuration versions. I checked it with a probe: one audit entry, log truncated (so the row was in state.db), time moved past retention, then a second Append. The aged entry's actor was still readable in the database files afterwards. With secure_delete, the zeroed page goes to the log, and state.db keeps the old page until a checkpoint copies it over. On a quiet router that can be a long time. The PR says the #185 follow-through found one failing path; this one isn't covered by #331's tests (they cover audit retention only through the start-up prune). It belongs in this PR or a follow-up: check changes() there and empty the log, as this PR does for the history.
4. Nit: the changelog line ends with the issue number
CHANGELOG.md:145 ends with (#185), but #185 is the audit issue. CONTRIBUTING says to "end the line with the pull request number", and the neighbouring lines do (#241, #235, #238 are pull requests). Use (#332).
5. Nit: docs
docs/host.md:180 says the log "is truncated after each prune and purge". That still roughly covers the cap, but "and after the history cap drops a version" would make it exact. Separately, the TruncateLog doc comment at SqliteRouterState.cs:596 should be corrected (see finding 1), because the "no wait" design depends on it.
Checked and fine
- The checkpoint mode.
TRUNCATEcopies every frame intostate.dband truncatesstate.db-walto zero bytes, so the frames of the dropped version are gone from the log, including old frames past the current write position. With the probe, the log was 0 bytes after the cappedRecord. - The main database file.
secure_delete=ONis set on every connection (:780), so the deleted cell is zeroed in the page that the checkpoint writes back. Freed overflow pages are zeroed too. Probe: a 20 KB note (overflow pages), checkpointed intostate.dbfirst and then dropped by the cap. Neither its head nor its tail was in any of the three files afterwards.-shmholds only the index, and the test reads it too. changes(). In the multi-statement command it reports theDELETE's count, not theINSERT's. Probe: the log kept growing after the first and secondRecord(107 KB, then 128 KB, so no checkpoint ran) and was 0 bytes after the third, capped one. ARecordbelow the cap costs nothing extra. The reader is disposed beforeEmptyLogruns, so the connection holds no statement that would pin its own snapshot.- A reader holding the log. The pragma returns busy=1 (not an error),
TruncateLogchecks it, and_logOwedis set. Probe: the version was still in the files while the reader was open, and gone after the nextRunonce the reader had finished. So it does not fail silently, though it is slow (finding 1). - Pooling and other connections. Idle pooled connections hold no read lock, so they don't block the checkpoint. Another process's reader is handled by the owed path above. The background writer holding the write lock makes
TRUNCATEfall back to passive and report busy, with the same result. - Cost. One checkpoint per configuration change once the history is at its cap, which only happens on admin actions and start-up. That's negligible without a concurrent reader.
- Platforms. It uses the same pragma the prune and purge already run on Linux, Windows and macOS, and touches no paths or processes.
- The test. I reverted
src/SemanticRouter.Storage.Sqlite/SqliteRouterState.csto its #331 version in a scratch worktree:A_configuration_version_past_the_cap_leaves_the_files_toofailed andHistory_keeps_exact_documents_newest_first_and_is_cappedstill passed. With the fix, all 37SqliteStateTestspassed (including my probes). The test readsstate.db-wal,state.dbandstate.db-shmwhile the router's pooled connections are still open, so closing a connection can't empty the log and hide the bug. ItsSettle()does nothing here (Recordis synchronous), which is harmless. It does not cover the reader-held path for this caller (see finding 1 for a test that would). - PR body. Accurate about the change, the cause and the verification. "The router's next database operation empties it" holds for
Runoperations (notPeekor queued writes), the same as documented for the purge.
… empties the log too The checkpoint that empties the write-ahead log ran with the connection's busy timeout, so a capped configuration Record waited for another connection's reader, and Execute then retried at once against the same reader: about twice the busy timeout under the runtime's lock. The checkpoint now runs with busy_timeout 0 (a purge still polls up to its wait), and an operation that tried a checkpoint itself is not followed by the owed retry. A failed checkpoint after the history cap no longer turns a saved version into the in-memory fallback's id: the error leaves the checkpoint owed. Audit entries deleted past State:Retention:AuditDays when the next entry is written now empty the log as well, since the hourly prune finds nothing left to delete.
|
Review of 2026-10-22T07:15Z, addressed:
Verified: CI on 7c2d001: every check passes. (The Pages run 39821899368 concluded |
siebe41
left a comment
There was a problem hiding this comment.
Needs changes, small: all five earlier findings are fixed, and the two new tests fail without their production changes. One side effect remains. The zero busy timeout now applies to every checkpoint that doesn't wait, including the hourly prune, so a momentary read by the router itself now makes those checkpoints give up instead of waiting a few milliseconds.
Re-review of 7c2d001 (previous review at a3f20b2). CI on 7c2d001 is green on Linux, Windows and macOS.
Previous findings
- Medium: a capped
Recordblocked for twice the busy timeout, inside the runtime lock. Fixed.TruncateLog(src/SemanticRouter.Storage.Sqlite/SqliteRouterState.cs:606-648) reads the connection'sbusy_timeout, sets it to 0 for the checkpoint and restores it infinally. A purge still waits, now by polling every 20 ms. I checked that the new test catches it: in a scratch worktree I turnedPRAGMA busy_timeout=0;into a no-op, andA_capped_version_does_not_wait_for_a_reader_and_leaves_the_files_once_it_has_finishedfailed ("found 11s, 99ms"; limit 2.5 s). With the change, it took 56 ms. - Low: a checkpoint exception turned a saved version into the fallback's id. Fixed.
EmptyLogAfterDelete(:675) catchesSqliteException, andEmptyLog(:654) sets_logOwedbefore rethrowing, soRecordreturns the saved id. No test covers it, as the PR's "Not done" says. That is acceptable for acatch. - Low: the audit log's age cap had the same gap. Fixed.
SqliteAuditLog.Append(:2150-2163) readschanges()after itsDELETEand callsEmptyLogAfterDelete. When I removed that call in a scratch worktree,An_audit_entry_past_retention_leaves_the_files_when_the_next_one_is_writtenfailed. I also checked with a probe thatchanges()is theDELETE's count: the log grew from 111,272 to 123,632 bytes over twoAppends inside retention (no checkpoint), and dropped to 0 bytes after theAppendthat deleted an aged entry. - Nit: the changelog ended with the issue number. Fixed:
CHANGELOG.md:145ends with(#332). Its new last sentence is covered by new finding 3 below. - Nit: docs. Fixed.
docs/host.md:180names the history cap and the audit age limit. TheTruncateLogdoc comment now describes the busy timeout correctly.
New findings
1. Low: the zero busy timeout also makes the hourly prune's checkpoint give up on any momentary read
src/SemanticRouter.Storage.Sqlite/SqliteRouterState.cs:614 (PRAGMA busy_timeout=0), reached with wait == default from Prune (:258), from the writer thread after the activity and feedback caps (:1338, :1514), and from Record/Append (:1656, :2163).
The earlier review asked for Record to stop waiting because it runs under the runtime lock. The change applies to every checkpoint that doesn't wait. So wal_checkpoint(TRUNCATE) now reports busy at once whenever any connection is in a read or write at that instant, including this router's own request-path reads (Peek: cooldowns, affinity, warm caches, usage totals) and its background writer. Before, SQLite's busy handler waited the milliseconds those take, and the checkpoint went through.
I measured it with a probe: a second connection holds a read for 300 ms while the operation runs.
| a3f20b2 | 7c2d001 | |
|---|---|---|
Capped Record |
363 ms, log 0 bytes, dropped version gone | 4 ms, log 164,832 bytes, dropped version still in the files |
Prune() deleting an aged audit entry |
349 ms, log 0 bytes, entry gone | 2 ms, log 127,752 bytes, entry still in the files |
Nothing is lost: _logOwed is set, and the next Run operation retries. But the request path uses only Peek and queued writes, so on a router whose dashboard nobody opens, the next Run can be the next hourly prune. A deleted row can now stay in state.db-wal for another hour in cases where the prune used to clear it. The timer prune (:129) runs outside the runtime lock and had no reason to stop waiting.
Fix: keep a short bounded wait for the default case instead of zero. For example, EmptyLog could poll for about 250 ms (still well under the lock budget the new test enforces, and it covers the router's own short reads), or the timer prune could pass Options.BusyTimeout. A probe like the one above, with a reader held for less than the wait, would pin it down.
2. Nit: _logAttempts is redundant now, and no test covers it
SqliteRouterState.cs:95, :557, :561, :656.
With the busy timeout at 0, a settle retry straight after a failed checkpoint costs one more failed attempt of a few milliseconds, not a second wait. In a scratch worktree I removed the Volatile.Read(ref _logAttempts) == attempts condition, and all 46 SqliteStateTests, DurableState* and privacy tests still passed. The counter is also global, so a checkpoint on another thread (the writer's :1514) makes an unrelated Run skip its settle. That is harmless, but the comment at :560 ("the operation has just tried itself") doesn't say so. Either drop the counter or note that it is only an optimisation.
3. Nit: the changelog's last sentence describes a change users never had
CHANGELOG.md:145: "The checkpoint does not wait for another program reading the file, so applying a configuration is not held up; it is made after the router's next database operation instead."
The wait it refers to was added and removed inside this PR (a3f20b2 was never released), so there is nothing user-visible to compare against. CONTRIBUTING asks for "what changed for the user, not how". The sentence is also inexact: the checkpoint doesn't wait for this router's own reads either, and it runs on the next admin or dashboard operation (or the next prune) once the reader has finished, not on any operation. Suggest dropping the sentence. docs/host.md:182 already covers the reader case for purges.
4. Nit: the reader test doesn't check that the reader held the log
tests/SemanticRouter.Tests/AspNetCore/SqliteStateTests.cs:493-520. The timing assertion would pass just as well if the reader's snapshot didn't pin the log (for example, if a later refactor of the setup stopped the read transaction from starting). It does pin it today: the reverted run took 11 s. One assertion inside the using block would make the test check its own setup: that ReadDatabaseFiles still contains 7c4a, or that state.db-wal is not empty.
Checked and fine
- Restoring the busy timeout.
PRAGMA busy_timeoutreturns the value set inOpen()(:837). The restore infinallymatters becauseOpen()sets the pragmas only once per pooled handle. If the checkpoint throws, the restore still runs. - The checkpoint result. A busy log comes back as a row with busy=1, not as
SQLITE_BUSYfrom the step. So Microsoft.Data.Sqlite's own 150 ms retry loop (DefaultTimeout) does not apply, and the zero timeout really does return at once. - Purge. It still waits up to
BusyTimeoutby polling.A_purge_says_so_when_a_reader_keeps_the_log…andA_purge_empties_the_log_once_a_reader_that_held_it_has_finishedpass.docs/host.md:182is still accurate. - Platforms. The change uses the same pragmas on every OS and touches no paths. CI passes on Linux, Windows and macOS.
- Tests at head. All 36
SqliteStateTestspassed locally, plus my three probes.
Stacked on #331 (the #185 privacy tests). Merge that first, or retarget this one to main.
What changed
SqliteConfigurationHistory.Record(src/SemanticRouter.Storage.Sqlite/SqliteRouterState.cs): the insert that caps the history atState:Retention:ConfigurationVersionsnow also readschanges()after itsDELETE. When the cap removed a version, it empties the write-ahead log (EmptyLog), as the prune and the activity cap already do. If another reader holds the log,EmptyLogmarks it as owed, and the router's next database operation empties it.TruncateLogruns it withbusy_timeout=0(a purge still polls for up to its wait), andExecutedoes not retry an owed checkpoint against the same reader when the operation has just tried one. Before this, a cappedRecordunder the runtime's lock waited about twice the busy timeout (10 s by default). A checkpoint error after the cap leaves the checkpoint owed instead of turning the saved version into the in-memory fallback's id (EmptyLogAfterDelete).SqliteAuditLog.Append, which deletes entries pastState:Retention:AuditDayswhen it writes a new one, now empties the log when it deleted something. It had the same gap (the hourly prune then finds nothing left to delete). TestsA_capped_version_does_not_wait_for_a_reader_and_leaves_the_files_once_it_has_finishedandAn_audit_entry_past_retention_leaves_the_files_when_the_next_one_is_written.SqliteStateTests.A_configuration_version_past_the_cap_leaves_the_files_too: cap 2, three versions, then the oldest one's actor and note must be in none ofstate.db,-waland-shm.Why
The privacy follow-through for #185 checks every path that deletes data against the raw database files. One failed: a configuration version dropped by the history cap stayed readable in
state.db-wal, with the masked document, who applied it and their note.secure_deletezeroes the deleted row in the database page, but the log still holds the page as it was written. The hourly prune empties the log only when it deletes something itself, and by then the cap has already removed the row. So the old version stayed in the log until an unrelated prune, a checkpoint that happened to overwrite those frames, or the last connection closing.How it was verified
src/and running it:Failed: 1), and passes with it.SqliteStateTests+DurableStateHostTests: 44/44.dotnet build -c Release: 0 warnings, 0 errors.dotnet format --verify-no-changes: clean.dotnet test -c Release(full suite, includes the stacked test PR): 1466/1467 passed. The one failure,SecretsTests.Literal_secrets_move_to_the_store_and_resolve_back, is caused by the environment: this PC hasOPENAI_API_KEYset, and the test passes withenv -u OPENAI_API_KEY.dotnet pack -c Release(package validation against 0.5.0): clean:SemanticRouter.Storage.Sqlite0.6.0 packs with no package-validation warning.Other platforms. This is a SQLite statement and a
wal_checkpoint(TRUNCATE), both already used by the prune on every OS. Nothing in it touches paths or processes.src/change (the cappedRecordtook 16.7 s against the test's 2.5 s limit, and the aged audit actor stayed in the files) and pass with it.SqliteStateTests+DurableState*+ privacy tests: 46/46. Full suite 1467/1469: theOPENAI_API_KEYSecretsTests failure above, andServiceTests.The_router_records_itself_while_it_runs…(Stop only the Windows router a record names, which ends a Windows test flake (#225) #335's flake), which passes alone. Build 0 warnings, format and pack clean.Not done
SQLITE_IOERR/SQLITE_FULLmid-checkpoint); the change is acatchthat leaves the checkpoint owed.The two documented behaviours listed in the test PR's "Decisions for Andrew" (learned-change examples outliving activity retention, and the pre-migration
.bakcopy surviving a purge).Refs #185