Upgrade 5.1.x→5.2: primary-key get() and indexed search miss rows written before the upgrade, while full scans and ops search see them #1864

Activity

1. kriszyp commented on Jul 18, 2026

   

   kriszyp

   on Jul 18, 2026

   MemberAuthor

   More actions

   Investigation update — layered diagnosis + corrections (2026-07-18)

   Ran ~30 more instrumented upgrade boots (fresh 5.1.10 install → seed → 5.2 boot, with an in-component probe that exercises every read layer per key: raw getBinarySync → store getSync → store getEntry → Table.get, plus a per-second health hammer from port-open). Key findings, including two corrections to the original report:

   Corrections

   1. The fresh-install repro is NOT deterministic. The original 4/4 first-boot failures were partly luck: today's fresh-install boots mostly come up healthy, with occasionally a brief (~seconds) broken window right after startup (health 503 immediately post-boot, healed by the time a probe ran seconds later, with zero replay writes and zero user writes — replayLogs logged nothing). The long-lived broken state (minutes+, the field symptom) reproduced this morning only on a root with real history — months of schema churn (multi-file schemas, type reorderings, ~15 restarts under 5.1.10) — and on the kris-test instance. A pristine seeded root seems insufficient to reliably trigger it; schema/catalog history appears to be an ingredient, echoing the original observation that reordering schema types once orphaned rows.

   2. Load sensitivity suspected but not confirmed: the morning's failures occurred while the box ran several concurrent Harper instances; a 2-CPU taskset starvation of the 5.2 boot did not reproduce on a fresh root.

   Layer analysis (why this narrows the search a lot)

   On a healed boot every layer HITs. During the brief window we caught, Table.get-level reads fail while raw reads see the rows. Studying the read path for how that divergence can exist at all:

   • Table.get reads via primaryStore.getEntry(id, { transaction: transaction.getReadTxn() }) — i.e. through a rocksdb-js transaction; every path that keeps working (full scan, getKeys, ops API, getBinarySync) reads without one.
   • But at the RocksDB level a transactional read cannot hide old committed data: Transaction::GetSync → txnHandle->getSync(key, value, readOptions, *dbHandle) passes the correct CF override, ensureSnapshot() pins a post-boot snapshot (sequence-based — old data always visible), and decode() is byte-identical between v5.1.10 and v5.2.0-beta.1. Value bytes of 5.1.10- vs 5.2-written records are format-identical too (only timestamps differ).
   • Therefore the app-visible miss is almost certainly above the store: either (a) Table.get throws during a boot/window state and every consumer (.catch(() => null) in apps, permission wrappers) launders the throw into "not found" — consistent with hdb.log showing no errors on bad boots (the errors would be swallowed client-side), or (b) Table-level entry validation (ensureLoadedFromSource / INVALIDATED|EVICTED flags / expiration) mis-classifies entries under some boot state. The metadataFlags of the affected records decode via the ACTION_32_BIT path to 0x0E000040 (HAS_NODE_ID only) on healthy boots — no EVICTED/INVALIDATED bits — so (b) requires state I haven't caught live yet.

   What would pin it

   The probe now distinguishes ERR vs NULL per key (Table.get wrapped bare, not caught). One captured long-lived broken boot with that probe answers (a)-vs-(b) immediately. The reliable trigger appears to need a schema-churned root: repro loops that also replay the history (multi-file schemas → reorder → restarts → concatenate → upgrade) are the next step, and/or deploying the layered probe to the kris-test instance where the long-lived state occurred in production form.

   Repro/probe assets: ~/dev/tmp/{layer-probe,hunt-broken,window-probe,hammer-probe}.sh + ~/dev/tmp/probe-app (dispatch app with /dispatch/storeprobe + err-capturing /dispatch/health) on kzyp's box.

   🤖 Generated with Claude Code

   — Claude (Opus 4.8)
2. kriszyp commented on Jul 18, 2026

   

   kriszyp

   on Jul 18, 2026

   MemberAuthor

   More actions

   Investigation update — schema-churn repro caught a long-lived break; ERR-vs-NULL answered (2026-07-18, later session)

   Built the schema-churn replay repro the previous update called for (scratch/harper-1864/churn-repro.sh on branch agent/harper-1864-upgrade-orphan): fresh 5.1.10 install → multi-file GraphQL schema with type declarations relocated across files over N restarts → concatenate to single file → seed rows throughout → upgrade-boot to 5.2.0-beta.1 → sub-second /dispatch/health + /dispatch/storeprobe hammering.

   Reliability: 15 attempts (RESTARTS=4 and RESTARTS=15, mixed hammer windows). 1/15 produced a long-lived break; the rest were clean or sub-second self-healing blips — consistent with churn history being a necessary but not sufficient ingredient (something else, likely boot-time race-window width, gates whether it's brief or long-lived). Documenting the odds rather than claiming full determinism.

   What the one caught long-lived break showed

   • GET /dispatch/health returned {"ok":false,"orphaned":[{"table":"User","rawCount":3,"scanCount":3,"getHits":0,"firstErr":"NULL"}]} continuously for ~175s. search({})/getKeys saw all 3 User rows; Table.get(k) returned null for all 3, zero exceptions. The identically-seeded Worker table was unaffected in this run — the divergence is per-table, not global.
   • firstErr was 'NULL' for the entire window, never 'ERR:...'. The health probe calls Table.get(k) bare (no app-level .catch) and explicitly distinguishes a caught exception ('ERR:'+message) from a clean miss ('NULL'). A 'NULL' result the whole time means Table.get resolved cleanly to null throughout — it did not throw.
   • This is evidence against candidate (a) (throw-laundered by a consumer .catch(()=>null)) for this window: there was no throw to launder. It's more consistent with candidate (b)-shaped behavior — something at or above the entry layer legitimately (from the code's perspective) treats the row as absent — though I did not manage to capture the entry's live metadataFlags/version during the break to confirm INVALIDATED/EVICTED/expiration specifically (see gap below).
   • The window healed with no write to the affected rows during the hammer phase — confirms a write isn't actually required to heal, just time or some other async completion.
   • Post-heal, storeGetEntry.flags for the previously-orphaned rows decoded to 234881088 = 0x0E000040 (HAS_NODE_ID only) — matches the healthy-boot decode from the prior update, so whatever caused the miss left no trace in the entry's flags once healed.

   Gap

   The mid-window storeprobe capture (added to the script after this first catch, to snapshot getEntry's raw version/metadataFlags/expiresAt while still broken) has not yet caught a second long-lived window in 14 follow-up attempts — so I can't yet cite the literal flag/version state of a broken entry, only that Table.get returns a clean null. Given the low, seemingly load/timing-sensitive hit rate, further blind hunting has diminishing returns; I'm consulting on diagnosis + fix direction now rather than continuing to guess.

   Where I'd point next given NULL-not-ERR

   Table.get's local-read path (resources/Table.ts, loadLocalRecord/withLocalEntry around L4835-4893) returns entry?.value straight through with no throw when primaryStore.getEntry(id, { transaction: transaction.getReadTxn() }) itself resolves to undefined/no-entry — no INVALIDATED/EVICTED branch needs to fire for a clean null if the entry itself is missing at the transaction-read layer. The previously-confirmed native-level finding (ensureSnapshot() pins a post-boot sequence snapshot, CF override correct) was established against a steady-state read; it doesn't rule out a boot-window race where a request's DatabaseTransaction/read-txn is constructed (and its snapshot/CF handle bound) while some table-recreation-driven column-family swap or finalization from the churned schema history is still in flight, so the very first read transactions on that table briefly bind to a pre-finalization state. That's a hypothesis, not a confirmed mechanism — the next concrete step would be instrumenting DatabaseTransaction.getReadTxn/primaryStore.getEntry (or the native ensureSnapshot) to log the bound sequence number / CF pointer identity on a request that hits during a caught broken window, correlated against when that table's CF was last (re)opened during boot.

   Repro script + notes: scratch/harper-1864/churn-repro.sh and scratch/harper-1864/README.md on agent/harper-1864-upgrade-orphan (pushed, no PR yet — consulting on diagnosis/fix direction before writing a fix per the task brief).

   🤖 Generated with Claude Code

   — Claude Sonnet 5
3. kriszyp

   self-assigned this

   on Jul 19, 2026
4. cb1kenobi

   closed this as completedin rocksdb-js#713on Jul 21, 2026
5. kriszyp

   set

   Priority

   to

   P1

   on Aug 4, 2026