fix(txnlog): resume the recovery scan and timestamp index past a mid-file framing break - #817
fix(txnlog): resume the recovery scan and timestamp index past a mid-file framing break#817kriszyp wants to merge 10 commits into
Conversation
…file break A mid-file framing break — a torn frame with intact, committed entries after it — was only partially readable after reopen even though query() resyncs past such breaks. Two native walks stopped at the first break: - scanTransactionLogForRecovery returned MidFileCorruption at the break, so lastCompleteTransactionEnd (the seed for the committed-read watermark) covered only the entries before it. Committed reads were clamped there: with frame 39 of 60 torn, a drain returned 39 entries and no error. - findPositionByTimestamp strode through the broken frame's declared length, carrying lastIndexedPosition past size and freezing the index, so every seek at or after the break reported "past this file". Both walks now resume at findFramingResumeOffset(), the same heuristic the JS reader's findResyncPosition() uses. The scan pins its classification to the first break and keeps walking, so the watermark covers every complete transaction in the file and a torn tail behind a break still reports MidFileCorruption (never truncated). The index walk resumes where framing does, or at the written extent; a break there is never an in-flight append because size is bumped only after the bytes land. Fixes #815 Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01Ves73HzfZGAwMgGbyTqLsr
…he map The map-size guard ran ahead of the header-timestamp-slot branch, so a header-only file (13 bytes, walk starting at offset 5) reported an unindexed tail and findPositionByTimestamp returned offset 5, mid-header, instead of 0 / 0xFFFFFFFF. Handle the slot first; the guard only applies to entries. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01Ves73HzfZGAwMgGbyTqLsr
…ded segment The native walks run before `size` has been corrected on a Windows segment, so `findFramingResumeOffset()` saw the physical, zero-padded size as EOF. A run of fewer than RESYNC_MIN_FRAMES entries after a break then ended at the padding rather than on EOF, satisfied neither resume rule, and recovery classified the file as a torn tail and truncated the run's committed entries. A chain landing exactly on the end of the nonzero bytes is now accepted as landing on the written extent: a single offset, as conclusive as EOF. Also trims the comments the round-1 review flagged as narration. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01Ves73HzfZGAwMgGbyTqLsr
…isk size On Windows the segment is pre-extended to the map size and never truncated on close, so statSync reports the physical extent. Also trims comments that restated the code. Co-Authored-By: Claude Fable 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01Ves73HzfZGAwMgGbyTqLsr
There was a problem hiding this comment.
Code Review
This pull request improves the transaction log recovery and indexing mechanisms to handle mid-file framing breaks (corruptions) more robustly. Instead of stopping or truncating at a break, the recovery scan and timestamp index now resume past the corruption using a new findFramingResumeOffset helper. This ensures that valid entries after a break remain readable, searchable, and indexed. Additionally, the recovery logic is updated to handle pre-extended files with zero padding (such as on Windows) by detecting the end of nonzero bytes to prevent premature truncation. Comprehensive native and integration tests have been added to verify these behaviors. I have no feedback to provide as there are no review comments.
📊 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 94b0fe3 |
…rs, not a pre-close query The four mid-file-break tests queried the log before closing the database to collect entry timestamps. That query maps the file, and the map outlives close() while the query's entries are reachable, so on Windows the truncating rewrite that tears the frame failed with ERROR_USER_MAPPED_FILE (errno -4094 on open). The timestamps are read from the frame headers on disk instead, which a tear leaves intact, so the file is unmapped when it is rewritten. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01LMb1MzgF9DR2MC8X7Fz3uj
|
I believe this resolves the broken CI failures on harper-pro main right now. |
| if (firstBreak == 0) { | ||
| firstBreak = pos; | ||
| } | ||
| pos = resume; |
There was a problem hiding this comment.
Critical — committed reads expose a torn transaction's prefix. Resuming here lets a later LAST_FLAG move the single contiguous lastCompleteTransactionEnd beyond the break; if the broken frame ended an uncommitted batch, its intact prefix is then emitted as committed before CorruptFrameError, creating phantom writes or replication. Simplest fix: keep the committed watermark before the first break; if post-break commits must remain readable, add a torn-group skip range that committed readers exclude before advancing it.
—
Generated by Barber AI
There was a problem hiding this comment.
Deliberately not fixed here — this is #816, and the ruling on this task was to keep #817 scoped to the #815 recovery fix. Both suggested shapes were weighed: pinning the committed watermark before the first break restores the 39/60 amputation this PR exists to remove (a stuck sender with no error, which is worse than a loud break the forced base-copy repairs), and the torn-group skip range is the hole-aware committed read that #816 tracks — a new engine surface, and the same leak has existed for rotated files since #750. Left unresolved on purpose so it stays visible.
— Claude Opus 5
| uint32_t windowLen = 0; | ||
| char headerBuf[TRANSACTION_LOG_ENTRY_HEADER_SIZE]; | ||
|
|
||
| auto reachesWrittenExtent = [&](uint32_t pos) -> bool { |
There was a problem hiding this comment.
High — trailing-zero payloads are mistaken for a torn tail. nonzeroEnd() returns the byte after the last nonzero value, not necessarily the start of preallocation padding; when the final committed frame's payload ends in zero bytes and the resumed run has fewer than eight frames, pos lands after this value, resync returns 0, and recovery truncates valid committed entries at the break. Simplest fix: determine or persist the exact logical append extent independently of payload contents and compare against that boundary.
—
Generated by Barber AI
There was a problem hiding this comment.
Accurate, and deliberately not fixed here: doing it exactly needs the persisted logical append extent you describe, which is a format change rather than part of this red fix. The scope is narrower than the base behaviour it replaces (which truncated every such run, not only one whose final payload ends in zero and is shorter than eight frames), and it is Windows-only since a POSIX segment ends at its physical size. Loosening reachesWrittenExtent to pos >= nonzeroEnd() instead would accept any forged length landing anywhere in megabytes of padding, so that is not a safe cheap version. Left unresolved so the follow-up stays visible; noted for issue triage.
— Claude Opus 5
…hrough an onCorruptFrame hook A corrupt frame ends a log's query iterator early and latches it dead (endIteratorOnCorruptFrame), but the store only warned; a consumer had no way to learn that its stream had stopped, or whether intact entries follow the break. The replication sender therefore parks on a latched iterator forever after a mid-log tear (harper-pro txnlogTearReplication red: follower holds 39/60 rows). getRange now takes an optional onCorruptFrame(error, logName) hook, fired once per log at the latch point on both the single-log and the aggregate path, synchronously from inside the iterable's next(). The error is the engine's CorruptFrameError, typed against the pinned engine: resyncPosition present means a mid-log break with entries lost to the stream, absent means a torn tail. Core reports only; the recovery policy belongs to the caller. A throwing or rejecting hook is contained so the end-of-log stop stays a stop. The unit tests drive the hook through fakes throwing the engine's own CorruptFrameError, and through the real engine over a log torn on disk: the hook receives the engine error with the resume offset and the drain stops at the break. Refs #2016, #2063. Engine half: HarperFast/rocksdb-js#817. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01LMb1MzgF9DR2MC8X7Fz3uj
… the extent The index walk searches the mapped region (`min(size, mapSize)`), which falls short of the written extent whenever one batch exceeded `transactionLogMaxSize` or the limit was lowered since. A resync that found nothing there was treated as "nothing follows the break" and `lastIndexedPosition` jumped to the written extent — past bytes the walk never inspected. That is permanent: a later, larger map resumes from `lastIndexedPosition` and never looks below it, so those entries stay unindexed and every seek into them reports "past this file". An empty resync result is now scoped to the bytes that were searchable. When the map stopped short, the walk stays at the break and reports an unindexed tail — the same treatment the header bound-check above it already gives a tail the map does not cover, and the caller scans from the break and resyncs through it. Only when the whole written extent was searchable, and the break is therefore a torn tail, does the walk park at the extent so later appends are still indexed. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Staying at the break when the map is short of the written extent means every later seek re-ran the byte-wise resync search over the whole corrupt gap, under the store's dataSetsMutex — stalling writers and every other reader for the length of the gap, per seek. Only a larger map can change the answer, so the searched extent is recorded and the search is skipped until the map grows past it. Every assignment that moves lastIndexedPosition off the break clears it. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…elides The repeat lookup asserted only that the position was unchanged, which holds with or without the memo, so nothing regression-tested the elided scan. A test-only counter on the resync search makes it observable: one search for the short map, none for the repeat, and one more once the map grows past the extent that failed. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Windows indexes the whole file against a full-extent map inside openFile(), so the fixture arrived with the break already resolved and the short-map assertions (and the search counter) would have failed in the Windows CI job. Dropping the mapping and the index first reaches the same starting state on both platforms. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
The index walk hands findFramingResumeOffset the mapped region as its file size, so the "a chain landing exactly on the written extent resumes" rule was reading an arbitrary map cut as the end of the data — the one bound AGENTS.md invariant 11 says the resync must never take. On an oversized current segment with a corrupt gap, a garbage chain inside the gap that happens to end on the cut would be accepted as the resume, and its bogus timestamp would enter the running-maxima index: every real entry behind it then fails the greater-than test, is never indexed, and seeks above that value report past-file, so a reader silently skips the rest of the segment. The landing rule is now conditional (endIsWrittenExtent, default true so the recovery scan is unchanged) and the index walk turns it off whenever the map stops short. A short map then has only the RESYNC_MIN_FRAMES run to go on, which is evidence rather than coincidence. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
…hrough an onCorruptFrame hook A corrupt frame ends a log's query iterator early and latches it dead (endIteratorOnCorruptFrame), but the store only warned; a consumer had no way to learn that its stream had stopped, or whether intact entries follow the break. The replication sender therefore parks on a latched iterator forever after a mid-log tear (harper-pro txnlogTearReplication red: follower holds 39/60 rows). getRange now takes an optional onCorruptFrame(error, logName) hook, fired once per log at the latch point on both the single-log and the aggregate path, synchronously from inside the iterable's next(). The error is the engine's CorruptFrameError, typed against the pinned engine: resyncPosition present means a mid-log break with entries lost to the stream, absent means a torn tail. Core reports only; the recovery policy belongs to the caller. A throwing or rejecting hook is contained so the end-of-log stop stays a stop. The unit tests drive the hook through fakes throwing the engine's own CorruptFrameError, and through the real engine over a log torn on disk: the hook receives the engine error with the resume offset and the drain stops at the break. Refs #2016, #2063. Engine half: HarperFast/rocksdb-js#817. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01LMb1MzgF9DR2MC8X7Fz3uj
A transaction log with a mid-file framing break — a torn frame that intact, committed entries follow — is now fully readable after reopen. Two native walks of the framing stopped at the first break even though
query()has resynced past such breaks since #750: the open-time recovery scan seeded the committed-read watermark (lastCompleteTransactionEnd) from the entries before the break, so a committed drain of a 60-entry log torn at frame 39 returned 39 entries and no error; and the timestamp index strode through the broken frame's declared length past the written extent and froze, so every seek at or after the break reported "past this file". Both walks now resume at the same offset the JS reader'sfindResyncPosition()uses (findFramingResumeOffset(), shared by the scan and the index), so the watermark covers every complete transaction in the file and the index covers every intact entry. The break is still surfaced asCorruptFrameErrorwithresyncPosition; a file with a break is never truncated, including when a torn tail follows the break.The shared resume rule also learned about pre-extended segments: on Windows a segment is zero-padded to its maximum size, and the native walks run before
sizehas been corrected to the end of the data, so a chain of fewer than eight frames in front of the padding could never "reach EOF" and classified as a torn tail — recovery would have truncated committed entries. A chain landing exactly on the end of the nonzero bytes now counts the same as one landing on EOF.Review feedback on this PR found the other half of that accounting in the index walk. It searches the mapped region (
min(size, mapSize)), which stops short of the written extent whenever one batch exceededtransactionLogMaxSizeor the limit was lowered — and an empty search there was treated as "nothing follows the break", parkinglastIndexedPositionat the extent, past bytes the walk never read. That loss is permanent: a later, larger map resumes fromlastIndexedPositionand never looks below it. An empty result is now scoped to the bytes that were searchable, so the walk stays at the break and reports an unindexed tail — the same treatment the header bound-check above it already gives a tail the map does not cover — and parks at the extent only when the whole extent was searchable and the break is therefore a torn tail. A short search also gives up the "chain lands on the written extent" signal: the region ends on an arbitrary cut, so a chain landing there proves nothing, and accepting one would let a garbage chain inside the corrupt gap resume the walk — whose bogus timestamp then caps this running-maxima index and hides every real entry behind it.Fixes #815. This is the engine half of the harper-pro
txnlogTearReplicationred (follower stuck at 39/60 rows); harper core and harper-pro follow with their own PRs on top of the 2.8.1 release.For the human reviewer
Framing-Verdict: better-alternative-exists (8fc19599da00) — resolved by ruling: system-level resync (core surfaces the mid-log-break halt, harper-pro forces the bounded base-copy) plus fix the engine watermark amputation and seek blindness here, rather than either alone.
lastCompleteTransactionEndadvances past a break to the last flagged entry the scan can reach, which means the committed-read bound accepts a run of frames thatfindFramingResumeOffset()judged to be real log data (≥ 8 well-formed frames, or a chain landing exactly on the written extent). Alternative: keep the watermark pinned before the first break and leave only uncommitted reads able to see past it. Chosen because the JS reader already delivers those frames as entries under the same heuristic, so pinning the watermark buys no additional safety, only the 39/60 amputation. A "no" here reverts to the amputation and pushes the whole recovery onto the base-copy resync in harper-pro. Cheap to reverse (one branch in the scan).sizeas a break, never as an in-flight append. This rests onwriteEntriesV1bumpingsizeonly afterwritevreturns and on the POSIX overlay exposing bytes only up to an entry boundary, so a nonzero header belowsizeis always a complete entry. If that invariant is ever relaxed (a writer publishingsizebefore the bytes land), the walk would skip a live entry's index slot untilresetTimestampIndex(). Same assumption the base code made implicitly by stridingHEADER + length; this PR makes it explicit in the comment. Where to look hardest: the resume branch offindPositionByTimestampand themin(size, mapSize)bound on the byte search.lastIndexedPositiontosizeso later appends get indexed and the torn bytes never do — but only when the whole written extent was searchable, which is the only case that proves nothing follows. Staying at the break costs nothing per seek: the extent that failed is memoized, since only a larger map can change the answer, and the guard answers a repeat seek without re-scanning the corrupt gap under the store'sdataSetsMutex. Every assignment that moveslastIndexedPositionoff the break — includingresetTimestampIndex()— clears the memo, so the two cannot disagree; that is the invariant to check hardest. A native-test-only counter (resyncSearchCountForTests,ROCKSDB_JS_NATIVE_TESTSonly) makes the elision assertable rather than assumed. The landing rule is switched off for a short search throughendIsWrittenExtent, which defaults to true so the recovery scan — which reads the real file — is unchanged.nonzeroEnd()is computed once per scan, reading the file backwards from its physical size, only when a break has already been found. The residual: a run whose last payload ends in zero bytes still misses the signal (its chain lands past the nonzero end) and, if shorter than eight frames and in front of padding, still classifies as torn — Windows-only, and narrower than the base behaviour, which truncated every such run; the rule is recorded in AGENTS.md invariant 11. A false positive needs a forged chain landing on that exact offset (one in 2³² per candidate). Alternative: derive the extent from the caller's correctedsize— but the callers are the ones computingsize, so the scan has nothing to be handed. Fixing it exactly needs a persisted logical append extent, which is a format change and a follow-up, not part of this red fix; acceptingpos >= nonzeroEnd()instead would let any forged length landing anywhere in megabytes of padding qualify, which is a much worse trade.firstBreak) while the walk continues past it (MidFileCorruption,validEnd= first break) — unchanged from base, which also stopped classifying at the first break and never truncated after it.Declined: the resync byte search runs under
fileMutexwith no upper bound other than the file (Codex, round 1). It runs once per file per open, only when a break exists, and spans only the corrupt gap; the adjudicator agreed it is a latency cliff on an already-corrupt file, not a hang. The memo above removes the repeat-seek half of the same concern raised against the index walk (which holds the store'sdataSetsMutex). The overlay-lag concern from the same round ("a live append mistaken for corruption") does not apply: the shared range ends at an entry boundary and the walk never reads a header at or pastsize, so a lagging overlay reads as zeros — the existing end-of-data branch.Declined: "the partial-map retry cannot recover through the public reader, because a current file is always mapped at
maxFileSize" (pre-push round 6-9). The retry is what makes recovery possible at all. While the segment is current,maxFileSizeis the same bound the reader maps under (TransactionLogStore::getMemoryMap), so no entry past it was readable in the first place; once the segment rotates or is reopened as non-current it is mapped at its ownsize, the whole extent becomes searchable, and the walk — still parked at the break — resumes and indexes the run. Under the previous behaviourlastIndexedPositionhad already jumped past those entries, so rotation could never recover them.Verification
src/reverted toorigin/main(tests kept), the new behaviour tests inTransactionLogRecovery.*/TransactionLogTimestampIndex.*fail and the 3 new JSmid-file break on reopentests fail withexpected 39 to be 59,expected 20 to be 58,expected 39 to be 59— the same 39/60 shape as the harper-pro red. TheTransactionLogResumeOffset.*tests do not compile on base (new symbol). The padding rule proven the same way: withreachesWrittenExtentreduced topos == fileSize,ShortRunReachingThePaddingIsNotTruncatedfails (TruncateTailinstead ofMidFileCorruption, watermark 69 instead of 177) andShortRunBeforeThePaddingIsIndexedAndEndsTheFilefails (seek reports past-file).ShortMapDoesNotSkipTheUnsearchedPostBreakTailfails with the previouslastIndexedPosition = writtenExtentline restored — the short-map seek and both later full-map seeks report4294967295(past-file) instead of the break and the run's offsets — and, with the memo guard disabled, the counter assertions fail2/3against the expected1/2.ShortMapCutIsNotTreatedAsTheWrittenExtentandACutIsNotTheWrittenExtentboth fail withendIsWrittenExtentforced true (the index one resumes at the run instead of holding at the break).pnpm test:native180/180;pnpm test837 passed, 3 skipped;pnpm checkclean. Note for anyone re-running the native suite:pnpm test:nativerebuilds only when the binary is missing or the RocksDB pin changed, so a C++ edit needsNATIVE_TEST_REBUILD=1or it silently tests the previous binary.mid-file break on reopentests failed on every Windows leg witherrno -4094(ERROR_USER_MAPPED_FILE) opening1.txnlog. The tests queried the log before closing the database to collect seek timestamps; that query maps the file and the map outlivesclose()while its entries are reachable, so the truncating rewrite that tears the frame is refused on Windows. They now read the timestamps from the frame headers on disk after close, so nothing is mapped when the file is rewritten (test/transaction-log.test.tsheaderTimestamps). The new native test needs the same care from the other direction: Windows indexes the whole file against a full-extent map insideopenFile(), so it drops that mapping and the index before asserting. Both are proven by the Windows legs on this push.integrationTests/cluster/txnlogTearReplication.test.mjsagainst a core pinned to this build, in the harper-pro PR that lands on top (its own PR body carries the 60/60 result).Complexity: complicated
Review-Coverage: authored=claude; ran=codex; blocked=gemini(auth); declined=cursor-grok,cursor-composer,domain; rounds=11 @ 7012af7
Human-Review-Need: 4 @ 7012af7