Skip to content

Outstanding-commit wedge recurs on 5.2.6/5.2.7: native commits never settle and checkOverloaded 503s every application write on the thread until restart #2450

Closed

Description

@Devin-Holland

Summary

On a production Harper Fabric control-plane node running harper-pro 5.2.6, three worker threads each had a native write commit that never settled. checkOverloaded() then rejected every new application write on those threads with the 503 Outstanding write transactions have too long of queue, please try again later for ~12.5 minutes, until the process was restarted (an upgrade to 5.2.7). Nothing else was logged: no RocksDB stall, no long-reader release, no event-loop stall warning at onset, no MDB_/ERR_BUSY error. Host resources were healthy throughout (37% memory, 3.5% CPU, 18% disk).

This is the harper#2001 family recurring with the #2001 fix present: trackOutstandingCommit() correctly detected and named the stuck commits (that part of #2001 works), but a commit that never settles is still never aborted, timed out, or diagnosed — the thread stays wedged until a restart. 5.2.6 and 5.2.7 are identical on this path (rocksdb-js 2.7.1, abandonWrites present in both), so upgrading does not prevent recurrence.

Timeline (UTC, 2026-09-01)

  • 20:25:03 — the three commits are submitted (each is timed from its own submission).
  • 20:25:48 — the guard fires on three threads within ~100ms, one stuck commit each:
[http/9]  [error]: Rejecting writes on this thread: a commit has been outstanding for 45019ms (exceeds the 45000ms limit), from table: data.Host/ (transaction 1724751), started from Host.patch. Further record updates and publishes from new application requests on this thread will be rejected with 503 until the commit settles or the process is restarted (...)
[http/10] ... from table: data.InstanceMonitoring/ (transaction 1724755), started from InstanceMonitoring.patch ...
[http/8]  ... from table: data.Host/ (transaction 1724822), started from Host.patch ...
  • 20:25:48 → 20:38:15 — every application write on http/8, /9, /10 is rejected. The rejection surfaced to the app as an unhandledRejection per write (the app's own bug, fixed separately), ~14K lines in the hour:
[http/10] [error]: unhandledRejection in worker thread 10: Error: Outstanding write transactions have too long of queue, please try again later
    at DatabaseTransaction.checkOverloaded (core/resources/DatabaseTransaction.ts:718:10)
    at Object.validate (core/resources/Table.ts:2343:20)
    at DatabaseTransaction.save (core/resources/DatabaseTransaction.ts:858:29)
    at TableResource.#saveOperation (core/resources/Table.ts:1898:33)
    at TableResource.save (core/resources/Table.ts:1869:32)
    at TableResource.patch (core/resources/Table.ts:2281:16)
    at patch.transactional.hasContent (core/resources/Resource.ts:180:17)
    at runAction (core/resources/Resource.ts:835:20) statusCode=503
  • 20:38:52 — process restarted (upgrade to 5.2.7): Harper was not properly shutdown → Replayed 23412 records in data database → healthy since. The stuck commits were cleared by the restart, exactly as the guard's message says; nothing else would have cleared them.

The two tables are the app's host/instance monitoring rows, patched every few seconds per connected host — a write shape that had run for months on v4 and for days on 5.2.x without incident, so the trigger is rare but the writes are constant.

Ruled out

  • Resource exhaustion (memory/CPU/disk healthy at onset and throughout).
  • Event-loop stall: the JavaScript execution has taken too long warnings that day were at 14:29–14:35 and 19:10, none at 20:25.
  • RocksDB write stall / long-reader release: none logged in the 20:00 hour.
  • harper#2368 (@computed/@relationship durable writes): one of the two tables has only three scalar fields, and there were zero attribute.set errors.
  • Blob stall: neither table has blob fields.
  • An app-side shared transaction: the writes are issued from a WebSocket message callback. In 5.2.7 that callback runs with no ambient contextStorage store (native uWS message → synchronous emit chain, nothing AsyncResource-bound — reproduced with a standalone uWS + AsyncLocalStorage probe on Node 24 and 22), so each contextless static Table.patch() resolved context = {} (Resource.ts:763) and ran in its own one-shot transaction. Three independent transactions on three threads parked at the same instant — that points at something shared underneath them.

Why this is a core issue — three distinct asks

1. A submitted native commit has no deadline (the #2001 residual). trackOutstandingCommit() (DatabaseTransaction.ts:89-130 @ v5.2.7) links the commit and unlinks it only when the promise settles. checkOverloaded() (:680-721) reads the oldest and rejects new work. Nothing ever acts on the stuck commit itself: it is never aborted, its promise is never rejected, and MAX_OUTSTANDING_TXN_DURATION only gates bystanders. rocksdb-js coordinated-retry commits park on write intents held by other transactions (the comment at :975-979 says so for the retained-read-handle case that abandonWrites fixed) — so a commit can wait forever on an intent holder that never completes, and the guard turns that into a permanent per-thread outage. Ask: after the limit (or a separate storage.maxCommitSettleTime), abort/time out the parked native commit with a diagnostic naming what it was waiting on, and let the thread recover without a restart.

2. Diagnostics stop at the symptom. The one-line identity snapshot (table, native txn id, startedFrom) is a real improvement over #2001's silence, but it says nothing about why the commit is parked: which native transaction holds the conflicting intent, on which key, from which thread, and how long it has been open. Without that, a recurrence is still un-root-causable from logs — this one was. Ask: when a commit crosses the limit, dump the waited-on transaction/intent (rocksdb-js should be able to expose the lock waiter → holder relationship) and the holder's startedFrom.

3. checkOverloaded() has the wrong failure semantics for a wedge. The 503 says "please try again later", but the condition is not transient — retries cannot succeed until a restart, so clients retry-storm a dead thread (14K rejections here). And it head-of-line-blocks every unrelated write on the thread: a patch to a different table/record is rejected because one other commit hung. Related: harper#2321 reports the same guard not recovering and punishing bystanders. Ask: once a commit is past the limit by a wide margin, distinguish "wedged" from "queue overloaded" (different message/error code, non-retryable), and scope the rejection to what actually conflicts where possible.

Environment

  • harper-pro 5.2.6 at the time of the incident; the process now runs 5.2.7, whose DatabaseTransaction.ts / rocksdb-js are identical on this path (verified by diffing the tags).
  • RocksDB storage; Node 24 (the harper-pro image's runtime).
  • Single-container control-plane deployment (not a multitenant Fabric host); a 2-node replicated pair.

App-side workaround

The application now awaits the message handler (so the 503 lands in its catch instead of an unhandledRejection flood) and passes an explicit fresh {} context per table op so its per-call transaction scope is pinned rather than left to the ambient store. That removes the noise and hardens the app's side of the contract; it does not and cannot prevent a native commit from parking. Workaround PR: HarperFast/central-manager#763.

Activity

  1. added theissue type on Sep 1, 2026
  2. added this to the v5.3 milestone on Sep 1, 2026
  3. self-assigned this
    on Sep 1, 2026
  4. Devin-Holland commented on Sep 2, 2026

    @Devin-Holland
    MemberAuthor

    Recurred on 5.2.7 on both production CM nodes (2026-09-02), mechanism reproduced

    Field data (both nodes on harper-pro 5.2.7 / rocksdb-js 2.7.1, all from hdb.log)

    node wedge onset (UTC) first parked commit threads flood until restart
    node B 04:24:59 (reported 04:25:44, 45007 ms) data.InstanceMonitoring/ from InstanceMonitoring.patch http/3 ~516k unhandledRejection … too long of queue
    node A 09:01:26 (reported 09:02:11, 45019 ms) data.Host/ from Host.patch, second thread 90 ms later, third at 09:02:52 http/1,2,3 ~454k

    Both cleared only by the 13:34 UTC container restart. Ruling out the environment: RocksDB's own LOG shows no flush/compaction/stall between 08:58 and long after 09:01 on node A (same for node B's window); sysstat shows the data disk under 0.1% util with ~1–2 ms await, CPU 99% idle, zero blocked tasks; 20% disk, 1% inodes. No job threads ran between the previous restart and either onset, and neither node logged a single Transaction was open too long and has been aborted line, so the long-transaction monitor never reaped a holder.

    Two observations that locate the fault above RocksDB:

    1. On node B the replication consumer (http/1) stopped making progress at ~04:25:01 — Receive watchdog: no consumer progress … for 1800000ms while paused for back-pressure every 30 min from 04:55:01 — i.e. replication-applied writes into the data DB stalled at the same instant as the local commit. The stall is database-wide, not thread-scoped; checkOverloaded() only reports the thread that receives new application writes.
    2. On node A two independent Host.patch commits on two threads parked within 90 ms of each other.

    Mechanism (rocksdb-js 2.7.1, src/binding/transaction/transaction.cpp completeCommitWork): every Harper commit runs with coordinatedRetry: true (DatabaseTransaction.getReadTxn). On IsBusy, the native layer releases the commit's own VT intents and then, if any transaction currently holds a write intent on one of those slots, registers a wake callback on that holder's LockTracker and parks — with no deadline. The verification table is process-global and hash-addressed (128K slots, db_settings.cpp), so the holder can be a transaction on a different table whose key merely collides. If the holder never commits/aborts/closes, the parked commit never settles; trackOutstandingCommit then ages it past 45 s and checkOverloaded() 503s every unrelated write on that thread. The holder is never logged anywhere.

    Reproduction (Node 24, npm i @harperfast/rocksdb-js@2.7.1 vs @2.8.0, node --expose-gc park-on-unreleased-intent.mjs):

    ##### rocksdb-js 2.7.1 (Harper 5.2.7) #####
    --- holder alive, never commits ---
    victim.commit() → {"stillParked":true,"ms":12002}
    releasing: holder.abort()
    after releasing holder → {"settled":"RETRY_NOW","ms":12008}
    --- holder dropped without commit/abort, then gc() ---
    victim.commit() → {"stillParked":true,"ms":12003}
    releasing: gc() x5, no reference to the holder remains
    after releasing holder → {"stillParked":true,"ms":18536}
    
    ##### rocksdb-js 2.8.0 (v5.2 after #2466) #####
    --- holder alive, never commits ---
    victim.commit() → {"settled":"RETRY_NOW","ms":5005}
    --- holder dropped without commit/abort, then gc() ---
    victim.commit() → {"settled":"RETRY_NOW","ms":5005}
    
    park-on-unreleased-intent.mjs
    // Reproduces the write wedge behind HarperFast/harper#2450 at the rocksdb-js layer.
    // A coordinatedRetry commit that hits an IsBusy conflict parks on the verification-table (VT) write
    // intent of whichever transaction currently holds that key's slot. If the holder never commits or
    // aborts, the commit promise never settles on 2.7.1 (Harper 5.2.7); 2.8.0 (#744) wakes it after
    // ROCKSDB_JS_PARK_TIMEOUT_MS (default 5000 ms) with RETRY_NOW.
    //
    //   node --expose-gc park-on-unreleased-intent.mjs
    //
    // Same key throughout; the VT is hash-addressed (128K slots), so an unrelated key that collides
    // with the holder's slot behaves identically — which is how one stuck transaction can park writes
    // to other tables.
    import { RocksDatabase, Transaction, constants, versions } from '@harperfast/rocksdb-js';
    import { mkdtempSync, rmSync } from 'node:fs';
    import { tmpdir } from 'node:os';
    import { join } from 'node:path';
    
    const sleep = (ms) => new Promise((r) => setTimeout(r, ms));
    const now = () => Math.round(performance.now());
    const withVersion = (version) => { const b = Buffer.alloc(16); b.writeDoubleBE(version, 0); return b; };
    const dir = mkdtempSync(join(tmpdir(), 'park-repro-'));
    const db = new RocksDatabase(dir, { encoding: false, verificationTable: true });
    db.open();
    console.log(`rocksdb-js ${versions['rocksdb-js']} (RocksDB ${versions.rocksdb}) | park timeout env: ${process.env.ROCKSDB_JS_PARK_TIMEOUT_MS ?? '(default)'}`);
    
    let n = 0;
    async function scenario(label, makeHolder, releaseHolder) {
    	console.log(`\n--- ${label} ---`);
    	const key = Buffer.from(`k${++n}`);
    	await db.put(key, withVersion(1e12));
    	db.populateVersion(key, 1e12);
    	const holder = makeHolder(key);                                   // installs a write intent on key's slot
    	const victim = new Transaction(db.store, { coordinatedRetry: true });
    	await victim.get(key);                                            // victim's snapshot
    	await db.put(key, withVersion(2e12));                             // committed after the snapshot → victim will be IsBusy
    	victim.putSync(key, withVersion(3e12));
    	const t0 = now();
    	const pending = victim.commit().then(
    		(r) => ({ settled: r === constants.RETRY_NOW_VALUE ? 'RETRY_NOW' : String(r), ms: now() - t0 }),
    		(e) => ({ rejected: e.message, ms: now() - t0 })
    	);
    	const first = await Promise.race([pending, sleep(12_000).then(() => ({ stillParked: true, ms: now() - t0 }))]);
    	console.log('victim.commit() →', JSON.stringify(first));
    	if (first.stillParked) {
    		await releaseHolder(holder);
    		const second = await Promise.race([pending, sleep(5_000).then(() => ({ stillParked: true, ms: now() - t0 }))]);
    		console.log('after releasing holder →', JSON.stringify(second));
    	}
    	try { victim.abort(); } catch {}
    }
    
    // 1. Holder stays referenced and never commits/aborts — a stuck long-lived transaction.
    await scenario(
    	'holder alive, never commits',
    	(key) => { const h = new Transaction(db.store, { coordinatedRetry: true }); h.putSync(key, withVersion(9e12)); return h; },
    	async (h) => { console.log('releasing: holder.abort()'); h.abort(); }
    );
    
    // 2. Holder dropped without commit/abort — the leak rocksdb-js#768 (in 2.8.0) closes on GC.
    await scenario(
    	'holder dropped without commit/abort, then gc()',
    	(key) => { const h = new Transaction(db.store, { coordinatedRetry: true }); h.putSync(key, withVersion(9e12)); return null; },
    	async () => { console.log('releasing: gc() x5, no reference to the holder remains'); for (let i = 0; i < 5; i++) { globalThis.gc?.(); await sleep(300); } }
    );
    
    db.close();
    rmSync(dir, { recursive: true, force: true });

    On #2466 (rocksdb-js 2.8.0 on v5.2): rocksdb-js#744 bounds the park at ROCKSDB_JS_PARK_TIMEOUT_MS (5000 ms) and #768/#780 release dropped / env-orphaned transactions, so the thread no longer wedges and two leak classes are closed. What it does not do — and what this recurrence argues still belongs on this issue:

    • The holder is still silent. A park timeout is indistinguishable from a real wake (HTTP Logs showing up in system (non external) logs #744 explicitly declined a transaction:parkTimeout event), so a permanently held intent now surfaces only as the initiating write failing after ~MAX_RETRIES × 5 s with the generic coordinated-retries error, and nothing names the transaction that held the slot. Ask 2 above stands: on park timeout (or when checkOverloaded() fires) log the holder's transaction id, startedFrom, thread and age.
    • A holder that is alive and referenced but stuck (not dropped, not on a dying env) is untouched by Test123 #768/Make RocksDB memory config configurable (block cache + WriteBufferManager) #780; the bound only protects its victims.

    Two adjacent observations from the same incident, filed here for triage rather than asserted as causes:

    • On both nodes, stdout mirroring (logging.stdStreams: true) went silent from the wedge onset until restart while hdb.log kept receiving lines from every thread — docker logs contains nothing from the incident window. Either the stdio guard (harper_logger.ts, permanent disableStdio() on EPIPE/EIO/ERR_STREAM_DESTROYED) tripped, or worker stdout stopped being drained. Unproven; worth its own issue.
    • After a restart operation, the restart job thread booted the components, HM WebSocket sessions attached to it, and once the job completed its DB handles closed while messages were still arriving: Database not open at new Transaction … getReadTxn … incomingMsgHandler. Adjacent to rocksdb-js#780, separate from the wedge.
  5. Devin-Holland commented on Sep 2, 2026

    @Devin-Holland
    MemberAuthor

    Split the unresolved half out: #2471 — A transaction holding staged writes stays open for hours and is never reaped or identified (the holder behind the #2450 wedge). #2466 / 5.2.8 bounds the park (this issue), so #2471 tracks the holder: naming it on park timeout / checkOverloaded(), reporting long-lived native handles, and the sourceApply/isReplay reap exemption.

  6. Devin-Holland commented on Sep 3, 2026

    @Devin-Holland
    MemberAuthor

    Recurred on 5.2.8 / rocksdb-js 2.8.0 (2026-09-03) — the park was not the root cause; the per-database commit lane stops

    Both production CM nodes wedged again after the 5.2.8 upgrade (17:56 UTC 09-02; harper-pro 5.2.8 and rocksdb-js 2.8.0 verified inside the containers). With the park bounded at 5 s, these commits cannot have been parked:

    node first guard line outstanding when first seen table
    A 05:15:06 45 s data.InstanceMonitoring
    A 07:29:04 34 min system.hdb_user (the addUser at 06:54:41)
    B 23:51:14 (09-02) 45 s data.Host
    B 00:47:48 57 min data.PurchasedBlock
    B 03:02:16 2 h 14 min system.hdb_session

    What the counters show. RocksDB's own periodic stats in LOG.old freeze at onset on every affected database: rocksdb.number.keys.written stops advancing (node A data: 2,152,375 from 05:16 onward; node B: 1,921,606 from 23:56), while rocksdb.stall.micros and rocksdb.db.write.stall stay at 0. Same on 09-02 under 2.7.1 (node A frozen at 2,559,581 from 09:08, node B at 2,195,484 from 04:32). CPU ~1%, disk idle, no blocked tasks, nothing in hdb.log or RocksDB LOG at either onset. So: commits stop reaching RocksDB, RocksDB never stalls, and the whole database stops — one bug common to 2.7.1 and 2.8.0. The coordinated-retry park was only how the victims presented on 2.7.1.

    Per-database, staggered. rocksdb-js runs one rocksdb-commit lane thread per database (three in /proc/<pid>/task: data, system, oauth). Each database wedges independently, at its next commit: on node A data at 05:14 and system at 06:54:42, one second after Adding user … on http/2; on node B data at 23:50:28 and system at 00:47:49 (the next session write). That is the signature of a lane thread blocking forever on the first commit that needs something a stuck thread holds — a process-global lock (the VT writerMutex_/DBSettings mutex taken on every putSync/releaseIntent), a RocksDB optimistic-commit lock bucket, or a wait inside Commit(). The http workers stay alive because checkOverloaded() rejects their writes before they touch any of that.

    Main-thread stall at onset, three days running. With logging.stdStreams: true, docker logs tracks hdb.log hour by hour before and after each wedge, but receives nothing from any thread from the onset until restart (09-03: node A nothing 05h–11h; node B nothing 23h–11h), while hdb.log kept receiving lines from every http worker. Worker stdout is drained by the main thread's event loop; file appends are not. Unproven, but consistent with the main thread being the stuck holder.

    What I could not do from logs: name the blocked call. The threadsafe-function calls on the lane path are all unlimited-queue (cannot block), the log-store lock orders I traced are consistent, and RocksDB reports no stall — a native stack of the wedged process is required. A read-only capture script is ready for the next occurrence (per-thread /proc wchan/syscall/kernel stacks, gdb thread apply all bt if gdb is present, and an ops-API probe that tests the main thread directly). The rocksdb-js.node in the image is unstripped, so gdb will give symbolized frames.

    One more variable worth knowing about: every Harper Pro worker runs @datadog/pprof's SIGPROF wall profiler at 50 ms sampling, restarted every 60 s (analytics/profile.ts, analytics.profiling: true by default; the v8:ProfEvntProc threads). Signal-based sampling profilers are a documented source of infrequent deadlocks in processes that use C++ exceptions and native mutexes. Not asserted as the cause — but it is the one process-wide agent that interrupts threads at random, and disabling it on one node is a cheap discriminating experiment.

    Stress harness (3 workers, hot keys, coordinated retry, log entries, main-thread log reads + cooling): 12 M commits in 5 min with no wedge; a profiler-enabled variant is running. Scripts and the capture script are attached to the follow-up; #2471 (holder reporting) stands, but the fix for this issue is downstream of the stack dump.

  7. Devin-Holland commented on Sep 3, 2026

    @Devin-Holland
    MemberAuthor

    Root cause found from the production gdb capture (2026-09-03 17:14/17:30 UTC): RocksDB WriteBufferManager write stall. The main thread and every rocksdb-commit lane are blocked in rocksdb::DBImpl::WriteBufferManagerStallWrites() (frames, reproduction and fix in #2490). Harper defaults the WBM on with allowStall: true (0183089, 2026-06-11 → 5.2.5–5.2.8), memtable memory across 28 column families crossed the ~660 MiB budget with no single CF near its flush trigger, RocksDB scheduled no WBM flush (flush.reason.write_buffer_manager = 0) and every writer slept forever. This is below rocksdb-js, so #2466 could not fix it; the coordinated-retry park was how the victims presented, not the cause. Reproduced deterministically with allowStall: true vs clean with allowStall: false.

  8. added a commit that references this issue on Sep 10, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

bugSomething isn't working

Type

Fields

Priority

P1

Projects

No projects

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions