Skip to content

fix(db): report checkpoint failure instead of a false "completed" on WAL TRUNCATE busy - #12998

Closed
hartmark wants to merge 1 commit into
diegosouzapw:release/v3.8.51from
hartmark:fix/wal-checkpoint-busy-detection
Closed

hartmark wants to merge 1 commit into
diegosouzapw:release/v3.8.51from
hartmark:fix/wal-checkpoint-busy-detection

Conversation

@hartmark

@hartmark hartmark commented Sep 8, 2026

Copy link
Copy Markdown
Contributor

What Problem This Solves

The 11 GB live database's WAL file had grown to 11.7 GB -- nearly as
large as the database it shadows -- and stayed that way across restarts
despite an existing periodic wal_checkpoint(TRUNCATE) scheduler
(startWalTruncateScheduler, every 6h) whose own logs claimed success the
entire time. On the next restart, an unrelated startup VACUUM over the
now-huge database blocked all HTTP traffic for ~15-20 minutes (better-sqlite3's
VACUUM is synchronous and blocks Node's single thread).

Root Cause

checkpointDb() called the wal_checkpoint(mode) pragma and unconditionally
returned true, ignoring the {busy, log, checkpointed} row SQLite always
returns
(docs). busy != 0
means SQLite could not get the lock this mode needs -- for TRUNCATE, full
exclusivity: any other open connection, reader or not, blocks it -- and the
WAL file was not shrunk, no matter how many frames checkpointed reports.

Both callers therefore always logged success:

  • The periodic scheduler printed "[DB] Periodic SQLite WAL checkpoint completed (TRUNCATE)." every tick, even when the checkpoint silently
    no-oped.
  • closeDbInstance() did the same on shutdown.

On a server that is rarely fully idle (this one runs continuous
SSE/embedding/batch traffic on a single long-lived connection), TRUNCATE
may never actually get the exclusive lock it needs within a given tick, so
the WAL just grows monotonically -- with the logs claiming success the whole
time, so nobody could tell from the logs alone that anything was wrong.

I verified this empirically before writing the fix: opening a second
connection with an uncommitted read transaction on a real WAL-mode SQLite
file reliably reproduces busy: 1 and a non-truncated WAL file; committing
that transaction (even without closing the connection) reliably reproduces
busy: 0 and truncation to zero bytes.

Fix

checkpointDb() now reads the pragma's own busy field and only reports
success when busy === 0. Both call sites now log the deferred/no-op case
too (previously silent), so a WAL that never finds an idle moment is visible
in the logs instead of looking identical to a healthy server.

This does not change the checkpoint cadence or add any new configuration --
it fixes the return value so the existing logging is truthful.

Evidence

New regression test opens a real WAL-mode SQLite file, holds it busy from a
second connection with an open read transaction (reproducing the exact
"server never fully idle" condition that hid this bug in production), and
asserts checkpointDb() correctly reports false while busy and true
once the lock becomes available.

$ node --test tests/unit/db-wal-checkpoint-busy-detection.test.ts
✔ checkpointDb reports failure (not success) when TRUNCATE cannot get the lock it needs
✔ checkpointDb reports success once TRUNCATE actually gets exclusivity
tests 2, pass 2, fail 0

$ node --test tests/unit/db-wal-truncate-scheduler.test.ts   # pre-existing, unmodified
tests 6, pass 6, fail 0

$ node --test tests/unit/db-core-extended.test.ts tests/unit/db-core-init.test.ts \
    tests/unit/db-reset-module-state.test.ts tests/unit/graceful-shutdown-sighup-8045.test.ts
tests 44, pass 44, fail 0
  • eslint on both touched files: clean (3 pre-existing, unrelated unused-var
    errors in core.ts confirmed present on unmodified release/v3.8.51 too --
    not touched by this PR)
  • tsc --noEmit: no errors in touched files

…WAL TRUNCATE busy

checkpointDb() called `wal_checkpoint(mode)` and unconditionally returned
true, ignoring the {busy, log, checkpointed} row the pragma always returns
(https://www.sqlite.org/pragma.html#pragma_wal_checkpoint). busy != 0 means
SQLite could not get the lock TRUNCATE needs (full exclusivity -- any other
open connection, reader or not, blocks it), and the WAL file was NOT
shrunk, no matter how many frames "checkpointed" reports.

Both callers logged success unconditionally as a result:

- The periodic scheduler (startWalTruncateScheduler, every 6h by default)
  always printed "[DB] Periodic SQLite WAL checkpoint completed (TRUNCATE)."
  even when the checkpoint silently no-oped.
- closeDbInstance() did the same on shutdown.

On a server that is rarely fully idle (continuous SSE/embedding/batch
traffic keeps a connection open), TRUNCATE may never actually get the lock
it needs, so the WAL just grows monotonically -- with the logs claiming
success the entire time. Observed live: an 11.7 GB WAL file, nearly as
large as the 11 GB main database it shadows, which then blocked all HTTP
traffic for ~15-20 minutes on the next restart while an unrelated startup
VACUUM churned through the bloated database.

Fix: checkpointDb() now reads the pragma's own busy field and only reports
success when busy === 0. Both call sites now log the deferred/no-op case
too (previously silent), so a WAL that never finds an idle moment is
visible in the logs instead of looking identical to a healthy server.

Regression test (tests/unit/db-wal-checkpoint-busy-detection.test.ts) opens
a real WAL-mode SQLite file, holds it busy from a second connection with an
open read transaction, and asserts checkpointDb() correctly reports false
while busy and true once the lock is available -- reproducing the same
busy=1 SQLite returns in production, empirically verified locally before
writing the fix.

Evidence:
- node --test tests/unit/db-wal-checkpoint-busy-detection.test.ts: 2/2 pass
- node --test tests/unit/db-wal-truncate-scheduler.test.ts (pre-existing,
  unmodified): 6/6 pass
- node --test tests/unit/db-core-extended.test.ts tests/unit/db-core-init.test.ts
  tests/unit/db-reset-module-state.test.ts tests/unit/graceful-shutdown-sighup-8045.test.ts:
  44/44 pass (unaffected)
- eslint on both touched files: clean (3 pre-existing unrelated errors in
  core.ts confirmed present on unmodified release/v3.8.51 too, not touched)
- tsc --noEmit: no errors in touched files

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
@hartmark
hartmark marked this pull request as ready for review September 8, 2026 00:46
hartmark added a commit to hartmark/OmniRoute that referenced this pull request Sep 8, 2026
…ad of a false "completed" on WAL TRUNCATE busy) into dev/omniroute-dev-combined
@hartmark

hartmark commented Sep 8, 2026

Copy link
Copy Markdown
Contributor Author

Superseded by #12853 (merged 2026-09-08T12:29:42Z), which fixes the exact same root cause -- wal_checkpoint()'s busy field being ignored so TRUNCATE always logged "completed" even when it silently no-oped -- with a more complete implementation: it extracts the scheduler into its own walMaintenance.ts, adds a structured WalCheckpointOutcome, tracks a busy streak, and schedules a PASSIVE retry on busy instead of just waiting for the next full-interval tick. It also covers closeDbInstance()'s own checkpoint call the same way this PR did.

Verified #12853's walMaintenance.ts on current release/v3.8.51: runCheckpointNow() parses {busy, log, checkpointed} from the pragma result and only reports ok when busy !== 1, matching this PR's core fix, then goes further with the retry/streak logic. Closing this one in favor of the already-landed, more thorough fix.

Thanks @maxmad64bis for landing #12853.

@hartmark hartmark closed this Sep 8, 2026
@hartmark
hartmark deleted the fix/wal-checkpoint-busy-detection branch September 8, 2026 20:10
diegosouzapw added a commit that referenced this pull request Sep 17, 2026
…-09-15) (#13731)

Second `npm run release:reconcile` pass on `release/v3.8.50..release/v3.8.51`
(0915890..c0f92ec, 916 non-merge commits, 877 merged PRs):

- fold the 173 changelog.d fragments accumulated since #12971 under
  `## [3.8.51]` and delete them
- generate bullets for the 58 cycle commits that had no fragment
  (4 features / 42 fixes / 12 maintenance), each with the merged PR link and
  `— thanks @author`
- link 137 fragment bullets to the PR of the commit that added them and
  credit the author; two prefix/origin mismatches reviewed (#12945→#13392,
  #13001→#13379, both maintainer rebaselines of other people's PRs)
- refresh "Release by the numbers" + Top-25 and regenerate the
  `### 🙌 Contributors` hall (112 external contributors + maintainer; every
  non-bot author of the 877 merged PRs present)
- closed-PR credit audit for the window: nothing to add (#13215→#13361 and
  #13059→#13690 are still open, #12998 was independently fixed earlier by
  #12853); no human co-author trailers, no commits without a PR
- resync the 58 i18n CHANGELOG mirrors

Gates: check:changelog-integrity OK, check:docs-sync PASS.
muhamadgalihsaputra pushed a commit to niyatna/NiyatnaRoute that referenced this pull request Sep 27, 2026
…-09-15) (diegosouzapw#13731)

Second `npm run release:reconcile` pass on `release/v3.8.50..release/v3.8.51`
(104d4f8..d61b804, 916 non-merge commits, 877 merged PRs):

- fold the 173 changelog.d fragments accumulated since diegosouzapw#12971 under
  `## [3.8.51]` and delete them
- generate bullets for the 58 cycle commits that had no fragment
  (4 features / 42 fixes / 12 maintenance), each with the merged PR link and
  `— thanks @author`
- link 137 fragment bullets to the PR of the commit that added them and
  credit the author; two prefix/origin mismatches reviewed (diegosouzapw#12945→diegosouzapw#13392,
  diegosouzapw#13001→diegosouzapw#13379, both maintainer rebaselines of other people's PRs)
- refresh "Release by the numbers" + Top-25 and regenerate the
  `### 🙌 Contributors` hall (112 external contributors + maintainer; every
  non-bot author of the 877 merged PRs present)
- closed-PR credit audit for the window: nothing to add (diegosouzapw#13215→diegosouzapw#13361 and
  diegosouzapw#13059→diegosouzapw#13690 are still open, diegosouzapw#12998 was independently fixed earlier by
  diegosouzapw#12853); no human co-author trailers, no commits without a PR
- resync the 58 i18n CHANGELOG mirrors

Gates: check:changelog-integrity OK, check:docs-sync PASS.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant