Skip to content

Report a transaction log's corrupt-frame stop to getRange callers through an onCorruptFrame hook - #2463

Closed
kriszyp wants to merge 14 commits into
mainfrom
fix/txnlog-midfile-break-callback
Closed

kriszyp wants to merge 14 commits into
mainfrom
fix/txnlog-midfile-break-callback

Conversation

@kriszyp

@kriszyp kriszyp commented Sep 2, 2026 •

Copy link
Copy Markdown
Member

RocksTransactionLogStore.getRange now exposes an onCorruptFrame(error, logName) hook when a transaction-log iterator stops at a corrupt frame, giving replication consumers the signal they need to recover instead of parking on a dead iterator. The hook is composed with main's corruption stop tracking and telemetry at the existing latch, while aggregate delivery remains safe under re-entrancy and keeps mutable exclusions private to each range. The whole contract — who reports, who owns recovery, and how a hook's removeLog/addLog interact — is recorded as a row in resources/DESIGN.md's read-path table, which is where the next reader of this code will look.

Independent review also identified a pre-existing addLog convergence issue: re-including an excluded peer does not itself invalidate latestUpdates, so that peer waits for another log-list update before receiving an iterator. It is outside this PR's change and is recorded as a follow-up finding.

Four later commits deal with CI, which was red for reasons that had nothing to do with the hook. The branch had drifted into a merge conflict with main, and GitHub builds no merge commit for a conflicting PR, so no pull_request workflow ran at all on it — the red checks were the stale ones from before. It is rebased onto main here, and three things came out of that:

  • The Next.js adapter job's install phases are now bounded. Those three jobs were cancelled at their 30-minute job cap inside Install fixture dependencies on a day when npm installs that normally take 20-50 seconds took 3.5-18 minutes. Its two existing step caps (Playwright 10m, tests 15m) left only 5m for four uncapped npm phases ahead of them, so the job cap was always reached first. Each network-bound phase is now capped at roughly 10x its measured healthy time and the job cap sits clear of their sum. The Linux unit job needed the same treatment and got a better one in Take install_node_modules off the npm registry so the Node 22 unit job stops timing out #2501 while this branch was behind; that fix arrives with the rebase, and nothing here touches unit-test.yml.
  • The PR's own tests were stale against Expose record version and txnLogKey as separate audit clocks #2497's audit-clock split. That PR made version the record's own version and txnLogKey its key in the transaction log, and updated the one corrupt-entry drain test it had. These tests predate it and still read record.version; their synthetic entries carry only a timestamp, so all thirteen collected undefined after the rebase. They read txnLogKey now.
  • Two of them depended on process-global state. Corrupt-frame reports are cleared before each case so the rejecting-async-hook test no longer needs a sibling to have suppressed the report first, and the logger-failure case counts only the reports naming its own log rather than every logger call, since the decoder's undecodable-header warning is latched per process. Both failed under --grep or .only before; both pass in isolation now.

Refs #2016, #2063. The paired engine work is HarperFast/rocksdb-js#817; harper-pro owns the policy that turns a mid-log report into a bounded base-copy resync.

For the human reviewer

  1. Core reports the gap; the consumer repairs it. The alternative is for core to seek past the break or initiate resync itself. Core cannot assign one recovery policy to boot replay, replication, and subscriptions, while harper-pro has the source and bounded-copy machinery. Reversing this later is invasive because recovery ownership crosses repositories; rejecting it now requires moving the policy and its end-to-end proof into core.

  2. The hook is synchronous inside next(). An event or microtask would be simpler, but the replication sender must learn why the drain stopped before it parks on a future transaction. Reports wait until the aggregate buffer is stable, and iterator splices wait for the outermost poll. Changing this later is behaviorally breaking; rejecting it now requires redesigning the sender notification contract.

  3. Promise-returning hooks are fire-and-forget. Rejections are contained and logged, but async recovery cannot gate a synchronous iterator. The alternatives are a synchronous-only signature or an asynchronous iterator contract. This is cheapest to change before adoption; rejecting it requires choosing one of those narrower APIs.

  4. Exclusions belong to the range, not the caller's options object. removeLog records the private exclusion immediately but defers structural mutation, so frozen options work and a hook's exclusion is visible to a nested refresh. The alternative is retaining the caller's array as live shared state. Reversal is local but restores hidden mutation and the frozen-options failure.

  5. The Next.js caps are sized from measured step timings, and ride on this branch rather than their own PR. Network-bound phases get roughly 10x their healthy time because they degrade multiplicatively — a degraded registry stretches an install by a factor, not by a constant. The alternative is tighter fail-fast caps; the cost of the sizing chosen is that a genuinely stuck install burns up to its cap before a named step fails, against a job cap that costs no runner minutes unless it is hit. On placement, the alternative is a standalone workflow PR — cleaner to bisect, but this PR is where the failure was visible. It is one self-contained commit, so say the word and I will cherry-pick it out.

  6. Of the three review findings on the hook, two are fixed and one is left for you. Still open, and adjudicated to nit: the aggregate path fires the hook in the next() that then returns the broken log's last intact entry, while the single-log path fires on the following next(). Neither ordering is wrong and the error direction is redelivery rather than a skipped entry, but the contract does not state which, so a hook that checkpoints "everything delivered so far" records a cursor one entry short on the aggregate path only. Fixed instead of carried: a deferred removeLog now replays only while the name is still excluded, so removeLog(X); addLog(X) inside one hook invocation keeps X rather than silently dropping the rest of that log — covered by a test that loses entries 2, 3 and 4 against the previous behavior. And the CorruptFrameHook contract no longer claims "once per log per iterable": it is once per mounted log, and it no longer implies addLog on its own remounts a removed log, which it cannot — that is the pre-existing latestUpdates gap named above.

Verification

  • npm run build — passed.
  • npm run lint:required — passed.
  • npx mocha unitTests/resources/auditLog.test.js --grep "onCorruptFrame|removeLog remembers|hook exclusion" — 14 passing, including frozen options across refresh, a future peer excluded before it exists, hook-time exclusion before a nested refresh, sync/async failure containment, and a real on-disk torn-frame report.
  • npm run test:unit:resources — 2,203 passing, 0 failing on the pushed head (exit 0). Before the rebase resolution it was 2,190 passing / 13 failing, all thirteen the record.version staleness above.
  • npx mocha unitTests/resources/auditLog.test.js — 94 passing, 8 pending, 0 failing on the pushed head, with main's audit tests and this PR's merged.
  • npx mocha unitTests/resources/auditLog.test.js --grep onCorruptFrame — 14 passing in isolation, including the on-disk torn-frame test. No review leg could execute that one (all of them run read-only without a shell), so it is worth saying plainly: the real rocksdb-js 2.8.0 reader does surface CorruptFrameError with resyncPosition through the hook, both standalone and in file order. The two order-dependent cases also pass alone now; before the fixes they failed with The input did not match the regular expression /onCorruptFrame hook failed/ and 3 !== 2 respectively.
  • Next.js caps derived from step-level timings on real runs, not estimated. Healthy is 4-5m end to end — adapter install 31-47s, harper override 42-67s, fixtures 35-57s, Playwright 23-37s, tests 99-131s — consistent across runs 34170623123, 34119563615, 33944768904 and 33912991544. The cancelled run 33845099465 spent 297s/869s/>1114s in its three then-unbounded npm phases and never reached Playwright.
  • npx prettier --check on the workflow and the test file — passed; the workflow parses to the intended caps (job 60 > 8 + 12 + 10 + 10 + 15 = 55).
  • npm run build on the rebased head — passed.
  • CI at the rebase commit, earlier in this branch's history: 41 pass, 3 fail. All three Next.js adapter jobs pass in 4m55s-5m32s, the jobs that were being cancelled at 30 minutes. The three red checks are Unit Test (Node.js v22/24/26), and they are main's, not this PR's: run 34124860863 on main at 38fcbf1 — the exact commit this branch is rebased onto — fails test MQTT connections and commands > subscribe to retained record with patch operations at unitTests/apiTests/mqtt-test.mjs:503 with 'update 3' == 'update 2', and all three jobs here fail on that same assertion in the same HARPER_STORAGE_ENGINE=lmdb leg. This PR touches no MQTT, apiTests, or server code, and its own legs are green in CI: test:unit:main 5,413 passing, test:unit:apitests 201 passing, test:unit:resources 2,203 passing. Worth a separate issue; deliberately not fixed here.
  • Maintenance push, 2026-09-09 (f416489e4 → 72d80cd9d, no rebase). Format Check was failing deterministically on resources/DESIGN.md: the table row this PR adds was not column-padded, which prettier --check rejects (main's copy of the file is clean). Re-run after the fix: npm run format:check clean repo-wide, npm run build, npm run test:types, npx mocha unitTests/resources/auditLog.test.js 95 passing / 0 failing, npm run test:unit:resources 2,256 passing / 0 failing. CI on 72d80cd9d is fully green — 44 pass, 3 skipped, 0 fail, including the Unit Test (Node.js v22) leg and all three Next.js adapter jobs.
  • Unit Test (Node.js v22) was red on a flake that predates this branch. longLivedTransactions.test.js — "names a chain link reachable only through the root under its own native id" — expects /state: [^,]*active/ and gets state: source-apply. The same assertion fails on main's own run at this branch's merge-base (run 34280999623 at 3a3c0ef), and nothing since has touched that test or DatabaseTransaction.ts. Root cause is the per-pass report cap, not timing noise: a holder skipped once a pass has emitted its 10 lines is retried on a later tick, but active is in the state list only while monitorTick - link.writeTick <= 1, so a deferred report has already lost it. Confirmed locally by forcing that cap to 1 — the file passes 3/3 alone at the real cap and fails immediately at 1 with the exact CI message. It reproduced in 1 of 6 full test:unit:resources runs here and never when the file runs alone. Filed as a follow-up rather than fixed in this PR.
  • Regression controls — the frozen-options test fails against the prior mutating implementation with TypeError: object is not extensible; the nested-refresh test fails before immediate exclusion registration because the excluded future peer is polled twice.
  • harper-pro integrationTests/cluster/txnlogTearReplication.test.mjs — prior paired-branch evidence: base parks at 39/60 rows; this hook plus the sender's bounded base copy converges to 60/60 and accepts a post-recovery row.
  • npm run test:integration:all — began successfully and passed numerous unrelated scenarios, then the runner saturated and multiple independent instances timed out together at 120 seconds; stopped after the synchronized infrastructure failures. npm run test:unit:main and npm run test:unit:windows likewise stopped producing a summary, with the Windows slice also exposing an unrelated ambient credential-socket failure.

Complexity: complicated

Review-Coverage: authored=claude; ran=codex,gemini; declined=cursor-grok,cursor-composer,domain; rounds=17 @ 72d80cd

Human-Review-Need: 3 @ 72d80cd

Refs #2142

@kriszyp kriszyp added this to the v5.2 milestone Sep 2, 2026
@github-actions

github-actions Bot commented Sep 2, 2026 •

Copy link
Copy Markdown
Contributor

Release cherry-pick v5.2: cancelled

Cherry-pick branch cherry-pick/v5.2/pr-2463 was deleted — this PR no longer targets v5.2 (milestone is now v5.3).

@gemini-code-assist gemini-code-assist Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Code Review

This pull request introduces a new onCorruptFrame hook option to RocksTransactionLogStore.getRange(), allowing callers to be notified synchronously when a transaction log iterator stops early due to a corrupt frame. The implementation safely handles hook execution, defers reports for construction-time corrupt frames, and queues log removals requested during polling to prevent iterator disruption. Comprehensive unit tests have been added to verify these behaviors under various scenarios, including aggregate/single-log paths, throwing/async hooks, and on-disk torn frame detection. No review comments were provided, so there is no feedback to address.

@kriszyp kriszyp modified the milestones: v5.2, v5.3 Sep 2, 2026
@kriszyp
kriszyp requested review from cb1kenobi and removed request for Devin-Holland and heskew September 2, 2026 17:08
@kriszyp
kriszyp marked this pull request as ready for review September 2, 2026 17:08
@kriszyp
kriszyp force-pushed the fix/txnlog-midfile-break-callback branch from d1bd8b6 to 85b5848 Compare September 2, 2026 19:06
@kriszyp
kriszyp marked this pull request as draft September 2, 2026 19:07
@claude

claude Bot commented Sep 2, 2026 •

Copy link
Copy Markdown
Contributor

Reviewed; no blockers found.

Comment thread resources/RocksTransactionLogStore.ts Outdated
@kriszyp
kriszyp requested a review from cb1kenobi September 4, 2026 04:56
@kriszyp
kriszyp marked this pull request as ready for review September 4, 2026 04:56
@kriszyp
kriszyp force-pushed the fix/txnlog-midfile-break-callback branch 2 times, most recently from 881e3d3 to 46b582e Compare September 8, 2026 04:14
Comment thread resources/RocksTransactionLogStore.ts Outdated
Comment thread resources/RocksTransactionLogStore.ts
kriszyp and others added 9 commits September 8, 2026 16:21
…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
…e the hook's per-iterable scope

The polling flag was cleared by the innermost guarded next(), so a hook
that re-entered the same iterable left the outer advance() unguarded and a
second break in that pass could splice a slot it was about to write. The
flag is now saved and restored, and deferred removals are applied only by
the outermost call. The hook doc now says once per log per iterable: the
latch lives on the iterable, so a still-broken log reports again on the
next getRange.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01LMb1MzgF9DR2MC8X7Fz3uj
… framing breaks

A hook that re-entered next() from inside the poll was given the entry
the outer next() was in the middle of returning, because the slot was
replaced only after the poll that fired the hook. With a hook configured
the slot is marked done before the poll. The hook doc now says it covers
framing breaks only (a reader that dies with another error ends its log
through safeNext without a report) and that removeLog from the hook is an
aggregate-path lever.

Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01LMb1MzgF9DR2MC8X7Fz3uj
Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Clone caller exclusions into mutable iterable state so corruption hooks can remove logs even when getRange options are frozen. Extend the regression coverage across refreshes and align logger-failure assertions with core corruption telemetry.

Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Record removeLog exclusions before a peer exists, allocate iterable-private state lazily, and reuse the existing corruption error type. Document and test the future-peer refresh contract identified during independent review.

Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Register excluded log names immediately while continuing to defer iterator-array splices until polling completes. Cover a hook that excludes a future peer and re-enters next during the same callback.

Co-Authored-By: GPT-5 Codex <noreply@openai.com>
… stops cancelling it

The three Next.js adapter jobs died at their 30-minute job cap on 2026-09-04
while npm was degraded, producing a bare cancellation with no failing assertion
and no named step to blame.

A healthy job is 4-5 minutes end to end. Its two step caps (Playwright 10m,
integration tests 15m) left only 5m for the four uncapped npm phases ahead of
them, so the job cap was always reached first: those phases ran to
5m/14.5m/18.5m and the job died inside `Install fixture dependencies`.

Cap each network-bound phase at roughly 10x its measured healthy time and raise
the job cap clear of the sum of its own step caps, so a stall fails as the step
that stalled rather than as a whole-job cancellation.

This is the treatment #2501 gave the Linux unit job, applied to the downstream
adapter workflow it did not cover.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01G5vXKjCvTH1zasJ3oYquFQ
kriszyp and others added 3 commits September 8, 2026 16:22
`createCorruptFrameReporter` dedupes per break site in a module-level map, so
whether it logs is decided by whatever ran earlier in the process. The
rejecting-async-hook case relied on that: it asserted the hook failure was
`logged[0]`, which held only because an earlier case had already registered the
same site and suppressed the report. Run alone — `--grep`, `.only`, or a
reordered file — it read the corrupt-frame report instead and failed. Its
sibling has the mirror dependency: it asserts two logger calls, so it needs the
site to be unseen, which a second in-process run would not give it.

Clear the reports before each case in the describe, and locate the hook-failure
entry by its message rather than by position.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01G5vXKjCvTH1zasJ3oYquFQ
…'s clock split

#2497 split the RocksDB audit record's two clocks: `version` is the record's own
version and `txnLogKey` is its key in the per-origin transaction log. The read
surface no longer overwrites `version` with the log key, and that PR updated the
one corrupt-entry drain test it had to `record.txnLogKey`.

The onCorruptFrame tests were written before that landed and still read
`record.version`. Their synthetic entries carry only a timestamp and no decodable
record version, so after the rebase all thirteen collected `undefined` and failed.

Read `txnLogKey`, and rename the collectors from `versions` to `logKeys` — they
hold log keys, which is the distinction #2497 exists to make.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01G5vXKjCvTH1zasJ3oYquFQ
…ning

The logger-failure case asserts that exactly two logger calls run: the
corrupt-frame report and the hook-failure report. It counted every call to the
stubbed `error`/`warn`, which also catches `corruptEntry`'s undecodable-header
warning at `resources/auditStore.ts:936`. That one is latched per process, so
the assertion held only when something earlier had already tripped the latch:
`mocha -g 'contains a hook failure'` or `.only` saw a third call and failed
while the full file passed.

Count the reports that name this case's own log instead. Same coupling to
process-global state as the dedup fix a commit earlier, different global.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01G5vXKjCvTH1zasJ3oYquFQ
@kriszyp
kriszyp force-pushed the fix/txnlog-midfile-break-callback branch from 46b582e to f416489 Compare September 8, 2026 22:23
kriszyp and others added 2 commits September 9, 2026 08:53
Prettier rejected the DESIGN.md row this PR added, failing Format Check.

The aggregate iterator defers a `removeLog` requested from an `onCorruptFrame`
hook until the outer `next()` returns. It replayed every deferred name
unconditionally, so `removeLog(X); addLog(X)` in one hook invocation re-excluded
X and spliced its iterator out, silently discarding the rest of that log. Replay
only what the exclusion still implies, so the hook's last call for a name wins.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01V8XZXXLTrtRdgdZt7YKUM5
`addLog` only drops the name from the range's exclusions; `updateIterators`
rebuilds the log set only when `this.updates` moves, so the previous wording
promised a remount the caller cannot trigger on its own.

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01V8XZXXLTrtRdgdZt7YKUM5
@kriszyp

kriszyp commented Oct 12, 2026

Copy link
Copy Markdown
Member Author

Closing as superseded. #2087 settled the corrupt-frame policy as fail-stop, and main now reports the break through range.corruptFrameStop (breaks, midLogBreak, truncatedVersions), which harper-pro's sender reads after each pass. harper-pro#802 pinned the mid-log tear test to fail-stop, so no consumer adopted this hook for resync. #3080 covers the addLog re-admit gap noted here. The remaining question for #2063 / #2016 is recovery policy (fail-stop + re-clone vs. automatic resync), tracked on those issues.

— Claude Opus 5.5

@kriszyp kriszyp closed this Oct 12, 2026
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.

2 participants