fix(txnlog): recover the committed watermark from the log tail on load - #723
fix(txnlog): recover the committed watermark from the log tail on load#723kriszyp wants to merge 23 commits into
Conversation
![gemini-code-assist[bot]](https://avatars.githubusercontent.com/in/956858?s=60&v=4){kind=small}
There was a problem hiding this comment.
Code Review
This pull request fixes an issue where transaction log entries written after the last flush were invisible to committed reads after an unclean exit. It seeds the in-memory committed watermark at the recovered write head during store loading and adds comprehensive crash recovery tests. The feedback suggests replacing the fragile fullPosition > 0 check with a safer check on logSequenceNumber > 0 to avoid potential issues with union-based double comparisons.
📊 Benchmark Resultsget-sync.bench.tsgetSync() > random keys - small key size (100 records)
getSync() > sequential keys - small key size (100 records)
ranges.bench.tsgetRange() > small range (100 records, 50 range)
realistic-load.bench.tsRealistic write load with workers > write variable records with transaction log
transaction-log.bench.tsTransaction log > read 100 iterators while write log with 100 byte records
Transaction log > read one entry from random position from log with 1000 100 byte records
worker-put-sync.bench.tsputSync() > random keys - small key size (100 records, 10 workers)
worker-transaction-log.bench.tsTransaction log with workers > write log with 100 byte records
Results from commit 12d0215 |
findPositionByTimestamp()'s indexing loop checked `entryTimestamp == 0` before checking whether the current position was the file header's timestamp slot. A header timestamp of exactly 0 (e.g. an unset/epoch value, as several test fixtures write) was therefore treated as the zero-padding end-of-data marker and truncated this->size back into the header itself -- below TRANSACTION_LOG_FILE_HEADER_SIZE. This is normally invisible: only TransactionLogFile::openFile() on Windows proactively calls findPositionByTimestamp() at open time (to correct for mmap zero-padding), so the corruption only ever surfaced there. It stayed latent until 13d57f7/f385ace8 started seeding lastCommittedPosition from the recovered nextLogPosition on load, which propagated the corrupted size into a value CI asserts on -- failing every Windows runtime (Node 22/24/26, Bun, Deno) on PR #723's new/pre-existing "should return valid lastCommittedPosition after purging earlier log files and reopening" case. Root cause: the header-timestamp branch and the end-of-data check were ordered so the latter could fire on a position that isn't an entry. Reordering to always handle the header slot first (as the timestamp index's designated position-0 entry) restores the invariant that the end-of-data heuristic only ever applies to real entries. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
|
I will note that 24b12b9 significantly expands this PR to more carefully avoid a partial transaction, but if you prefer it to be separated into a different PR, happy to do so. |
|
Pushed The reason for the follow-up: seeding the watermark at the last complete transaction is only true until the next commit. The bytes stayed in the file, the first Dropping the bytes is safe because The gating is the part most worth your eye: the last-entry flag only landed in One intentional behavior change: a 660 vitest / 51 files and 110 native gtests locally; the new end-to-end test fails without the source change ( — Claude Opus 5 |
…rtial failure Zero the end-of-entries marker at `newSize` with its own write before the bulk zeroing loop. A reader stops at the first zero timestamp regardless of what follows, so once that write lands, `newSize` is a safe end-of-log position even if a later chunk fails partway through the rest of the range — the caller can lower `size` to `newSize` unconditionally instead of leaving it at `entriesEnd` while the on-disk marker already sits earlier, which would put the next append past where readers stop. Addresses PR #723 review feedback from cb1kenobi. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
|
Re cb1kenobi's Windows
— KrAIs (Claude Sonnet 5) |
|
Fixed the Windows recovery-test failure in 05e2001. The test now validates the platform-specific recovery contract: POSIX physically truncates to the last complete transaction, while Windows preserves the crash-time file length and zeroes the discarded range. Both paths also assert the parser's logical end is the completed-transaction boundary. Local verification: |
Follow-up thought: the whole-file-read-then-scan patternReally clean recovery work here — the committed-watermark seed walk and the While reading through it, one efficiency pattern stood out that's worth capturing. It's mostly not blocking this PR — only the first row below is new here — but the new code follows an existing shape that's worth a second look. Several spots allocate the entire file and read every byte, then hand the buffer to a scan that only ever touches the 13-byte entry headers and skips the bodies (
SuggestionSwap the byte source, keep the framing logic byte-identical: a bounded reader that Since the scanners already take Wrinkles worth knowing before committing to it
PriorityGenuinely low for the recovery sites — they're cold, once-at-open, bounded by rotation size. The strongest case is Net: the whole-file read in the new — Generated by Claude Opus 4.8 |
The transaction log's committed watermark (lastCommittedPosition) is in-memory state advanced by commitFinished(); it is never persisted. It was seeded on load from txn.state -- the *flushed* position, i.e. how far RocksDB has already absorbed the log -- which after an unclean exit sits behind the log's recovered tail. Every committed read is bounded by that watermark, so entries that were durable on disk (and that a consumer's boot replay re-applies via readUncommitted) stayed invisible to committed readers until an unrelated later commit advanced the watermark past the whole tail at once. load() already recovers the true end: recoverTail() truncates any torn tail, nextLogPosition is set to the last structurally valid entry, and it is inserted as the write-head sentinel. commitFinished() defines the watermark as the front of uncommittedTransactionPositions, which in a freshly loaded store is exactly nextLogPosition -- so seeding it there only makes load() agree with the rule the store already enforces. Fixes HarperFast/harper#1949 Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Cross-model review findings: the fixture's `ready` handshake went through an async console.log to a pipe, which the following SIGKILL could drop; a self-kill on Windows surfaces as exit code 1, not a signal. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
findPositionByTimestamp()'s indexing loop checked `entryTimestamp == 0` before checking whether the current position was the file header's timestamp slot. A header timestamp of exactly 0 (e.g. an unset/epoch value, as several test fixtures write) was therefore treated as the zero-padding end-of-data marker and truncated this->size back into the header itself -- below TRANSACTION_LOG_FILE_HEADER_SIZE. This is normally invisible: only TransactionLogFile::openFile() on Windows proactively calls findPositionByTimestamp() at open time (to correct for mmap zero-padding), so the corruption only ever surfaced there. It stayed latent until 13d57f7/f385ace8 started seeding lastCommittedPosition from the recovered nextLogPosition on load, which propagated the corrupted size into a value CI asserts on -- failing every Windows runtime (Node 22/24/26, Bun, Deno) on PR #723's new/pre-existing "should return valid lastCommittedPosition after purging earlier log files and reopening" case. Root cause: the header-timestamp branch and the end-of-data check were ordered so the latter could fire on a position that isn't an entry. Reordering to always handle the header slot first (as the timestamp index's designated position-0 entry) restores the invariant that the end-of-data heuristic only ever applies to real entries. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Adds the regression test for b10e725. The indexing path is cross-platform even though only Windows openFile() reaches it at open, so the test drives it directly through _findPosition and fails without that fix on any platform. Also tests the committed-watermark seed on logSequenceNumber rather than fullPosition: that union member aliases the two uint32s as a double, so a sequence number >= 0x7ff00000 reads back as NaN or negative and `> 0` would silently skip the seed, falling back to the stale txn.state position this PR exists to fix. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Windows has no real signals, so Node maps a self-kill to TerminateProcess(h, 1). Accepting code 1 on every platform would let a POSIX run whose kill() threw after the `ready` handshake pass with normal addon teardown, which is the very thing the fixture must rule out. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…ction Only a batch's final entry carries TRANSACTION_LOG_ENTRY_LAST_FLAG, so a crash partway through a multi-entry transaction leaves whole, well-framed entries that are merely a prefix of it. recoverTail() deliberately keeps those bytes -- they are structurally valid and a readUncommitted replay still wants them -- but seeding the committed watermark at the write head published them to committed readers, exposing a transaction that never closed. The next transaction's flag would then close the phantom group, so replication could see two source transactions merged into one. The scan now reports the offset just past the last flagged entry alongside validEnd, computed in the same walk, and load() seeds there instead. Because writeBatch() writes a batch across multiple log files when it crosses a rotation, the prefix can span files, so the seed walks back through older sequences until one ends on a real transaction boundary. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Seeding the committed watermark at the last complete transaction keeps a crash mid-batch out of committed reads, but only until the next commit: the leftover entries stay in the file, the watermark jumps past them on the first commitFinished(), and the next batch's TRANSACTION_LOG_ENTRY_LAST_FLAG then closes the phantom group -- the same two-transactions-merged-into-one exposure, one commit later. recoverTail() now drops those entries so the file itself ends on a transaction boundary. Nothing durable depends on them: writeBatch() completes before Transaction::Commit() in every commit path and both commit-thread lanes preserve dispatch order, so an interrupted log write is always the newest thing in the log and its RocksDB commit never ran. The discard is gated on proof that it is one interrupted batch of a flag-setting writer -- a boundary earlier in the same file, plus a single timestamp across the trailing run (writeEntriesV1 stamps every entry of a batch with the batch timestamp, and getMonotonicTimestamp() never repeats). Without that proof the bytes are kept and warned about, which is what protects a batch split across a rotation and a log written before the flag existed; the watermark seed still covers committed readers there. POSIX truncates. Windows overwrites the range with zeros -- its files are pre-extended and a zero timestamp is the end-of-entries marker, so a torn tail needs no repair there but real entries do -- and drops the cached read-only mapping, which is not coherent with WriteFile. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
…rtial failure Zero the end-of-entries marker at `newSize` with its own write before the bulk zeroing loop. A reader stops at the first zero timestamp regardless of what follows, so once that write lands, `newSize` is a safe end-of-log position even if a later chunk fails partway through the rest of the range — the caller can lower `size` to `newSize` unconditionally instead of leaving it at `entriesEnd` while the on-disk marker already sits earlier, which would put the next append past where readers stop. Addresses PR #723 review feedback from cb1kenobi. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Co-Authored-By: GPT-5 Codex <noreply@openai.com>
9676862 to
cea3330
Compare
Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Co-Authored-By: GPT-5 Codex <noreply@openai.com>
…uffer The recovery walk only needs 13-byte entry headers. Slurping payloads was leftover from the validation-oriented scanner. I/O failure now fails open rather than being classified as a torn tail. Co-authored-by: Cursor <cursoragent@cursor.com>
A 13-byte pread per entry regresses dense-log cold opens; a 64 KiB refill at every header would pull large payloads. Nearby sequential headers share a window, and a jump past it reads exactly one header. Co-authored-by: Cursor <cursoragent@cursor.com>
The first header is a 13-byte read, so a 13-byte nearby slack never engaged the window for real payload sizes. Treat a gap up to the window size as sequential so typical entries amortize without slurping megabyte payloads. Co-authored-by: Cursor <cursoragent@cursor.com>
The old name implied a whole-file slurp. The helper only fills n bytes at an offset, retrying short reads. Co-authored-by: Cursor <cursoragent@cursor.com>
2 participants
Fixes HarperFast/harper#1949 — Crash recovery restores records but not the transaction log's committed watermark, silently stranding them from replication.
The defect
After an unclean exit (crash, OOM kill, container kill), transaction-log entries that are durable on disk are invisible to every committed read — replication's resume replay and
read_transaction_log— until some unrelated later commit happens to advance the watermark past the whole stale tail. A peer that resumes replication after the crash never receives writes that were already acknowledged and durable before it.The two positions involved are easy to conflate, so, precisely:
lastCommittedPositionis in-memory only and is never persisted.commitFinished()/commitAborted()advance it to "front ofuncommittedTransactionPositions, elsenextLogPosition". It is what bounds committed reads (loadLastPosition()intransaction-log-reader.ts).lastFlushedPositionlives intxn.stateand is written bydatabaseFlushed()— the RocksDBOnFlushCompletedcallback, so on every memtable flush. It means "the log up to here is already in SSTs", and it bounds replay (startFromLastFlushed) and purge eligibility.The link is the bug:
getLastCommittedPosition()lazily seeded the in-memory watermark fromtxn.stateon first use. A graceful shutdown looks clean only becauseshutdown()forces a final flush, which writestxn.stateat the true end of log — nothing ever persists the committed watermark itself. After a crash,txn.statesits at the last periodic flush, so the watermark is seeded behind the recovered tail and stays there: the consumer's boot replay re-applies the tail withreadUncommitted, and those replayed writes deliberately don't re-append to the log (that would prevent replay convergence), socommitFinished()never runs and the watermark never moves.The fix
load()now seeds the watermark from the last entry that closed a transaction, using the active recovery scan and walking backward through rotated files until it finds a boundary or reaches thetxn.statefloor. The persistedtxn.stateflushed position is a safe floor, so recovery never hides entries already absorbed by RocksDB. Older-file probing is bounded, exception-safe, and closes files opened only for the scan. Active-file repair readstxn.statefirst and refuses to truncate below its same-file flushed offset, so a missing flag cannot erase history RocksDB already absorbed.A store with no log files still leaves the position at
{0, 0}for the existing lazy path to resolve.Tests
test/transaction-log-crash-recovery.test.ts(+ a SIGKILL fixture). Both fail onmainand pass here:Also strengthened the two existing tail-recovery tests in
transaction-log.test.ts. One carried the comment "the committed position isn't persisted without a RocksDB flush, so read uncommitted to verify the entries survived on disk" — this bug written down as an accepted workaround.Local: 764 vitest passed / 56 files (2 skipped), 117 native gtests passed, production build and
pnpm checkpassed.Worth a reviewer's attention
Complete-but-uncommitted tail entries are now visible to committed readers. The log entry is appended before the RocksDB commit, and
recoverTail()only strips torn tails, so a crash can leave a structurally complete entry whose data commit never landed — the seed exposes it. Two things make that the right behavior rather than a new hazard:commitAborted()already produces at runtime: when a batch was written but the commit failed,TransactionHandle::close()calls it and the watermark advances past those bytes.replayLogs()runs synchronously insidereadRocksMetaDb()immediately after the database is opened and before the root store is returned, so no committed reader can observe the tail before replay has applied it.The residual case is a replay that aborts early — Harper bounds replay on a no-progress counter (harper#1266) and a wall-clock limit (harper#1316). There the watermark advertises a tail the database doesn't fully have. Both abort paths already log
fatalwith "re-clone this node", so this seemed acceptable rather than worth gating the advance on replay completion, but it is a deliberate call and worth a second opinion.Recovery ends the log on a transaction boundary
Only a batch's final entry carries
TRANSACTION_LOG_ENTRY_LAST_FLAG, so a crash partway through a multi-entry transaction leaves whole, well-framed entries that are merely a prefix of it. Left alone, the next transaction's flag closes the phantom group, merging two source transactions into one over replication. The PR closes that two ways, because either alone is incomplete:nextLogPosition.scanTransactionLogForRecovery()reports that boundary alongsidevalidEndfrom the same walk, so open-time recovery gets it without a second pass.recoverTail()discards the leftover entries (discardUnclosedTransaction), so the file itself ends on a boundary. Seeding alone only holds until the next commit: the bytes stay on disk, the firstcommitFinished()after boot advances the watermark past them, and the merge happens then — one commit later rather than never.Discarding is safe because nothing durable depends on those bytes.
writeBatch()completes beforeTransaction::Commit()in every commit path (transaction.cpp:236/286async,701/710sync) and both commit-thread lanes preserve dispatch order, so an interrupted log write is always the newest thing in the log and its RocksDB commit never ran.The discard is gated, deliberately. The last-entry flag only landed in
a69528c1(2025-12-02); a log written before that has no flagged entries at all, and a naive "truncate to the last flagged entry" would wipe the whole file. So it requires both:writeEntriesV1()stamps every entry of a batch with the batch timestamp while a prior flagged boundary prevents conflating separate transactions even if a caller reuses a timestamp, so more than one timestamp means more than one transaction went unflagged, which a flag-setting writer cannot produce.Without that proof the bytes are kept and a warning is emitted. That is also what covers a batch
writeBatch()split across a rotation (no flagged entry in the active file), which is why (1) is still needed: there the seed walks backward across every unflagged rotation until it finds a boundary or reaches thetxn.statefloor.Both platforms physically truncate every torn tail the framing scan can identify. Windows drops its cached mapping before
SetEndOfFile, uses the same path for torn and unclosed tails, and resets the timestamp index after either recovery shrink. A durable header followed by a partial payload remains indistinguishable from a valid zero-ending payload on a pre-extended Windows file; detecting that case requires an entry checksum.Behavior change worth noting: a
readUncommittedreplay no longer sees the interrupted batch's prefix. That is intentional and arguably a second fix — Harper'sreplayLogs()currently applies those entries, i.e. writes a partial transaction into the database.Covered by 13 GoogleTests on the pure scan (framing boundary + the unclosed-tail description that gates the discard) and two end-to-end tests: one truncates a real three-entry transaction to two and asserts the file is back at the boundary,
readUncommittedsees 1 entry, and the following transaction's entries parse as flags[1, 1]; the other clears the flag on the last two entries of a three-transaction log (a pre-flag log's shape) and asserts nothing is dropped. Reverting just the source changes fails the first withexpected 124 to be 50.Relationship to rocksdb-js #668
#668 — Data loss: IsBusy commit retry orphans an uncommitted log position, pinning the committed watermark → committed reads truncate is the runtime sibling of this defect: there an orphaned entry in
uncommittedTransactionPositionspinslastCommittedPositionas a permanent floor; here a staletxn.stateseed sets that floor too low at boot. Same watermark, same silent-truncation symptom, different path — this PR does not fix #668.Its "Suggested fix → Subtlety" section is worth reading alongside the design question above: it already names the same tension (
writeBatchdurably writes a transaction's bytes before the commit outcome is known, so advancing the watermark past them exposes bytes whose transaction never committed). Recovery now answers that structurally — the log cannot retain an unclosed transaction — while #668's runtime path can still strand one via an orphanedIsBusyposition, and there the pin is permanent rather than cleared by the next commit. Its fix should probably adopt the same boundary rule rather than inventing a second one.Follow-up
Harper needs a
@harperfast/rocksdb-jsbump once this releases;crashWindowReplication.test.mjsin harper-pro can then drop itsHARPER_TEST_CRASH_WINDOWopt-in and become a real regression guard.Current-head review at
2a1833cb: a full Gemini + Harper storage-domain review found that destructive tail repair ran before readingtxn.stateand could erase a committed, flushed tail. That major is fixed and regression-tested. A delta pass confirmed the fix; its remaining Human-Review-Need 4 items are the deliberate log-authoritative recovery decision Kris approved, inferred interrupted-tail deletion, and the documented Windows checksum gap. Cursor refused the earlierAGENTS.mddiff and was policy-pruned from the low-risk delta; no Claude leg was used.Cross-model review coverage at
ba0a59c7: full passes by Claude, Gemini, and the Harper storage adjudicator, followed by a Claude + Gemini delta pass. Two review-found majors were fixed; the optional Cursor/Grok leg refused theAGENTS.mddiff. Gemini's sole blocker — thatlastCommittedPositionis astd::optionaland the assignment is UB — did not survive a source check: it is astd::shared_ptr<LogPosition>always constructed viamake_shared. Its two test findings (asyncconsole.loghandshake lost to the SIGKILL; Windows self-kill surfacing as exit code 1) were real and are fixed.Codex additionally caught that the seed's
fullPosition > 0guard is unsound — that union member aliases the two uint32s as adouble, so alogSequenceNumber >= 0x7ff00000reads back as NaN or negative and would have silently skipped the seed. The repo's own CI review bot independently flagged the same line. Now tested onlogSequenceNumber. Its remaining finding was the transaction-boundary issue, now fixed here.The Windows CI failure this PR initially hit was a genuine latent bug it exposed, not a test artifact:
findPositionByTimestamp()checked for the zero-timestamp end-of-data marker before special-casing the header's own timestamp slot, so a log file with a zero header timestamp had itssizecorrected down below the 13-byte header and read as empty. Only Windows reached it at open (itsopenFile()indexes to undo memory-map zero-padding), but the indexing path is cross-platform and the added regression test reproduces it everywhere.Generated with Claude Opus 5.
🤖 Generated with Claude Code
Review-Coverage: authored=unknown; ran=none; rounds=1 @ 027f001
Human-Review-Need: 4 @ 027f001