Repository navigation
Flaky: clone from a legacy v4 leader intermittently fails when audit-log forwarding throws RangeError converting a non-integer to BigInt #737
Description
Activity
Root cause found — it is not a decode bug on the v4↔v5 audit path, it is a redundant reverse full copy that makes the v4 leader write audit entries nobody can parse
Reproduced locally and confirmed at the byte level (leader =
harperdb@44.7.36, the same version CI installs).Chain
- The v5 clone bootstraps from the v4 leader (
isLeaderfull-table copy). Fine. - The v4 leader's own outbound subscription to the clone has no recorded cursor —
Starting time recorded in db <clone> 1 data undefined start time: 1— so it requests a full copy back from the brand-new clone, and the clone streams all 100 records back to the node they just came from. - The leader applies those redundant puts. Its apply path mints each audit entry with
previousVersion = 1, the "storage, substitute the previous timestamp" sentinel (previousVersion > 1 ? setFloat64(previousVersion) : PREVIOUS_TIMESTAMP_PLACEHOLDER). lmdb-js's instructed-write substitution puts 2.0 in that slot. - The presence of the previousVersion field is signalled only by
buffer[0] === 66(0x42 — the first byte of a float64 in the ms-timestamp range, i.e.[2^33, 2^49)).2.0encodes as0x4000000000000000, first byte0x40, so every reader (v4'sreadAuditEntryand harper's, they are byte-identical here) skips the field and parses the entire entry 8 bytes off. - The leader's own audit-log forwarding then walks those entries and decodes
recordIdout of the misaligned region. Usuallynull; when the misaligned walk lands on the record body's length byte it takes ordered-binary's number path and doesBigInt(<non-integer float>)→ theRangeErrorin this issue →.catch→close(1008)→ reconnect loop → the clone has no connected database socket and never receives the post-clone write. Both assertions fail.
Byte-level proof
A poisoned entry, straight out of the v4 leader's audit log:
400000000000000011000113686973746f726963616c5f6f72646572732d30427a01d59066560e002013... [0..7] 40 00 00 00 00 00 00 00 float64 2.0 <-- previousVersion; first byte 0x40, not 0x42 [8] 0x11 put | HAS_RECORD [9] 0x00 nodeId 0 [10] 0x01 tableId 1 [11] 0x13 recordId length = 19 [12..30]"historical_orders-0" [31..38]427a01d59066560e float64 version 1787198768741.378 [39] 0x00 username length 0 [40..] 20 13 "historical_orders-0" "historical_orders record 0"Misparsed (because byte 0 is not 66):
action = 64,nodeId = 0,tableId = 0,recordIdLength = 0→recordId = null,type = undefined, and the entry is then dropped asNot subscribed to table 0.And the CI value reverses cleanly to the same misparse:
4.94629614062414e-46unpacks (ordered-binary shifts the 9 key bytes by a nibble) to13 68 69 73 74 6f 72 69 6?=0x13+"historic…"— the length-prefixed id inside the record body, i.e. the misaligned walk had run past recordId, version and username into the value.Why it is intermittent
- The race is whether the leader's outbound connect to the clone lands before or after the clone has the data. In the failing CI runs it was delayed ~1.5 s by
this server does not have a certificate authority for the certificate provided by wss://<clone>retries; when it lands late, the clone already holds everything and serves the poisoned reverse copy. When it lands early the clone is still empty, the reverse copy is a no-op, and the run is green. - Getting a
RangeErrorrather than a silentnulladditionally needs the misaligned walk to hit a body byte in[8,24). And it only throws at all because the harness runs the nodes atlevel: debug: the v4 send loop islogger.debug?.('sending audit record', pt, mr.recordId), so above debug the getter is never invoked and the misparsed entries are skipped silently. A production leader at the default level does not crash — it just accumulates unreadable audit entries (whichread_audit_log, record history and audit cleanup all walk).
Deterministic repro
npm install harperdb@4into a scratch dir, patchcreateWebSocketto honour aKR_CONNECT_DELAY_MSenv var (a one-time delay before the leader's first outbound connect — it reproduces exactly what the CA retries did in CI), and runcloneFromLegacy.test.mjswithKR_CONNECT_DELAY_MS: '2500'in the legacy node's env. Every run: the leader takes the reverse full copy and 55 of the 100 applied entries come out with an undecodable recordId. Patched files and notes are in~/dev/tmp/737on my box.Fix direction
The trigger — and the thing worth fixing regardless of this test — is step 2. A brand-new clone provably holds nothing its leader needs, so a full copy back is always wrong: on a production v4 leader it re-ingests the leader's entire dataset into itself mid-migration, and poisons the leader's audit log while doing it.
Preferred: when a node finishes applying a base copy from a peer, hand that peer a resume cursor for itself (
[SEQUENCE_ID_UPDATE, T]— v4 honours it:case 143→end_txn, which persists the cursor). The peer then has a proven baseline and never asks for the reverse copy. Lossless in the fresh-clone case (no own-origin audit entries for that database yet); if there are own-origin entries, publishT= the oldest one, and if that predates retained history, skip and keep today's behaviour.Considered and rejected: sending
start_timeinadd_node_back(v4 does honour it) — but v4 and harper also stampstart_timeon the leader's self record, which replicates back to the clone and can suppress the clone's own full copy, i.e. it risks re-breaking #236.Separately worth a small hardening PR in core:
createAuditEntryshould never emit apreviousVersionwhose float64 does not begin with0x42, since that byte is the field's only presence signal — thepreviousVersion > 1guard is not the right test. That closes the same hole for a v5+LMDB deployment.- The v5 clone bootstraps from the v4 leader (
Metadata
Metadata
Assignees
Type
Fields
Priority
Summary
integrationTests/cluster/cloneFromLegacy.test.mjs("Clone from legacy v4 leader") failsintermittently on
Cluster Integration Tests 2/6 (Node.js v24). Two of its cases fail together:The proximate cause is in the log, repeated on the sending side:
That error comes from the
.catchon the audit-log forwarding loop inreplication/replicationConnection.ts('Error handling subscription to node'), which thenclose(1008, …)s the subscription — which is exactly why the follower ends up with no connecteddatabase socket and never receives the post-clone write. The value (
-1.49e-154) is a float64reinterpretation of unrelated bytes, so this looks like a misread field on the v4↔v5 audit path rather
than a legitimate value.
Frequency
Observed on
kris/2226-receive-queue-bound(harper-pro#735), 2 of 4 runs of the same shard atdifferent commits, passing the other 2 with identical code:
Not caused by that PR
harper-pro#735 changes only the replication receive path (an admission gate in
ws.on('message')). The failure is on the send path — the audit-log iteration insidesendAuditRecord's enclosing loop — and no BigInt conversion exists anywhere in that PR's diff. The50/50 behavior at fixed code says the same thing.
Related
harper-pro#236 ("cloneNode against a v4 leader never reaches Available (full-table-copy path broken
across v4↔v5)") is closed and describes the same test and the same end state. Either that fix left an
intermittent path, or this is a second cause with the same symptom — worth checking against that
issue's repro before treating this as new.
Why it is worth its own issue
The v4→v5 clone path is a migration-runbook step (§3a, the "recommended" path), so an intermittent
failure there is a customer-facing migration risk, not just CI noise. It also mimics a real
regression on any PR that touches replication, which costs a review cycle each time someone has to
rule it out — I just spent one doing exactly that.