Log once when checkOverloaded() first rejects writes (harper#2001) - #2007
Merged
Conversation
A wedged outstandingCommit currently causes checkOverloaded() to return 503 for every write on the thread, forever, with nothing logged server-side — hdb.log shows zero occurrences even during a live incident. outstandingCommit is also anonymous, so there is no indication of which database/table to investigate. Capture the arming transaction's database/table/resourceName identity alongside outstandingCommit, and log once (not once per rejected request) the first time checkOverloaded() rejects, including how long the commit has been outstanding. This does not change the rejection behavior itself — only adds visibility into it. Refs #2001 Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
…tartedFrom Two real bugs found by the codex/gemini/harper-domain pre-push review: - The identity capture sat in the arming branch shared by both a real write commit and a no-op abort (no writes). An abort flowing through that branch would stamp the wedge identity with an uninvolved read-only store. Gate the capture on this.writes.length > 0, the same condition that distinguishes commit() from abort() a few lines up. - transaction.next never inherited startedFrom in txnForContext (Table.ts), so a chained (second-table) transaction's identity was always blank — affecting both this new log and the existing long-transaction-abort log at DatabaseTransaction.ts. Propagate it alongside the existing sourceApply/ isReplay inheritance. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
…table - Read the table name off the actual write (this.writes[0].store), not this.db — this.db is whichever table first claimed the shared per-database transaction in txnForContext, so a transaction spanning two tables in the same database could log the wrong one. - Reword the log line: checkOverloaded() only rejects transactions that haven't yet passed the check, not every write on the thread (an in-flight one keeps going). "All further writes" overstated that. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
…ing gap - Log message: guard against printing "started from Resource.undefined" when startedFrom.method is unset. - Fix the stale "up to 25 seconds" comment on MAX_OUTSTANDING_TXN_DURATION's declaration (default is 45000ms) — the new log now surfaces this value to operators, so the comment mismatch is no longer just cosmetic. - Document, in code, the pre-existing arming gap the reviews surfaced: a coordinated retry or a chained store's commit runs synchronously inside the settling commit's own .then handler, one microtask before outstandingCommit is cleared, so neither is ever armed/logged if it wedges itself. This bounds what the diagnostic can see; fixing the underlying race is a separate, riskier change to the arming mechanism itself, not bundled here. Trimmed the Table.ts comment to match. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
- The abort branch (no writes) was blanking the whole identity, discarding an accurate database/resourceName/method along with the unknowable table. Keep what's known; only table is genuinely unavailable there. - Include the native transaction id in the log so an operator can correlate it with the coordinated-retry debug line and rocksdb-level diagnostics, which are already keyed on the same id. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Round 5's domain lens read rocksdb-js's dist directly: Transaction.abort() is synchronous and returns void, so it can never reach the `if (commitResolution)` arming branch — my round-4 "abort has no writes" handling was defending against a path that cannot execute. Simplified back to unconditional this.writes[0].store access (both commit() call sites are themselves guarded on this.writes.length > 0) and corrected the comment. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
checkOverloaded() is only reached when !context.source (Table.ts:2188, :4317) — replication/source-applied writes bypass it entirely, and deletes reach neither call site. "Further write transactions" overstated this; narrowed to "further record writes and publishes from application requests" and noted that replication-sourced writes continue. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
… not an outcome "replication-sourced writes ... continue" overclaimed progress the log can't guarantee — if the same commit that's wedged is what a canonical- source apply would also stall on, it doesn't continue either. context.source also isn't replication-specific (it covers caching-source applies and MQTT durable-session writes too). Reworded to describe the bypass mechanism instead of asserting an outcome. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
![gemini-code-assist[bot]](https://avatars.githubusercontent.com/in/956858?s=60&v=4){kind=small}
Contributor
There was a problem hiding this comment.
Code Review
This pull request improves diagnostic logging for stuck database transactions by capturing and logging the identity (database, table, resource name, method, and transaction ID) of the transaction that caused a commit to hang, logging it only once per stuck commit to avoid log spam. It also ensures that chained transactions inherit the startedFrom property. Feedback was provided to address a potential TypeError when accessing this.writes[0].store if this.writes is empty, which could crash the transaction abort/cleanup path.
Contributor
|
Reviewed; no blockers found. |
…nt/wording - checkOverloaded()'s outstanding-commit tracking allocated a 5-property identity object on every armed commit (i.e. on ImmediateTransaction.save(), per write, not per batch) even though it's only ever read on the 45s wedge path. Replace it with two reference assignments (the DatabaseTransaction instance and the native transaction), and assemble the log message lazily inside checkOverloaded() — safe because a stuck commit means the resolve handler that would clear this.writes never runs while outstandingCommit still references it. - Fix a comment at the recordCommitLatency call site that claimed outstandingCommit "re-arms per attempt" on every retry; only the backoff path (retries > 2) actually yields and re-arms — the coordinated-retry and retries<=2 paths re-commit synchronously while outstandingCommit is still set. - Reword the rejection log: "further application requests" (not "further writes") since already-checked in-flight transactions and deletes are not gated by checkOverloaded() and keep writing during a wedge. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
…azily The prior fix held a reference to the DatabaseTransaction object itself and read writes[0].store / startedFrom off it lazily in checkOverloaded(). Independent review (codex/grok/domain) caught that this object can be reused for a later immediate commit while the original native commit is still wedged, and that later commit's resolve handler clears/replaces writes on the SAME object — so the deferred read could log a blanked or wrong table/origin, reintroducing the mis-attribution bug from 8f53462. Snapshot the store and startedFrom at arm time instead (both stable references — a Store and a set-once object), so the identity is immutable for the arm's lifetime and holds no lingering reference to the transaction/writes/entries graph. Also narrow the rejection log's wording: checkOverloaded() only gates record updates and publishes (_writeDelete never calls it), so "further writes" overstated scope. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
The comment claimed two reference assignments and no lingering strong reference to the transaction, but the snapshot fix in the prior commit added a third assignment (outstandingCommitNativeTransaction) and does retain the native transaction handle (its lifetime was already bounded by the pending outstandingCommit promise, so this isn't a leak, but the comment no longer described the code). Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
kriszyp
marked this pull request as ready for review
July 30, 2026 21:25
Member
|
Reviewed — |
kriszyp
added a commit
that referenced
this pull request
Jul 31, 2026
… stuck-commit diagnostics Per codex's independent pre-push review: main landed #2007 (Log once when checkOverloaded() first rejects writes, harper#2001) while this branch was in flight, adding per-commit identity (store/startedFrom/native-transaction-id) and one-time logging to the single-slot `outstandingCommit`/`outstandingCommitStart` this PR replaces. A plain rebase/merge would have silently dropped that diagnostics feature. Reconciled by moving the identity fields and a `logged` flag onto each OutstandingCommit list node (populated at trackOutstandingCommit() call time) instead of a single module-level slot, and having checkOverloaded() read them off `oldestOutstandingCommit`. This also strictly improves on #2007: its single slot only ever armed for the FIRST commit attempt (a documented known gap — a chained second-store commit or most retries were invisible to both the overload check and the log), whereas every node here carries its own identity, so a chained or retried commit that wedges is now named just as precisely as the first one, and a second still-stuck commit logs on its own once it becomes the oldest. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
kriszyp
added a commit
that referenced
this pull request
Jul 31, 2026
Per gemini's independent pre-push review: per-node `logged` dedup (added in the previous commit to close #2007's known single-slot gap) means that under sustained overload, each distinct commit that individually ages past MAX_OUTSTANDING_TXN_DURATION logs once as it becomes the oldest — which is correct in isolation, but a large pileup where many commits settle in succession could turn one overload episode into a growing stream of ERROR lines. Cap the log to once per second across the whole thread regardless of how many commits cross the threshold. A commit skipped by the cooldown is not marked `logged`, so it still logs later if it's still the oldest once the cooldown clears, rather than going silent forever. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
2 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
What
When a RocksDB commit stays outstanding past
storage.maxTransactionQueueTime(default 45s),checkOverloaded()rejects every subsequent write on that worker thread with a 503 — and until now, logged nothing server-side.hdb.logshowed zero occurrences during a live production incident (harper#2001), andoutstandingCommitcarried no database/table identity, which was the single biggest obstacle to root-causing a recurrence.This adds one
error-level log, emitted once per stuck commit (not once per rejected request — a wedged thread can reject hundreds of requests/sec), naming:Also fixes
startedFrom(the resource/method that started a transaction) never propagating to a chained transaction when a request touches a second table intxnForContext(Table.ts) — this was silently blanking the equivalent field on the pre-existing long-transaction-abort log too, not just the new one.No change to the 503 rejection itself, the arming condition, or any write path. Diagnostics only.
Why this shape
Goal 2 of the investigation asked specifically for a single, low-risk logging addition — not a fix to whether/how the stuck commit gets cleared (that's a separate, riskier change to the arming mechanism itself; see Risks below and the linked issue for a proposal).
Test plan
npm run build— cleannpm run test:unit:resources— 1323 passing, 0 failing (twice, to rule out the one observed flake in an unrelatedcaching.test.jstest)npx oxlint/npx prettier --check— cleanthis.writes[0].store(confirmed viaabort(): voidin the installed@harperfast/rocksdb-js2.5.0, so this branch'sif (commitResolution)gate is only ever reached via a realtransaction.commit(), neverabort())outstandingCommit/outstandingCommitStartare module-private andMAX_OUTSTANDING_TXN_DURATIONis frozen at module-load time from config, so a unit test can neither drive the sentinel nor shrink the 45s threshold after import. Forcing a genuine "native commit that never settles" deterministically is the same open problem this whole investigation is about. See Risks below.Risks & open questions
this.next.commit()runs synchronously inside the settling commit's own.thenhandler, one microtask before the.catch().finally()clearsoutstandingCommit— so a retry round or a second store's commit that itself wedges is never armed, and neither the 503 nor this log will ever see it. Only the first store's first commit attempt is covered. Fixing this touches the arming/clearing mechanism itself and is exactly the kind of riskier change the linked issue asks to keep separate from this logging PR.LMDBTransaction.tsmaintains its own separateoutstandingCommitsentinel, never stamps a start time, and has nocheckOverloaded()-equivalent timeout/rejection at all. Pre-existing, out of scope here.DatabaseTransaction.ts, "Transaction was open too long...") still identify the table via(txn.db as any)?.name— the same first-claiming-table imprecision this PR's own reasoning found and fixed for the new log (now viathis.writes[0].store). Left alone as a separate, self-contained cleanup outside this PR's scope.resources/transaction.ts's low-leveltransaction()helper never setsstartedFromat all (only Resource.ts's own transaction-starting dispatch does) — so theTable.tspropagation fix here only helps requests that start through a Resource method, not code that manually orchestrates a transaction via that helper directly.Refs #2001