Out-of-order audit walk still pegs replication receivers on 5.3.2: retried duplicate writes bypass both the dedup skip and #2684's floor check

@kriszyp

@kriszyp: follow-up to #2642, which you closed as fixed by #2684. It still reproduces on 5.3.2.

Summary

The #2642 stall still happens on harper-pro 5.3.2, which includes #2684. A replicated write far below the audit floor still runs the full out-of-order audit walk. The incoming write ties the stored record (same version, same origin), so precedesExisting is 0, and #2684's floor check only runs when precedesExisting < 0. The duplicate skip that would normally drop an exact tie is also bypassed, because the commit is a retry (stagedOwnAuditEntry: true). The walk then does an exact-start lookup with nodeId=undefined, iterating every per-origin transaction log (18 here) for a key that isn't retained. Each attempt repeats the scan, and the receiving worker stays at 100% indefinitely.

Environment

16-node cluster, rolled harper-pro 5.2.13 → 5.3.2 on 2026-10-20. RocksDB storage. The cluster was migrated from v4 on 2026-09-15 (same history as #2642).

Evidence (one node, captured with Debugger.pause, ~57 ms per worker)

Two receiver workers at utilization 1.0. They hold the data-DB replication legs from two different peers.
CPU profile: ~93% inclusive under Table.commit → RocksTransactionLogStore.get/getSync/getRange. Self time is in replayLogsGuards next (one thread) and the rocksdb-js iterator next (the other).
Both workers are processing the same record:
- image_cache put, sourceApply: true, origin nodeId=35 (the v4-era origin), viaNodeId 4 and 8 respectively
- txnTime / version = 1789444815347.8994 (2026-09-15T04:00:15Z), expiresAt = 2026-09-16T04:00:15Z (already expired)
Commit frame (Table.js dist, 5.3.2), identical on both threads:
- retry=true, stagedOwnAuditEntry=true
- existingEntry.version === txnTime, existingEntry.nodeId=35
- belowAuditFloor=false, walkSteps=2
Audit floor on this database (Symbol.for('audit-floor'), audit-resume-floor and audit-floor-bootstrap): all 1792539714879 = 2026-10-20T23:41:54Z, set at the 5.3.2 start. The write is five weeks below it.
Lookup frame: auditStore.get(1789444815347.8994, tableId=6, <id>, nodeId=undefined) → getRange({start, exactStart: true}) across logs=Array(18), foundExactStart=false. At the pause the iterators were reading entries timestamped 2026-10-19 and 2026-10-21, past the target key, still searching.
The data-DB replication cursors from those two peers are frozen at 2026-09-15T04:00:15Z, the same stretch as Out-of-order audit walk pegs a replication receiver for 24h+ on pre-retention replicated writes: no retention/expiry short-circuit before the walk, and a local-head lookup fans out across every origin log #2642.

Root cause (as read from 5.3.2 dist `Table.js`)

precedesExistingVersion returns 0 (a tie) because the stored entry has the same version and origin as the incoming write. Two guards that would stop the walk both miss this case on a retry:

The keyed duplicate skip (~3938) is disabled when a prior attempt staged this write's own audit entry:

if (isRocksDB && !replaying && !stagedOwnAuditEntry && dedupVersionCouldBeRetained(txnLogKey)) {

Skip the out-of-order audit walk below the retention floor, and stop its head lookup fanning out across every transaction log #2684's floor check (~3954) is gated on precedesExisting < 0, so a tie never reaches it:

if (isRocksDB && precedesExisting < 0) {
    const auditFloor = getAuditFloor(auditStore);
    belowAuditFloor = Number.isFinite(auditFloor) && txnTime < auditFloor;
}

The walk proceeds even though, as #2684's own comment says, the floor already determines its outcome. (The precedesExisting=1 visible in the paused frame was reassigned inside the walk, ~4062-4072.)

Possibly related (unverified)

On the examined node, the per-origin transaction log for the v4-era origin was created at 23:42:07Z, 16 s after the 5.3.2 start, and reached 77 files / 1.3 GB in about 1 h 50 m. A comment in commit says a failed attempt's audit entry survives the rollback, so repeated retries appending entries keyed at the 2026-09-15 log key would explain the growth. On another node, the same origin's log began growing again at 22:35Z, during the roll but before that node itself was upgraded.

Open question

Why the write needs a retry at all. One possibility: the same key arrives on two receiver threads at once (as captured above) and the two commits conflict. Not confirmed.

Suggested

Apply the floor check to ties as well (precedesExisting <= 0), or at least on the stagedOwnAuditEntry retry path, whenever txnTime < auditFloor.
Define a safe early exit for already-expired replicated writes #2873: skip already-expired replicated writes before the walk (this one expired 2026-09-16).
Bound the live out-of-order audit walk and target predecessor-log lookups #2872 / rocksdb-js#676: a nodeId-less exact-start lookup shouldn't iterate every origin log for an absent key.

Impact

Pinned-worker warnings on all 16 nodes. On the examined node, 2 receiver workers at 100%. Requests and health probes routed to a pinned worker stall: fresh-connection /status samples hung on 1/60, 1/20, 1/20 and 0/20 across four nodes. Ops calls that broadcast to all workers take ~5 s on the examined node. Replication from the affected peers is frozen. Restarts and upgrades don't help, because receivers resume at the same cursor.

Related: #2642, #2684, #2872, #2873, HarperFast/rocksdb-js#676

@DavidCockerill

Thanks for writing this up, Maurice. It matches what I found independently, and I can add a few things from paused frames on two nodes.

It reproduces on a second node. On another node in the same cluster, one receiver worker was paused at the same walk step. Its frame showed:

an image_cache put at 2026-09-15T04:00:15.983Z, a different record from the same stretch;
origin nodeId=35, viaNodeId 4;
retry=true and stagedOwnAuditEntry=true;
the stored entry has the same version and origin as the incoming write, belowAuditFloor=false, and walkSteps=2;
expiresAt 2026-09-16.

That node's floor is also its 5.3.2 start time. So this isn't specific to one node.

Step 2 looks up the same entry as step 1. In both paused frames, localTime at step 2 is still the write's own txnTime. Step 1 reads the write's own entry from origin log 35. That entry's predecessor resolves back to the same timestamp, and previousNodeId isn't stored, so step 2 repeats the lookup with nodeId=undefined and searches every origin log. The visited-entry guard doesn't catch this because it keys on ${nodeId ?? 0}:${localTime}: step 1 is 35:T and step 2 is 0:T. A narrow fix that doesn't depend on #2872: stop the walk when advanceToPreviousAudit yields the same localTime it just looked up.

The duplicate check could use the committed entry. !stagedOwnAuditEntry protects against a prior attempt's orphaned entry for a record that was never committed. In this case the existing entry, which keeps the pre-transaction version and audit chain, already has the same version and origin as the write, so the write is a duplicate whether or not a prior attempt staged its entry. A check against that entry should be safe on the retry path, and it would also catch ties above the floor, where the floor fix doesn't apply.

The receivers reconnect about every 10 minutes. On the first node, the two stuck legs map to the two pinned workers. One holds the leg from one peer and the other holds the other peer's leg. Since the 5.3.2 start, those workers reconnected to their peer 12 and 13 times, and the cursors never moved. That's consistent with each reconnect re-sending the same stretch, and with restarts not helping. It doesn't answer your open question about why the write needs a retry. Retries below 40 only log at debug level, so the logs don't show conflicts either way.

_{🤖 Generated by Claude Code (Claude Opus 5.5); posted via @DavidCockerill.}

Control comparison: a cluster without v4 history is unaffected.

A second cluster running the same application (same image_cache table), also upgraded to 5.3.2 the same night, shows none of this: no pinned workers, no "pinned at" / "JS execution taken too long" warnings, get_status ~20 ms, public /status 60/60 200.

The difference is migration history. Comparing exportIdMapping on one node of each:

Affected cluster: 16 current v5 nodes plus 19 v4-era node names from the 2026-09-15 bridge migration. nodeId=35, the origin of every stuck record captured so far, is one of those v4-era nodes.
Unaffected cluster: only its own 6 v5 nodes. It was never bridged from v4.

So the trigger appears to be replicated records that originated on v4-era nodes, not 5.3.2 or the workload itself.

Side note: the affected cluster's mapping also contains a node registered under the literal name "undefined" (id 51). Possibly unrelated, but noting it given the nodeId=undefined lookups above.

Third node in the same cluster: here the cost is in the keyed dedup lookup itself, without the retry flags. Plus why the stretch never ages out, and how restarts amplify it.

Captured today on 5.3.3 (which includes the #3377 backport of #3366): a CPU profile and Debugger pauses on the pinned workers of a third node.

Profile (3 pinned http workers, 10 s each): 92 to 96% of samples in one stack.

transaction.js onComplete
 -> DatabaseTransaction commit -> performCommit -> save
 -> Table.commit                      (dist Table.js:3952 = Table.ts keyed dedup lookup, ~L4830 in 5.3.3)
 -> RocksTransactionLogStore.get / getSync
 -> replayLogsGuards next
 -> rocksdb-js transaction log iterator next

Paused frames (2 workers, each pause held about 2 s):

image_cache puts, versions 2026-09-15T04:00:23Z and 04:04:24Z, origin nodeId=35, viaNodeId 3 and 4 (two different relaying peers)
isNotification=true, sourceApply=true, replaying=false
precedesExisting=0: stored entry has the same version and origin, belowAuditFloor=false
retry=undefined, stagedOwnAuditEntry=undefined, so the dedup guard (isRocksDB && !replaying && !stagedOwnAuditEntry && dedupVersionCouldBeRetained(txnLogKey)) is taken
getSync(key=txnTime, tableId=6, recordId, nodeId=35) -> getRange({ start: key, exactStart: true, log: 35 })
rocksdb-js iterator frame: foundExactStart=false, about 15.9 MB into a 16.7 MB log segment. On one worker the iterator's current timestamp was ~3 min before the start key, on the other ~63 s after it. getSync returns on the first non-matching entry, so the time is in positioning the iterator, which appears to scan the segment linearly looking for an exact start it doesn't find.
expiresAt 2026-09-16 on both records

So in the Oct 21 capture (retry=true) the dedup was bypassed and the walk ran; here the dedup runs and is itself the expensive part. Either way the same v4-origin entries cost seconds per replayed write. Bounding the exact-start positioning (or failing fast when the key isn't present) looks as important as the walk fix.

Why the stretch never ages out. This node's oldest retained audit time is 2026-09-15T04:00:15Z, 38 days later. Origin 35 is a v4-era node that stopped writing at the cutover. Retention removes whole files but keeps the newest file per origin, so origin 35's last file is never purged and those entries stay available to replay on every receiver reconnect. The records themselves expired on Sep 16. Possible mitigations alongside the code fix:

Let retention purge an origin's last file once it is past retention and the origin is inactive.
Skip applying a replicated write whose expiresAt is already in the past.

Restarts amplify it. The node went through 3 http worker restarts in about 13 minutes (two overlapping rolling restarts from a replicated deploy_component with restart: "rolling", plus one manual). Pinned workers went from about 2 to 13, and request-path p95 from about 65 ms to about 470 ms and stayed there, while other nodes that restarted recovered within minutes. Receivers resume at the same Sep 15 position after each restart, and with legs spread over a fresh set of workers, more threads end up stuck. The node is now out of rotation as a mitigation.

Dedup retried replicated writes whose duplicate already committed

Navigation Menu

Repository navigation

Out-of-order audit walk still pegs replication receivers on 5.3.2: retried duplicate writes bypass both the dedup skip and #2684's floor check #3361

Summary

Environment

Evidence (one node, captured with Debugger.pause, ~57 ms per worker)

Root cause (as read from 5.3.2 dist `Table.js`)

Possibly related (unverified)

Open question

Suggested

Impact

Metadata

Assignees

Labels

Type

Fields

Projects

Milestone

Relationships

Development

Out-of-order audit walk still pegs replication receivers on 5.3.2: retried duplicate writes bypass both the dedup skip and #2684's floor check #3361

Description

Summary

Environment

Evidence (one node, captured with Debugger.pause, ~57 ms per worker)

Root cause (as read from 5.3.2 dist Table.js)

Possibly related (unverified)

Open question

Suggested

Impact

Activity

DavidCockerill commented on Oct 21, 2026

maurice-harper commented on Oct 21, 2026

maurice-harper commented on Oct 23, 2026

Metadata

Metadata

Assignees

Labels

Type

Fields

Projects

Milestone

Relationships

Development

Issue actions

Root cause (as read from 5.3.2 dist `Table.js`)