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

## Summary

On a 16-node harper-pro **5.2.12** Fabric cluster (rocksdb-js 2.9.1), two `data` replication legs from one sender have committed nothing for over 24 hours. On each receiver the worker thread that owns the socket sits at 100% CPU inside `Table.commit`'s out-of-order audit reconciliation walk. Each walk step is `auditStore.get(localTime, tableId, id, nodeId)` → `RocksTransactionLogStore.getSync` → `getRange({ start, exactStart: true, log: nodeId })`, and on these nodes one step costs minutes, because:

1. The incoming writes are 2.5 days stale (older than the receiver's audit-retention floor, and already past their own `expiresAt`), so the walk can never reach `txnTime` and always walks the full retained chain. The retention guard added in #1486 gates only the two *keyed dedup* lookups and explicitly left the walk untouched.
2. The existing record head is a local write, so `existingEntry.nodeId` is `undefined`. The walk passes that raw to `auditStore.get`, and `RocksTransactionLogStore.getRange` treats `log: undefined` as "aggregate over every log", so every step opens 17 per-origin logs (30 to 37 GB each here) and each log that does not contain the exact timestamp scans to end-of-log (rocksdb-js#676).
3. Nothing on the live-delivery path bounds or yields the walk, so one record freezes the batch, the resume cursor never advances, the sender's receive watchdog re-terminates, and the same stretch is re-streamed forever.

The same CPU signature was seen in harper-pro#480 and fixed for the keyed dedup lookups in #1486. This is the walk-step lookup, on much larger logs.

## Environment

- Cluster: `[customer-cluster]`, 16 nodes, harper-pro `5.2.12`, `@harperfast/rocksdb-js` `2.9.1`, Node v24.21.0, 50 http threads per node.
- Config: `logging.auditLog: true`, `auditRetention: 3d`, `replication.databases: "*"`, `storage.rocks.blockCacheSize: 20937965568`.
- Sender: `[sender]` (the v4→v5 bridge node; it received the `data` DB one-way from the legacy v4 cluster until cutover on 2026-09-15 ~04:08Z).
- Wedged receivers: `[receiver-A]` (thread `http/19`) and `[receiver-B]` (thread `http/22`). The other 13 peers drained the same stream.
- Table: `data.image_cache` (per-record `expiresAt`, high churn, written locally on every node by cache fill).
- Per-origin `data/transaction_logs` on the receivers: ~2,000 files / 30 to 37 GB **per origin**, 17 origins (~430 GB `data` dir on receiver-A, ~443 GB on receiver-B). Healthy `healthy-peer` is the same order (40 GB per origin), so log size alone is not the differentiator.

### Affected versions (checked in `resources/Table.ts` on each ref, not release notes)

| Line | Ref | Walk | Retention gate at walk entry | `nodeId` passed raw to `auditStore.get` |
|---|---|---|---|---|
| v5.2 (latest) | `v5.2.13` (2026-09-15) | `:2698` | none | `:2707` |
| v5.1 (latest) | `v5.1.27` | `:2161` | none | `:2170` |
| v5.3 | `v5.3.0-alpha.1` | `:3271` | none | `:3283` |
| main | `1c312feb` (2026-09-16) | `:3728` | none | `:3740` |
| v4 (latest) | harperdb `release_4.7.38` | `:1663` | n/a | n/a |

Every v5 line carries the same three gaps; the only nearby change on `main` is the dedup lookups comparing `txnLogKey` instead of `version` (#2497), which does not touch the walk step or its entry condition. **v4 has the walk but not the failure mode:** on 4.7.38 the step is `auditStore.get(localTime)` against the LMDB audit store keyed by local audit time, a B-tree point read, with no per-origin log files and no retention purge to fall below (the v5 comment says the same: "LMDB's exact lookup is O(log n), not a log scan"). v4's walk is unbounded (no 1000-step cap), which is the original #1114 concern, not this one.

## Field evidence (read-only, 2026-09-16 03:35 to 03:50Z)

### Sender-side `cluster_status` on [sender] (data DB only)

Commit confirmations frozen since minutes after the bridge stream ended; the message being sent is 2.5 days old:

```
[receiver-A] data connected=true backPressurePercent=60.1 → 82.8 → 83.5 lastCommitConfirmed=Tue, 15 Sep 2026 04:03:26 GMT
sendingMessage=Sat, 12 Sep 2026 22:36:33 GMT → 22:38:50 → 22:51:04 (03:35Z / 03:38Z / 03:48Z snapshots)
[receiver-B] data connected=true backPressurePercent=99.6 → 100.0 → 98.7 lastCommitConfirmed=Tue, 15 Sep 2026 04:07:47 GMT
sendingMessage=Sun, 13 Sep 2026 02:00:17 GMT → 02:00:17 → 02:01:11
```

All 13 other `data` legs: `backPressurePercent=0`, `lastCommitConfirmed` current. `redirects` and `system` legs to receiver-A/receiver-B: current.

### Receiver-side `cluster_status` (socket from [sender], data DB)

```
receiver-A: lastReceivedStatus=Receiving lastReceivedVersion=1789445006649.9485 (2026-09-15T04:03:26.649Z) identical at 03:36Z and 03:39:40Z
receiver-B: lastReceivedStatus=Receiving lastReceivedVersion=1789445281601.5303 (2026-09-15T04:08:01.601Z) identical at 03:36Z and 03:39:40Z
```

Pre-cutover snapshots (2026-09-15 03:50Z) show both legs current (`ver=2026-09-15T03:50:27Z`), so the freeze began between 03:50 and 04:03/04:08Z on Sep 15, i.e. on the tail of the bridge stream. The sender's own log shows its receive watchdog firing on nearly every peer's `data` leg at 04:05 to 04:10Z (`Receive watchdog: no ping from … (db: "data") for 60000ms`), so the whole cluster stalled on this stretch; 13 nodes got through it.

### Thread state on the receivers

`top -H` inside the container: one `http` thread at 99.9% (receiver-B) / 72.7% (receiver-A) with four `V8Worker` GC helpers at ~63% each; `docker logs --since 30h`:

```
receiver-A: 1625 × "[http/19] [warn]: JavaScript execution has taken too long and is not allowing proper event queue cycling …"
receiver-B: 1744 × "[http/22] [warn]: JavaScript execution has taken too long …"
hourly counts climb through the day: 46 (04Z) … 61, 65, 75, 78, 87, 95 (14Z) …
0 × "Out-of-order audit reconciliation exceeded depth cap" on either node in 30h
0 × "coordinated retries" / conflict lines
```

`system_information` per-thread heap is ~0.1 GB, but `Runtime.getHeapUsage` on the pegged thread reports `backingStorageSize` 38.9 GB (receiver-A) / 31.8 GB (receiver-B): mmapped transaction-log files. `/proc//maps` shows 902 (receiver-A) / 2,208 (receiver-B) `.txnlog` mappings spread across **all** origin dirs (`[peer-C]` 160/278 files, `[peer-D]` 155/277, `local` 99/195, …) versus 233 on healthy healthy-peer. receiver-B's process RSS is 96.6 GB against ~62 GB on healthy peers.

### CPU profile of the pegged thread (8 s, 500 µs sampling, `Profiler.start/stop` via the in-container inspector)

receiver-A `http/19` (port 9248), 13,534 samples:

```
13422 99.2% next @ @harperfast/rocksdb-js/dist/index.cjs:3673
99 0.7% next @ @harperfast/harper-pro/dist/core/resources/replayLogsGuards.js:138
11 0.1% getLogMemoryMap @ @harperfast/rocksdb-js/dist/index.cjs:3761

inclusive: 100% of samples under
onComplete (transaction.js:64) -> commit (DatabaseTransaction.js:871) -> save (:789)
-> commit (Table.js:2357) -> get (RocksTransactionLogStore.js:187) -> getSync (:190)
-> getRange (:259) -> updateIterators (:312) -> safeNext (:298)
-> next (replayLogsGuards.js:138) -> next (rocksdb-js index.cjs:3673)
```

receiver-B `http/22` (port 9251), 13,587 samples: 92.7% in the same rocksdb-js `next`, 2.4% GC, 1.5% idle, 94.6% inclusive under `Table.commit`.

### `Debugger.pause` on the pegged threads (two pauses each, ~40 ms, 8 minutes apart)

Every pause landed inside the walk at `Table.js:2576` (`auditStore.get(localTime, tableId, id, nodeId)`), at `walkSteps=1`, on a different record each time (so roughly one record per several minutes, and no record has ever completed a 1000-step walk). Frame locals, verbatim:

**receiver-A, 03:40Z** (single-log lookup path, `nodeId=13`):
```
commit txnTime=1789252606191.1467 (2026-09-12T22:36:46Z) localTime=auditedVersion=1789487641353.3704 (2026-09-15T15:54:01Z)
oldestRetainedAuditTime=1789271188359 (2026-09-13T03:46:28Z) nodeId=13 succeedingUpdates=Array(0) auditRefsToVisit=Array(0)
id=[record-1] fullUpdate=true
getSync key=1789487641353.3704 tableId=6 nodeId=13
rocksdb-js query: start=1789487641353.3704 exactStart=true foundExactStart=false logId=6856 latestLogId=6897 position=1051213
```

**receiver-A, 03:48Z** (aggregate lookup path, `nodeId=undefined`):
```
commit txnTime=1789252740915.2559 (2026-09-12T22:39:00Z) localTime=auditedVersion=1789468131071.8613 (2026-09-15T10:28:51Z)
oldestRetainedAuditTime=1789271280204 (2026-09-13T03:48:00Z) nodeId=undefined walkSteps=1 auditWalkCapped=false precedesExisting=-1
existingEntry{ localTime=1789468131071.8613 version=1789468131071.8613 expiresAt=1789554531071 nodeId=undefined additionalAuditRefs=undefined size=479 }
options{ isNotification=true nodeId=35 viaNodeId=8 expiresAt=1789339140916 (2026-09-13T22:39:00Z) isCopyApply=false async=true }
context{ table=image_cache type=put nodeId=35 viaNodeId=8 timestamp=1789252740915.2559 sourceApply=true beginTxn=true }
getSync key=1789468131071.8613 tableId=6 nodeId=undefined
getRange options{ start=1789468131071.8613 exactStart=true log=undefined } logs=Array(17) iterators=Array(17) i=5
rocksdb-js query: start=1789468131071.8613 exactStart=true foundExactStart=false size=16777123 position=5776645
```

**receiver-B, 03:40Z** (aggregate path):
```
commit txnTime=1789264099173.0627 (2026-09-13T01:48:19Z) localTime=1789449662182.5654 (2026-09-15T05:21:02Z)
oldestRetainedAuditTime=1789271181153 (2026-09-13T03:46:21Z) nodeId=undefined walkSteps=1
id=[record-2]
getRange logs=Array(17) iterators=Array(17) i=6 rocksdb-js: foundExactStart=false size=16777005 position=14581713
```

**receiver-B, 03:48Z** (aggregate path):
```
commit txnTime=1789264104905.0273 (2026-09-13T01:48:24Z) localTime=1789446871730.5017 (2026-09-15T04:34:31Z)
oldestRetainedAuditTime=1789271268640 nodeId=undefined walkSteps=1 precedesExisting=-1
existingEntry{ version=1789446871730.5017 expiresAt=1789533271730 nodeId=undefined additionalAuditRefs=undefined }
options{ nodeId=35 viaNodeId=8 expiresAt=1789350504905 (2026-09-14T01:48:24Z) isCopyApply=false }
id=[record-3]
getRange logs=Array(17) iterators=Array(17) i=3 rocksdb-js: foundExactStart=false size=16777069 position=12125104
```

Reading those off: every incoming write is a `sourceApply` `put` from origin node id 35 (not one of the 16 cluster nodes; sender is the only node with a `[v4-bridge-origin]` per-origin log, so this is the v4 bridge origin) relayed via node 8 (`[sender]`). Its version is ~2.5 days older than the local head (`precedesExisting=-1`), older than `oldestRetainedAuditTime`, and its `expiresAt` is one to two days in the past. The local head has `nodeId=undefined` (a local write), so `nodeId` reaches `getSync` as `undefined` and `getRange` fans out to all 17 logs.

### Where the stale writes came from

On the sender, the v4-origin log `data/transaction_logs/[v4-bridge-origin]/` holds 523 files (3104.txnlog written 2026-09-12T20:41Z … 3625.txnlog written 2026-09-15T04:08:10Z, `txn.state` 04:08:20Z). The receivers' cursors (04:03:26 / 04:07:47Z) sit inside the last two files, so the poisoned stretch is the final ~5 minutes of the bridge stream: records the v4 source re-sent with Sep 12/13 versions (the known v4 restart-triggered resume-replay from a pinned position). The per-origin log volume that makes each step so expensive comes from the pre-#809 15× relay amplification (harper-pro#809, #2485), with 3-day retention.

## Mechanism, with the deployed code

`Table.js` (5.2.12 dist, line 190) `const MAX_OUT_OF_ORDER_AUDIT_DEPTH = 1000;`. The out-of-order block (dist 2436-2700; `main` @ 1c312feb `resources/Table.ts` 3560-3760; identical shape on tag `v5.2.13` at 2591-2707):

```js
// dist Table.js:2480 — the retention guard from #1486. It gates the two KEYED dedup lookups only.
const dedupVersionCouldBeRetained = (version) => { … return version >= oldestRetainedAuditTime; };
if (isRocksDB && !stagedOwnAuditEntry && dedupVersionCouldBeRetained(txnTime)) {
const priorAudit = auditStore.get(txnTime, tableId, id, options?.nodeId); // :2512, skipped here (pre-retention)
…
}
let localTime = existingEntry.localTime;
let auditedVersion = existingEntry.version;
let nodeId = existingEntry.nodeId; // undefined for a local head
…
do {
while (localTime > txnTime || (auditedVersion >= txnTime && localTime > 0)) { // :2567 — enters regardless of retention
if (isRocksDB && ++walkSteps > MAX_OUT_OF_ORDER_AUDIT_DEPTH) { auditWalkCapped = true; break; }
const auditRecord = auditStore.get(localTime, tableId, id, nodeId); // :2576 — raw nodeId, no retention gate
if (!auditRecord) break;
…
localTime = auditRecord.previousVersion; nodeId = auditRecord.previousNodeId;
}
…
} while (nextRef);
```

The comment directly above the guard already documents the cost model this issue hits, for the other lookups (dist :2497, main :3582):

> On RocksDB an exactStart miss scans the whole log to end-of-log (~17ms each in the field, all 100% misses while applying aged hdb_analytics during a system-DB copy, pegging the worker at ~100% CPU — harper-pro#480).

`RocksTransactionLogStore.js` (dist :187-200; main `resources/RocksTransactionLogStore.ts:181-197`):

```js
getSync(key, tableId, recordId, nodeId) {
…
for (const entry of this.getRange({ start: key, exactStart: true, log: nodeId })) {
if (entry.recordId === recordId && entry.tableId === tableId) return entry;
if (entry.version !== key) return;
}
}
// getRange (dist :259 / main :340):
if (options.log !== undefined) { /* one log */ } else { /* updateIterators(): one iterator per log, all 17 */ }
// addLogToMaps (main :210): const nodeId = logName === 'local' ? 0 : getIdOfRemoteNode(logName, this)
```

So `log: undefined` is not "the local log", it is "every log". `main` normalizes the identity string with `nodeId ?? 0` (`:3729`) but still passes raw `nodeId` to `auditStore.get` (`:3740`).

rocksdb-js `TransactionLog.prototype.query` (2.9.1 `dist/index.cjs:3627-3755`): `_findPosition(start)` is a running-maxima lower bound; in `exactStart` mode `matchesRange` is false until `timestamp === start`, and the loop continues through `getLogMemoryMap(logBuffer.logId + 1)` to the last file before returning `done`. That is rocksdb-js#676 ("no upper bound on its forward scan … turns a point lookup into an O(n) scan"). With 16 of 17 logs never containing the key and each log 30 to 37 GB, one walk step is 16 full-log scans.

Net effect per incoming record: the guard skips the cheap dedup (pre-retention), the walk is entered (`localTime > txnTime`), step 1 fans out over ~500 GB of logs, and even after step 1 the walk has up to 999 more steps before it reaches the cap, because `txnTime` is below everything retained. Since the apply loop commits per batch, one such record blocks the batch, the cursor never advances, and after every reconnect the sender re-streams from the same cursor.

## Why this is not a duplicate

- #1114 (closed) — same walk, diagnosed as heap growth during full-copy; the fix was the 1000-step cap. The cap is irrelevant when one step takes minutes. Its last comment already reported the ping-timeout/wedge presentation.
- #1310 (merged) — up-front keyed dedup before the walk. Does not engage: the incoming writes are not duplicates, and the lookup is skipped for pre-retention versions anyway.
- #1486 (merged) / harper-pro#480 (closed) — same "exactStart miss scans to end-of-log" CPU storm, fixed by gating the keyed dedup lookups on retention. The PR states: "The `previousVersion` audit-chain walk and all LMDB paths are untouched." This issue is that walk.
- #1316 (closed) — bounded the *boot replay* path with a wall-clock limit (`REPLAY_WALL_CLOCK_LIMIT_MS`) and listed "skip the resequencing walk / bound cumulative per-record walk cost" as directions; the live-delivery path got none of that.
- harper-pro#399 (open) — reduce the volume of proxied re-deliveries. Complementary; the writes here are not re-deliveries, they are stale first deliveries from a bridge replay.
- rocksdb-js#676 (open) — the storage-side bound for absent-timestamp `exactStart` scans (suffix-minimum index). Would shrink each miss; it does not stop the walk from being entered or from fanning out to 17 logs.
- #2412 / #2519 / #2497 / harper-pro#812 / harper-pro#790 — dual-clock model (record version vs. log key). Addresses why exact-version seeks are not index hits in the first place; long-range.
- #2593 (open) — the three audit-floor implementations disagree. Related: this issue wants the floor consulted at a fourth site (walk entry), so it should use whichever contract #2593 settles on.
- harper-pro#815 (open PR) — recovers legs wedged by a stale `done` iterator on the sender. Different mechanism: here the sender is streaming and the receiver is CPU-bound.
- #2063 (open) — corrupt-frame head-of-line block. Not this: no corrupt-frame errors on any of the three nodes.

## Impact

- Two of 15 legs from the bridge node dead for 24h+ and counting; `image_cache` writes originating on sender never reach receiver-A/receiver-B (cache misses, no data loss).
- One of 50 http workers burned per receiver, plus GC helpers; RSS +30 GB on receiver-B from mmapped logs. HTTP status probes still 200/200 (40/40) on both nodes, GTM Available.
- Will not self-heal until the sender's 3-day retention purges the stretch (~2026-09-18 04:08Z) and forces a bounded base-copy resync (harper-pro#285). Restarting the receivers alone re-enters the same records from the same cursor.
- The monitoring signal was "slowly increasing replication backlog", which reads as a slow drain; `cluster_status` showed `connected: true` throughout.

## Proposed fixes (in order of leverage)

1. **Short-circuit before the walk when the incoming version is below the audit floor.** If `txnTime < oldestRetainedAuditTime` the walk cannot reach `txnTime`; the outcome is already determined (the write is older than every retained version of the record, so under LWW the head wins and the write's only possible contribution is commutative ops, which for a `fullUpdate` `put` is nothing). Apply the `dedupVersionCouldBeRetained` answer (or the #2593 floor) at walk entry, not just at the two dedup lookups.
2. **Drop replicated writes whose `expiresAt` is already in the past** before reconciliation (cheap, table-agnostic, and exactly the records that made this stretch expensive).
3. **Normalize `nodeId` for the walk lookup:** `auditStore.get(localTime, tableId, id, nodeId ?? 0)` so a local head queries the `local` log (node 0) instead of aggregating all logs. `main :3729` already does `nodeId ?? 0` for the identity string one line above.
4. **Bound the live-delivery walk in wall-clock terms and yield**, mirroring #1316's `REPLAY_WALL_CLOCK_LIMIT_MS` for boot replay, so a pathological record degrades to the capped approximation instead of freezing the leg.
5. Storage side: rocksdb-js#676 (suffix-minimum stop for absent `exactStart` keys).

## Open questions

- Why only receiver-A and receiver-B of 15 receivers. Hypothesis: the walk runs only when the key exists locally with a newer version; `image_cache` is per-node cache fill, so only nodes holding those keys hot paid the cost. Not verified.
- Whether `existingEntry.nodeId === undefined` is the intended representation of a local head in the RocksDB entry, or a separate encoding gap; the `?? 0` fallbacks throughout `Table.ts` suggest it is expected.

## Repro sketch

Two-node RocksDB cluster, `auditLog: true`, short `auditRetention` (minutes), a table with per-record `expiresAt`. Write key K locally on B many times (deep chain, local head). On A, replicate to B a `put` of K carrying a version older than B's retention floor and an `expiresAt` in the past (a `setTimestamp` or bridge-style relayed write). B enters the walk at `Table.ts:3728` and issues `auditStore.get(localTime, …, undefined)`; with several per-origin logs present, each step scans every log to end-of-log. Assert: walk not entered for `txnTime < floor`, and `getRange` receives `log: 0` for a local head.

Customer, cluster, node and record identifiers redacted per field-issue convention; the unredacted capture is with the reporter.

## Method notes (for whoever picks this up)

Profile and pause were taken with no dependencies from inside the container: `docker exec -i node --input-type=module - <9229+threadId> ` using Node 24's global `WebSocket` against `http://127.0.0.1:/json/list` (`Profiler.start/stop`, and `Debugger.pause` → `Runtime.getProperties` → `Debugger.resume`, ~40 ms paused). Thread id comes from `cluster_status` `database_sockets[].threadId`.

Start in resources/Table.ts at the out-of-order audit reconciliation block and compare its walk-entry logic with the retention guard from #1486. Then trace auditStore.get through RocksTransactionLogStore.getSync and getRange, using the reported Table.js and rocksdb-js stack locations. Done should prevent stale writes from taking the full walk and avoid an undefined nodeId expanding each lookup across every origin log, with regression coverage for the affected path.

Written by the indexing model from the issue text.