HarperFast / HarperFast/harper
Open investigation: transaction-log entry misframed on a healthy process — bytes on disk are valid, reader's buffer disagrees with the file (cause unidentified)
- Dominant language
- JavaScript
- Stars
- 89
- Forks
- 10
- Avg merge
- 2d 6h
- Merged PRs (30d)
- 200
Description
## Summary
A system-database transaction-log entry became **misframed** on a node that had been running continuously, with no crash, no abrupt termination, and ample free disk. The result was an 11-day silent replication stall (see #2063 for the containment half). The bytes on disk at the reported offset turned out to be **valid, intact record data** — so this is a framing/offset problem, not a torn write.
**Cause not identified.** Filing to preserve the investigation and the ruled-out list, because the artifact has since been deleted by normal transaction-log retention and the same evidence will be hard to reassemble next time.
Observed on 5.1.19 with rocksdb-js 2.4.0.
## Symptom
```
[warn]: Stopping transaction log "local" at a corrupt entry during replay
RangeError: Corrupt transaction log entry at position e4649f of log 8:
declared length 3107454976 overruns the log (limit=16777155)
```
Replay stops at that entry, so nothing written after it is ever delivered to the peer. Deploys then fail with a misleading `Connection closed 1006` because the deployment row cannot replicate.
## What was verified
**The bytes at the reported offset are not corrupt.** Hexdumping the file at `0xe4649f` gives:
```
64 20 76 65 72 73 69 6f 6e 73 20 6f 66 "d versions of"
```
— mid-string inside a **valid** msgpack payload. The surrounding region parses cleanly (`cb` + float64 timestamp, `a7` + `"install"`, `a3` + `"npm"`, `a6` + `"stderr"`, `da 0113` str16). No tear, no zero-fill, no garbage. The reader is simply not at an entry boundary, so it reads payload bytes as a header and gets an absurd declared length.
**Two discrepancies that were never explained:**
1. `dataView.getUint32(position + 8)` on the file at that offset yields `6e 73 20 6f` = **1,853,161,583** — *not* the **3,107,454,976** the error reported. The buffer the reader was walking therefore **did not match the file** at that offset. This points at the memory-map layer rather than at the writer.
2. The reader's bound (`limit` = 16,777,155, i.e. `Math.min(size, logBuffer.length)`) was **3,544 bytes smaller** than the physical file (16,780,699 B), leaving a tail unreachable. Possibly just the committed-vs-physical distinction, but unconfirmed.
The persisted committed position (`txn.state`, little-endian `[position:4][logId:4]`) pointed at a *different, later* log, so a stale/torn position word does not explain it.
## Ruled out (with evidence)
| Candidate | Why it's out |
|---|---|
| `createAuditEntry` returning a shared `ENTRY_HEADER` view (#1132) | The native layer copies synchronously: `TransactionLogEntry`'s constructor allocates its own `unique_ptr` and `::memcpy`s the bytes, and `TransactionLogHandle::addEntry` constructs it before returning. Verified in rocksdb-js at the deployed tag, not just older ones. **#1132's fix PR was deliberately closed as unnecessary overhead, and that call was correct — please don't reopen it on the strength of this symptom.** |
| Abrupt-termination torn write | `RestartCount=0`, `OOMKilled=false`, exactly one `successfully started` line, process up continuously across the corruption window. |
| Full disk / quota mid-write (the cause in #1977) | Data volume at 37% used. |
| An entry spanning two log segments | The writer never splits an entry: `writeEntriesV1` fits whole entries or breaks. (`TransactionLogEntryBatch.currentEntryBytesWritten` / `currentEntryHeaderWritten` exist but are unused on this path.) |
| Short `writev` dropping a tail | `writeBatchToFile` loops, advances into a partial iovec's remainder, and retries `EINTR` — it cannot return before every iovec is fully written. |
## Leading hypothesis (unconfirmed)
The mapped buffer the reader walks diverges from the file's contents — implicating the mapping layer (the anonymous memory-map overlay / `updateMemoryMapOverlay()`, a map created with a wrong length or offset, or map reuse across log ids) rather than anything on the write path. Discrepancy (1) above is the main support: two different garbage lengths for the same offset, one reported by the reader and one present on disk.
Supporting circumstantial evidence: the wedge **cleared itself** when the affected log aged out of retention, and on a *different* cluster an operator reported a restart appearing to "unstick" replication. A restart cannot repair corrupt bytes on disk, but it does rebuild mappings — consistent with the blocking state being in memory rather than in the file.
## How to confirm next time
1. **Before restarting**, copy the affected `.txnlog` and `txn.state` off the host. Retention will delete them (that is what happened here) and the evidence is then gone.
2. **CDP-eval on the affected worker** to dump what the *process* sees at the failing offset in its mapped buffer, and diff it against the same offset read from the file. That single comparison decides map-layer vs file, and it is the one measurement this investigation lacked.
3. **rocksdb-js ≥ 2.5.0** ships `validateTransactionLogStore(path, { strict })` and a `verify-logs` CLI that validate a store **offline** (no open database). Run it against a copy to get an authoritative verdict on whether the file itself is framing-clean.
## Why it's worth keeping open
The containment gap (#2063) means one such entry stalls a replication stream indefinitely with no alarm, so however rare this is, its blast radius is large — here it was 11 days of silent divergence between two nodes, discovered only because a deploy failed with an unrelated-looking error.
## Related
- #2063 — the containment half: corrupt-entry handling is per-drain, so the stream never recovers. Fixing that limits the damage but not the cause.
- #1977 — torn audit entry throwing out of iteration; attributes tearing to write failures (full disk/quota), which is explicitly **not** the case here.
- #1135 — corrupt length-prefix entry aborting startup (closed; introduced the stop-at-corrupt-entry behaviour seen above).
- #1132 — see the ruled-out table; closed deliberately and correctly.
- #1370 — records that fail to decode taking out a worker; adjacent failure mode.
Filed from a field incident; cluster and host identifiers omitted.
Contributor guide
Research direction
Start with the transaction-log reader and updateMemoryMapOverlay(), then compare the process's mapped buffer with the copied .txnlog at the failing offset before restart. Review writeEntriesV1 and writeBatchToFile as the already-checked write path, and use validateTransactionLogStore or verify-logs on an offline copy. Done means identifying a reproducible mapping or offset cause, or documenting evidence that rules it out.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- javascript, nodejs
- Domain
- backend, databases, distributed-systems
- Issue type
- Bug
- Difficulty
- 5/5
- Estimated time
- Over a week
- Activity status
- Quiet
- Clarity
- Needs clarification
- Newbie friendliness
- 28/100