Replication: subscriber silently skipped ~700k backlogged writes during a write-conflict storm — cursor stayed "current", no base-copy triggered, no error anywhere

[harper-joseph]

Summary

During a bulk table migration on a 4-node cluster, the replication stream for one database silently dropped ~700k of 803k writes on all three subscribing peers. Every health surface looked fine: sockets connected, backpressure 0, lastReceivedRemoteTime current, and new writes kept replicating normally after the incident window. No base-copy/resync was triggered and no error or warning was logged on any node. The gap was only discovered by manually comparing SELECT COUNT(*) across nodes.

This is data-loss-grade divergence with a fully healthy-looking cluster — a concrete field case for #432 (cursor correctness & divergence detection).

Environment

• harper-pro 5.1.26 (docker harperfast/harper-pro:5.1.26)
• 4-node Fabric cluster prerender.kohls.harperfabric.com (yc0-us-central-1 / cd5-us-southeast-1 / e9v-us-east-1 / v3t-us-sea-1)
• Database render_service, table Target (string PK url), replicated (no residency pinning on this table)

Timeline (2026-08-02, ~17:00–19:30Z)

1. A component migration on yc0 bulk-wrote 803,324 rows into render_service.Target (chunked writes over ~30 min).
2. Concurrently, duplicate sweeps (same component, other workers) raced the migration and died with repeated "After 40 retries, unable to commit transaction" — i.e., the table was under a sustained write-conflict storm while the subscriber stream was consuming the same backlog.
3. Peers ended up with 103,658 rows each. Delivery stopped mid-backlog, roughly coincident with the conflict storm.
4. Writes issued after the window replicated instantly and correctly (verified with a control-row write that appeared on all peers within seconds).

Key observations

• The skipped range is not a clean prefix. Peer copies had holes: rows at higher PK offsets were present while earlier rows were missing — consistent with the subscriber advancing its resume cursor past transactions it never applied (or the sender skipping log segments), rather than a simple disconnect.
• cluster_status on all nodes: connected: true, backpressure 0, lastReceivedRemoteTime current — before, during, and after.
• No "predates retained transaction-log history… forcing a bounded base-copy resync" lines anywhere (leader-side stale-cursor handler, replication/replicationConnection.js ~line 3046 in the 5.1.26 dist, never fired). No full-copy triggered either (the no-resume-cursor path near ~4160, where the rapid-reconnect stress: follower permanently loses replication backlog after restart churn (data loss; fast-skip ruled out) #426 comment lives, correctly did not apply — cursors existed and looked "valid").
• So the cluster considered the cursors valid while ~700k committed, audited transactions between them and head were never delivered/applied — and nothing detected the divergence.

Impact

3 of 4 nodes served a 103k-row view of an 803k-row table for ~2.5 h. Downstream logic that treats a local miss as "row does not exist" took destructive actions (deleting sibling schedule rows). Nothing in Harper surfaced the problem; discovery was a human noticing a wrong dashboard count.

Suspected area / repro hypothesis

Bulk sequential writes to one table + concurrent conflicting writers on the same keys (enough to produce "After 40 retries, unable to commit transaction" aborts) while ≥1 subscriber is consuming the resulting backlog over the per-database stream. Suspect the interplay between the conflict/retry machinery's audit entries and the subscriber's cursor advance — the cursor appears to have jumped over a large undelivered span while remaining "valid" to the leader's retention check.

Recovery that worked (for the record)

Re-emitting every row from the holder via ops-API upsert with the complete record (161 × 5k chunks) pushed the backlog through the same stream successfully; peers converged to 803,324 with zero retries. Note for anyone repeating this: update/upsert on an existing row audit as a patch delta of only the supplied fields (core/resources/Table.js ~1887), and a subscriber missing the base row stores the patch body verbatim (tracked.js updateAndFreeze: if (!target) return changes) — so a partial-field "touch" re-emit would have materialized field-stripped stubs on the peers. Re-emits must carry every field.

Asks

1. Root-cause the cursor advance across an undelivered span under write-conflict storms.
2. Divergence detection (Replication W2: Cursor correctness & divergence detection #432): even a cheap periodic per-table count/hash comparison between publisher and subscriber would have caught this in minutes instead of hours.

---

Filed by an agent (Claude) from the incident session; evidence gathered live from the cluster (UDS ops, docker logs, 5.1.26 dist source).

[harper-joseph]

Follow-up with a precise timeline from the node logs (all times 2026-08-02 UTC) — this narrows the repro considerably. The failure was two distinct events: a delivery stall during the conflict storm, then a worker restart ~30 min later that converted the stall into a permanent cursor skip.

Timeline (cd5 as the observed subscriber; yc0 the publisher):

• 18:01:22 — http workers restart on all nodes (component deploy). All replication sockets bounce and reconnect cleanly within ~1s (code 1006 → reconnect). No full-copy triggered for render_service (cursors present).
• 18:02–18:12 — bulk migration writes 803,324 rows to render_service.Target on yc0 (~90k rows/min).
• 18:03:49 and 18:04:46 — two After 40 retries, unable to commit transaction aborts on yc0 (concurrent duplicate sweeps racing the migration).
• ≈18:04:00 — cd5 stops applying. It ended with 103,658 rows; per the migration's progress logs (100k targets created by 18:03:55, 130,325 by 18:04:46), the cutoff lands squarely between the two conflict aborts. No restart, no crash, no OOM anywhere in this window (dmesg clean); the socket stayed connected and lastReceivedRemoteTime stayed current.
• 18:04 → 18:33 — the stream delivers nothing further from the migration backlog (~700k writes), while reporting healthy.
• 18:33:43 — http workers restart on all nodes (next component deploy). Sockets bounce; on reconnect the subscriber resumes at/near head rather than at its ~18:04 apply point. The 700k-write span is never re-delivered.
• Everything written after 18:33 replicated normally (verified with control writes).

Implication: during the 18:04–18:33 stall, the persisted resume cursor kept advancing (or was already ahead) without the records behind it being applied — so the 18:33 reconnect's subscription request legitimately (from the leader's view) asked to skip the span. This is the same hazard class the blob-drain cursor-clamping code guards against (the #426-adjacent seqUpdateEndTxn watermark logic): sequence/watermark updates persisting a cursor past undelivered content.

Refined repro hypothesis: (1) bulk-write a table with enough concurrent conflicting writers to produce After 40 retries aborts while a subscriber consumes the backlog; (2) observe the subscriber's apply stall while its cursor keeps advancing via watermark updates; (3) restart the subscriber (or bounce the connection) mid-stall; (4) reconnect resumes at head, span silently lost.

Operational corollary worth documenting even before a fix: a worker restart while a replication stream is stalled/lagging converts a recoverable stall into a permanent silent skip — and nothing in cluster_status distinguishes "current" from "stalled with an advancing cursor". Divergence detection (#432) would have caught this before the fatal restart.

Note: the concurrent page_cache blob errors on these connections ("Blob file not found at source … advancing the resume cursor past it", #388) look separate — that's lag + source-side blob eviction — but they demonstrate the same pattern of cursor advancement past undelivered content.

— agent-filed follow-up (Claude), same incident session

[kriszyp]

Investigation update: this is a cursor-advance-over-skipped-records defect, not a delivery stall

Code references below are against harper-pro main @ 2aed45a9 (v5.2.1) and its core pointer eb702ee52. I diffed the three load-bearing blocks between v5.1.26 and main — skipAuditRecord(), the matchesSubscription predicate, and the receiver's SEQUENCE_ID_UPDATE handling — and they are byte-identical. Whatever this is, it is not fixed on main.

The mechanism

skipAuditRecord() (replication/replicationConnection.ts:3723) arms a 300 ms timer (SKIPPED_MESSAGE_SEQUENCE_UPDATE_DELAY, :317). When it fires it does a direct ws.send([SEQUENCE_ID_UPDATE, currentSequenceId]) (:3732). On the receiving side (:3112) that is turned straight into an end_txn via seqUpdateEndTxn(...), and core's apply loop persists it as the durable resume cursor (core/resources/Table.ts:757, applied at :856).

So "I deliberately did not send you these records" and "I delivered these records" are indistinguishable to the subscriber. The resume cursor advances over undelivered content by design, and every one of the five skip predicates logs only at debug or trace:

predicate	site	log level
LOCAL_ONLY	:3590	trace
not subscribed to table	:3606	debug
send-excluded table	:3611	trace
node/timeRange mismatch	:3659	trace (DEBUG_MODE only)
residency-excluded	:3689	trace

That single fact accounts for the whole symptom set at once: socket healthy, backpressure 0, the cursor stays "valid" so the retention check never forces a base copy, nothing logged at default level, and the 18:33 reconnect legitimately asking to resume past the span.

The decisive evidence

The most load-bearing observation in the follow-up comment is that lastReceivedRemoteTime stayed current throughout the 18:04–18:33 blackout.

That field maps to RECEIVED_VERSION_POSITION (replication/clusterStatus.ts), which has exactly three writers — :3125 (the SEQUENCE_ID_UPDATE handler), :4310 (inline REMOTE_SEQUENCE_UPDATE), and :4447 (the record-batch path). All three are data-plane. No keepalive, ping, or liveness path writes it (liveness has its own LAST_LIVENESS_TIME_POSITION).

Zero records applied, plus a remote version that kept advancing, therefore means the sender was actively walking the backlog and skipping every entry while emitting periodic sequence updates. This was not a stalled sender and not a wedged receiver.

Candidates eliminated

Two plausible-looking mechanisms are ruled out by the code, recorded so nobody re-chases them:

• The sender's table map going stale mid-connection. No. Replicator.subscribe() (replication/replicator.ts:407) replaces the subscription object only if (!subscription?.auditStore), and carries tableById over by reference — so tables registered later mutate the same array the live connection holds.
• The self-catchup endTime entry clobbering the publisher's subscribedNodeIds slot. No. getIdOfRemoteNode allocates lastId + 1 and never returns 0 (core/resources/nodeIdMapping.ts:91), and the local node is always id 0, so the two subscription entries cannot collide onto one index.

Leading hypothesis — not yet demonstrated

Flagging this explicitly as a hypothesis. subscribedNodeIds is indexed by getIdOfRemoteNode(name, auditStore) evaluated on the publisher, while the publisher's own writes carry nodeId: 0. Those line up only if the name the subscriber uses for yc0 is exactly yc0's own getThisNodeName().

getIdMappingRecord actively reassigns ids when the local node name changes (core/resources/nodeIdMapping.ts:21): the previous local hostname is bumped off id 0 to lastId + 1, and the new name takes 0. If a container restart changed yc0's resolved node name, every subsequent yc0-originated record would carry nodeId: 0 while the subscriber's entry sat on the bumped id — leaving subscribedNodeIds[0] undefined, matchesSubscription false, and every record skipped with the cursor advancing. The two deploy restarts bracket the window, which is suggestive but not evidence.

A second, independent defect found en route (bounded)

currentSequenceId = key is assigned before await sendAuditRecord(...) (:4256), and the frame only flushes at transaction boundaries. The guard sentSequenceId + 150 < currentSequenceId compares epoch-millisecond sequence ids, so it passes whenever a single transaction spans more than 150 ms of audit time — routine for a 5k-row migration chunk. The SEQUENCE_ID_UPDATE then goes out on a direct ws.send that bypasses the frame buffer and can overtake records still sitting in it.

Harmless in steady state, because those records arrive moments later. Not harmless if the connection drops in between — which is exactly what the 18:33:43 worker restart was. Maximum loss is one transaction (~5k rows), so this cannot explain 700k; it is a real separate bug, not the primary cause here.

Repro status

Instrumented main with an env-gated trace attributing every skip to its predicate and logging each cursor advance. backlogRecovery (OFFLINE=1, KEYS=200) converged cleanly — {"A":200,"B":200,"C":200,"D":200} — and the only skips exercised were correct LOCAL_ONLY skips on system tables. The generic backlog shape does not reproduce this; that path is what #452 already fixed.

What the run did show is that the cursor advance fires routinely even on a fully healthy cluster, pushing a peer's durable resume cursor roughly 1.35 s of sequence-space past the last transaction actually flushed to it — on the order of 2,000 records at this incident's write rate. The unsafe primitive is continuously exercised in production. It only needs one wrong skip to become silent loss.

Related: the After 40 retries aborts are themselves a known-fixed defect

Worth separating out, because it changes how the trigger should be read. harper-pro 5.1.26 locks @harperfast/rocksdb-js at 2.4.1, which does not contain rocksdb-js commit 45f11007 "fix(txn): align ERR_TRY_AGAIN with the IsBusy reset path" (first released in 2.5.0; zero IsTryAgain occurrences in 2.4.1's transaction.cpp).

Without it, resetTransaction fires only on IsBusy, so a TryAgain commit — an optimistic snapshot stranded outside the memtable window after a flush, which is exactly what sustained bulk writes produce — re-checks the same stranded snapshot forever. That is precisely the After 40 retries, unable to commit transaction in core/resources/DatabaseTransaction.ts:938.

Secondarily, 2.4.1's publish gate is !status.IsBusy(), so a failed TryAgain still called commitFinished, publishing transaction-log entries for a transaction whose data was rolled back. That produces phantoms (peers getting more data, not less), so it is not the 700k-loss mechanism — but it does mean the conflict storm described here was itself a defect rather than ordinary contention.

To be clear on one point, since it is easy to get backwards: 2.4.1 does contain the cross-column-family transactional read fix (#717, backported in rocksdb-js #732). The v5.1 line is not exposed to that one.

Ask: three greps would settle this

The remaining question is which predicate misfired. Rather than keep guessing, three checks against the retained publisher (yc0) logs would discriminate between all remaining candidates in one round-trip:

1. grep -c "Message too large to send" hdb.log — checkExcessMessageSize (:3867) drops an oversized frame and returns without sending it, while the next transaction's sequence update advances the cursor past the dropped records. This logs at error level, and the report says no errors were seen — but it is worth confirming it was actually grepped for, because the failure mode fits.
2. Whether Not subscribed to table appears anywhere, if debug-level logs were retained.
3. Whether yc0's node name or container hostname changed across the 18:01:22 and 18:33:43 restarts — this directly tests the leading hypothesis above.

Also useful, if it can still be recovered: whether the 103,658 count was measured independently on each of the three peers, or observed once and assumed uniform. Three peers landing on an identical count is strong evidence for a deterministic delivery cut over anything read-side or per-node.

---

Investigated by an agent (Claude Opus 5). The mechanism class is well supported by the code and by the reporter's own lastReceivedRemoteTime observation; the specific misfiring predicate is explicitly still a hypothesis.