Skip to content

Mid-log corrupt transaction-log frame silently truncates replay and replication — acknowledged writes lost #2016

Description

@heskew

Summary

A mid-log corrupt frame in a table's local transaction log silently truncates every reader of that log — crash-recovery replay and replication — at the position of the tear. Because tables run WAL-less by default, replay is the only thing standing between an unclean exit and the loss of acknowledged writes, so a single torn frame converts into:

  1. Unbounded, silent loss of acknowledged writes. Observed: a crash 2.2 days after the tear rolled a table back to the tear position, dropping 33 acknowledged records written over those 2.2 days.
  2. Indefinite replication starvation. The peer's reader stops at the same frame, so the peer receives nothing written after the tear — for days — while cluster_status and component health stay green.
  3. All of it at warn level, latched to fire once per log.

The design assumption that breaks

endIteratorOnCorruptFrame (resources/replayLogsGuards.ts) deliberately treats a corrupt frame as end-of-log:

"Logs (once per log) when a corrupt frame ends a query iterator early; see endIteratorOnCorruptFrame in replayLogsGuards.ts for why this is end-of-log, not a crash."

That is sound when the tear is at the tail — a torn final write, nothing after it. It is wrong when the tear is mid-log: a failed append (ENOSPC/EDQUOT partial write) that the process survives. The process keeps accepting writes and appending valid frames after the tear, every one of them acknowledged to clients — and every one of them unreachable to any future reader.

With options.disableWAL ??= true (resources/databases.ts:163), those post-tear writes have exactly two homes: the memtable and the txnlog-beyond-the-tear. An unclean exit destroys the first and the tear amputates the second.

Observed incident (5.1.x, two-node hosted cluster)

  • Day 0: the instance exhausted its filesystem quota. A torn frame landed mid-log in one table's local transaction log. First evidence, 3 seconds into the recovery-restart boot:
    [main/0] [warn]: Stopping transaction log "local" at a corrupt entry during replay
      RangeError: Corrupt transaction log entry ...
    
  • Day 0 → Day 2.2: the node ran continuously; 33 records were written and acknowledged (memtable + post-tear txnlog appends; low write volume, so no flush ever triggered).
  • Day 2.2: a component deploy's restart crashed the process (native-addon segfault during teardown — separate issue in the component's repo). Recovery replay walked the log, stopped at the tear:
    [http/2] [warn]: Stopping transaction log "local" at a corrupt entry during replay
      RangeError: Corrupt transaction log entry at position 7d20bb of log 2: declared le...
    
    and the table silently rolled back 2.2 days. The same warn fired for a second torn frame (position 3bc071 of log 23) and repeated at every subsequent boot.
  • Replication: the peer had been starving since the tear. Restarting either node re-established sessions (logs said Connected, cluster_status said replicates: true) but moved zero rows — each new reader re-stopped at the same frame. Nothing distinguished this from healthy replication except manually diffing record counts across nodes.

The records were recoverable only because the operator happened to hold an off-box copy.

Suggested directions

Ordered roughly by how much of the problem each removes:

  1. Distinguish mid-log from tail tears. If any bytes/frames exist beyond the corrupt frame, this is not end-of-log — escalate to error, surface it in health/cluster_status, and don't let replay conclude "done".
  2. Frame resync: scan forward from a corrupt frame to the next valid frame boundary so replay and replication readers can recover the post-tear entries rather than amputating them. (The entries observed here were valid and intact — only one frame between them and the reader was torn.)
  3. Don't acknowledge a write whose txnlog append failed (ENOSPC/EDQUOT). A torn frame mid-log is only possible because the append path can fail partially while the write is still acknowledged.
  4. At minimum: a startup counter/metric for "corrupt frame encountered, N bytes/frames unreachable beyond it", so this is observable before it becomes a rollback.

Related


🤖 Filed by Claude on behalf of @heskew

Activity

  1. added
    bugSomething isn't working
    area:storageStorage engine, LMDB/RocksDB, compaction
    on Jul 31, 2026
  2. added this to the v5.2 milestone on Aug 5, 2026
  3. added theissue type on Aug 5, 2026
  4. kriszyp commented on Aug 6, 2026

    @kriszyp
    Member

    Status on this, since the fix is split across three repos and only part of it can land today.

    The reader half — rocksdb-js#750 — fix(txnlog): resync past a mid-log corrupt frame instead of ending the log. Ready, green on every platform/runtime leg, awaiting human review. query() now reports a break as a CorruptFrameError carrying resyncPosition (where valid framing resumes) plus the unreadable byte count, and advances its reader there before throwing — so only the torn frame is lost, not everything behind it. This is suggested direction 2. A 12-entry log with a broken second frame yields 11 entries where the old reader yielded 1.

    The consumer half — harper#2087 — fix(replay): resync past a mid-log corrupt transaction-log frame and surface it as data loss. Draft, rebased onto main today. endIteratorOnCorruptFrame keeps pulling when the error carries a resume point instead of latching, capped at 32 resyncs per iteration; a mid-log break now logs at error and says entries were lost, which is suggested direction 1's severity half. Kept a draft deliberately: no released rocksdb-js sets resyncPosition (verified against 2.7.0), so it is inert until a bump ships — behavior is unchanged today, which is why the two need not land in lockstep, but also why neither closes this on its own.

    The health signal — harper-pro#667 — cluster_status reports a stream healthy after it has lost transaction-log entries. Filed just now, not started. harper#2087 accumulates break sites and exposes them as getCorruptFrameReports() (location, mid-log vs torn tail, unreadable bytes, whether iteration stopped, occurrence counts), but nothing consumes it yet, and cluster_status is harper-pro. Until that is wired, the only operator-visible signal is still a log line — the exact gap that let this run 2.2 days here and 11 days in #2063. That covers suggested directions 1 (surfacing) and 4.

    Suggested direction 3 — don't acknowledge a write whose append failed — is not addressed and is the only one that prevents rather than recovers. Filed as rocksdb-js#748 — A failed transaction-log append orphans its partial bytes, baking a mid-file framing break into the log. Related: rocksdb-js#749 — Uncommitted transaction-log reads bound corruption checks by mapped capacity, which is why a torn frame with a plausible declared length still goes undetected on the boot-replay path.

    One honest coverage gap on both PRs: every test drives synthetic buffers or iterators. Nothing reopens a genuinely damaged log on disk and watches a real consumer replicate past the break — that test lives in harper-pro and is not written.

    🤖 Claude Opus 5

  5. kriszyp commented on Aug 7, 2026

    @kriszyp
    Member

    The end-to-end test is now up as harper-pro#670 — test(cluster): prove mid-log txnlog tear recovery end-to-end, which closes the coverage gap noted above: a real two-node stream reading a genuinely damaged log off disk, rather than synthetic buffers.

    It confirms the fix (39/60 rows on released rocksdb-js 2.7.0, 60/60 on the #750 build) and turned up a residual: the readable tear shape — the one a partial append usually leaves — still wedges the receiver even on a fixed engine, because the torn frame is yielded as a well-formed entry with a garbage payload and no reader can tell. Filed as harper-pro#669; details in my note on #2087.

    So suggested direction 2 (frame resync) is proven for the unreadable shape, and direction 3 (don't acknowledge a write whose append failed — rocksdb-js#748) is now the load-bearing one, since prevention is what removes the poison entry rather than surviving it.

    🤖 Claude Opus 5

  6. kriszyp commented on Aug 30, 2026

    @kriszyp
    Member

    A data point for this issue's "corrupt frame silently accepted" premise, from dispatch QA finding F-289: rocksdb-js's open-time recovery scan has no payload checksum. scanTransactionLogForRecovery() (src/binding/transaction_log/transaction_log_recovery.h, rocksdb-js origin/main a941a670) classifies only framing integrity — Clean / TruncateTail / MidFileCorruption — and the header docs state outright that a payload-level bit-flip is "indistinguishable... without a checksum". So a corruption that leaves the frame header and length prefix intact but flips payload bytes classifies as Clean and is loaded/replayed as if valid — exactly the silent-truncation-vs-silent-bad-data hazard this issue is about, one layer deeper than replayLogsGuards.ts's endIteratorOnCorruptFrame (which only fires on framing breaks).

    This came up while investigating a separate, still-unconfirmed claim (a 2-byte payload flip appearing to wedge restart); that wedge half is being localized separately and may be a harness signal-handling artifact. But the payload-checksum gap itself is real and independent of the wedge question, and it argues for a frame-level payload checksum (or CRC) as part of hardening this path.

    From dispatch QA finding F-289. — Claude (Fable 5)

  7. changed
    Priority
    toon Sep 20, 2026
  8. kriszyp commented on Sep 20, 2026

    @kriszyp
    Member

    Root causes have been addressed, these are pretty rare edge cases at this point.

  9. maurice-harper commented on Oct 1, 2026

    @maurice-harper
    Contributor

    Data point for the "cases that look like this issue": a production occurrence on 5.2.6 (rocksdb-js 2.7.1) with the exact declared length N overruns the log (limit=L) fail-stop, where there was no corrupt frame at all. L equalled the pinned committed watermark on each of three affected nodes (full table in harper#2073, comment of 2026-10-01). Replication to every peer stopped at the first entry straddling that byte, cluster_status stayed connected: true and replication metrics stayed at 0 lag for 8 days, matching the "indefinite replication starvation" item here.

    Worth splitting the two causes in the reader's handling: a frame that overruns the watermark bound is not evidence of corruption and should not fail-stop the stream, whereas a frame that overruns the file is.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

area:replicationReplication, clusteringarea:storageStorage engine, LMDB/RocksDB, compactionbugSomething isn't working

Type

Fields

Priority

P2

Projects

No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions