Skip to content

Name the long-transaction monitor's abort log with database/table/txn identity - #2958

Merged
kriszyp merged 8 commits into
mainfrom
fix/monitor-abort-log-commit-identity
Oct 9, 2026
Merged

kriszyp merged 8 commits into
mainfrom
fix/monitor-abort-log-commit-identity

Conversation

@kriszyp

@kriszyp kriszyp commented Oct 1, 2026 •

Copy link
Copy Markdown
Member

⊙ Problem

When the long-transaction monitor aborts a write-bearing transaction, its error line named only the visited link's bare table (from table: <table> path: <url>). It gave no database, no native transaction id to join against the long-lived-holder sweep, and on LMDB no started from resource. For a transaction spanning several databases, operators had no way to tell which store and which native handle the abort belonged to. The newer stuck-commit log already solves this with describeCommitIdentity().

❓ Your call: Is the requirement warranted? As specified, yes: this is the line an operator sees when a write is rejected for running too long, and the stuck-commit lines already use this format. The one sibling touching the same line, #372, wraps it in harperLogger.status() without changing its text, so the two compose.

💡 Solution

Both engines' abort lines now go through the shared describeCommitIdentity() export. The line becomes:

Transaction was open too long and has been aborted after exceeding the open-transaction limit, from table: <db>.<table> (transaction <native id>)[, started from <Resource>.<method>] path: <url>

The request-path suffix both lines already carried is kept. No write, poison or abort ordering changes: both engines still log synchronously and then call abortDueToTimeout() on the chain head.

❓ Your call: Only the two abort error lines are converted. The monitor's sibling warn lines (commit-phase grace, released read snapshot) keep the old from table: <name> path: shape, so a transaction that is first spared and later aborted is logged in two formats. Converting them is a cheap follow-up; this PR stays on the lines the task named.

❓ Your call: The line names the link the monitor visited (txn.db, txn.transaction), while the abort is applied to commitChainHead. In a two-database chain the line can name database B while the rejection surfaces at head A. I kept the visited link because it is the one whose idle limit expired, and its native id is what the long-lived-holder sweep reports. Naming the head instead is a one-argument change.

🔧 Changes

  • resources/DatabaseTransaction.ts: exports describeCommitIdentity(). It catches a throwing .id read, since rocksdb-js throws "Transaction has already been closed" on a reset handle. A throw while building the line would skip the abort and the rest of that monitor tick. The RocksDB abort line now uses the helper; started from moves from a separate logger argument into the message.

    ❓ Your call: The guard lives in the diagnostic rather than in rocksdb-js's Transaction.id (which could return undefined on a closed handle). It is local, cheap and removable once the binding changes.

  • resources/LMDBTransaction.ts: imports the helper and uses it for its own copy of the abort line. LMDB gains the started from context; it has no native id to print.

    ❓ Your call: The log shape changes: a database prefix, an inline started from, and (transaction N). An outside alert keyed on from table: <table> path: or on the separate "was started from" argument stops matching, with no error. In-repo matchers key only on the Transaction was open too long / has been aborted prefix, apart from the integration test updated below.

✅ Verification

  • integrationTests/database/delete-index-atomicity-rocksdb.test.ts: Arm A's matcher accepts the new db.table (transaction N)[, started from R.m] shape and still pins the table and path: /SlowMixedHold/. The old regex fails against the new line. npm run test:integration -- integrationTests/database/delete-index-atomicity-rocksdb.test.ts passed 9/9 before the rebase. It has not been re-run on the rebased head; CI's integration workflow covers it.
  • unitTests/resources/longLivedTransactions.test.js, "monitor abort attribution": drives a real two-database, non-source-apply RocksDB transaction through the monitor's abort branch, with the second link reachable only through the head's chain. It asserts the poisoned commit still rejects (the harper#2062 invariant), then that the line names the head's db.table and native id. LMDB is skipped: LMDB has no native id to assert.
    • The first version was red on every Linux CI leg. It expected database test, but the unit config aliases data/dev/test/test2 onto one RocksDB root that takes the name of whichever alias opens it first. Inside the full suite, an earlier file had opened it as data. The head table now has its own database. The rejection check now rethrows anything other than the poison error, so a failed setup assertion reports under its own message.
    • Reproduction: a table declared in data before the original test produces CI's exact failure; the fixed test passes under the same ordering.
    • Mutation: making abortDueToTimeout() a no-op fails the test with Missing expected rejection: the poisoned commit must still surface as a rejection….
  • npx mocha unitTests/resources/longLivedTransactions.test.js: 52 passing.
  • npm run test:unit:resources:core on the rebased head: 3414 passing, 0 failing. Before the test fix: 3413 passing, 1 failing (this test).
  • npx prettier --check and npx oxlint --quiet on the changed files: clean.
  • CI at 4b0cbc134:
    • Unit Test Node 22, Node 24 and Windows: green. The fixed test passes on 22, 24 and 26.
    • Unit Test Node 26: red only in test:unit:main (nodeAdapterMiddleware, npmUtilities dry_run). The same 7 failures occur on main 26a914501 under the Node v26.11.1 runner.
    • Integration: all shards green.
    • Next.js adapter: one use cache test failed on each of Node 22 and Node 24, a different test on each leg. No abort-log line appears in any of that run's server logs, and a re-run passed.

❓ Your call: The new unit test covers RocksDB only. The LMDB call site is reached by no test. Its reads are optional-chained and the line has no native id, so the crash risk is low; an LMDB variant can be added later.

— Claude Opus 5.5

🤖 Generated with Claude Code

https://claude.ai/code/session_01V5mxNqhsJGMSr9SYiDUsTt

Related PRs: #372 overlaps (wraps the same RocksDB abort line in harperLogger.status(); whichever lands second keeps both the wrapper and the new message)

Complexity: easy

Review-Coverage: authored=claude; ran=cursor-muse,gemini,codex; adjudicated=domain; declined=cursor-grok,cursor-composer,cursor-kimi; rounds=10; full=2 @ b58cba8

Review-Attention: study ~13m (critical: DatabaseTransaction.ts, LMDBTransaction.ts; decisions: abort-log-attributes-visited-link, convert-only-the-abort-line, error-line-format-change) @ b58cba8

@gemini-code-assist gemini-code-assist Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Code Review

This pull request improves transaction abort logging by standardizing the output format using describeCommitIdentity across database transactions (including RocksDB and LMDB). It also safely wraps native transaction ID access in a try-catch block to prevent crashes on already-closed handles. A new integration test suite is added to verify the attribution of aborted transactions. The review feedback suggests increasing the transaction expiration timeout in the new test from 20ms to 200ms to prevent flakiness in resource-constrained CI environments.

Comment thread unitTests/resources/longLivedTransactions.test.js Outdated
@kriszyp

kriszyp commented Oct 8, 2026

Copy link
Copy Markdown
Member Author

Why "monitor abort attribution" was red on Unit Test Node 22/24/26

The production change was fine. The test expected the wrong database name, and its assertion structure hid that.

  • The test declared its head table in database test and expected from table: test.MonitorAbortPrimaryTable (transaction N).
  • The unit config (unitTests/mocha.init.js, unitTests/testUtils.js) points data, dev, test and test2 at one RocksDB root. initStores in resources/databases.ts names that root with rootStore.databaseName ??= …, so the first alias to open it wins.
  • Run alone, the root is first opened as test and the test passes. In npm run test:unit:resources:core, an earlier file opens it as data. The line then reads from table: data.MonitorAbortPrimaryTable/@… (transaction 81252) (captured locally from the full suite), and the assert.match fails.
  • That assert.match ran inside the transaction callback. Its AssertionError became the transaction's rejection, the /exceeding the maximum open-transaction time/ validator didn't match it, and Node reported the custom message "the poisoned commit must still surface as a rejection". The poisoned commit had in fact rejected correctly.

Fix (test only, 4b0cbc134, branch rebased onto current main with no conflicts):

  1. The head table gets its own database (monitor-abort-primary), so the logged name is deterministic.
  2. The assert.rejects validator is a function that rethrows anything other than the open-transaction error, so a failed setup assertion inside the callback reports under its own message.
  3. The attribution assert.match runs after the rejection check.

Evidence

  • Repro: declaring one table in data before the original test produces CI's exact failure in about 3 s. The fixed test passes under the same ordering.
  • Poison invariant still guarded (harper#2062): with abortDueToTimeout() made a no-op in dist/, the fixed test fails Missing expected rejection: the poisoned commit must still surface as a rejection once the callback returns.
  • npm run test:unit:resources:core: 3414 passing, 0 failing. Before the fix: 3413 passing, 1 failing (this test).

The ??= naming also applies in production if two configured databases share one path: describeCommitIdentity() then prints whichever alias opened the root first. That predates this PR and also affects the stuck-commit log; I've noted it as a possible follow-up rather than changing it here.

— Claude Opus 5.5

kriszyp and others added 8 commits October 8, 2026 22:47
…tity()

The abort log in DatabaseTransaction.ts and LMDBTransaction.ts named only
the transaction's head table, which is misleading for a chain spanning
several tables. Route it through describeCommitIdentity() like the
stuck-commit log already does, so it carries the database name and native
transaction id too, and give the LMDB copy the startedFrom suffix the
RocksDB line already had.

Dispatch-Task: harper-monitor-log-commit-identity
Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01TsPwRKneHVrUNA3LdBcuME
…ad, update integration regex

- Restore the request-path suffix on both abort logs (dropped when they
  moved to describeCommitIdentity()); startedFrom is only populated by
  Resource's static wrapper, so non-Resource writes would otherwise lose
  all request attribution on timeout.
- Read the native transaction's `.id` defensively inside
  describeCommitIdentity(): rocksdb-js's accessor can throw on an
  already-closed handle, and a diagnostic log must never crash the
  monitor loop that calls it.
- Update delete-index-atomicity-rocksdb.test.ts's Arm A regex for the
  new `database.table (transaction id)[, started from R.m]` identity
  shape; the database prefix and dropped `path:` segment broke its
  previous match (confirmed failing before this fix, now green).
- Trim narrative/history comments in the new unit test and harden its
  log-line lookup to filter on the fixture's own table name, so another
  suite's own timed-out transaction logging the same phrase first can't
  be picked up instead.

Dispatch-Task: harper-monitor-log-commit-identity
Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01TsPwRKneHVrUNA3LdBcuME
Dispatch-Task: harper-monitor-log-commit-identity
Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01TsPwRKneHVrUNA3LdBcuME
Trivial wording fix from round 3 review; only the transaction id and
started-from groups in the regex are unpinned.

Dispatch-Task: harper-monitor-log-commit-identity
Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01TsPwRKneHVrUNA3LdBcuME
gemini-code-assist flagged that setTxnExpiration(20) before the two real
Table.put() calls risked a premature tick firing mid-write on a loaded
runner. Stay on the slow ambient expiration while the writes land, and
only switch to the fast interval and force the head's own timeout past
zero once the chain is fully built and the secondary link's recency is
already decayed — the abort then fires deterministically on the very
next tick instead of racing how long the writes took.

Dispatch-Task: harper-monitor-log-commit-identity
Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01TsPwRKneHVrUNA3LdBcuME
Dispatch-Task: harper-monitor-log-commit-identity
Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01TsPwRKneHVrUNA3LdBcuME
Dispatch-Task: harper-monitor-log-commit-identity
Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01TsPwRKneHVrUNA3LdBcuME
The two-table monitor-abort test pinned the logged database to `test`, but the unit config aliases
data/dev/test/test2 onto one RocksDB root, and initStores names that root after whichever alias
opened it first. Run alone the test saw `test`; inside test:unit:resources:core an earlier file had
opened the root as `data`, so the line read `data.MonitorAbortPrimaryTable` and the match failed on
every Linux leg. The poison path was never at fault.

That match ran inside the transaction callback, so its AssertionError became the rejection and the
regex validator reported it under "the poisoned commit must still surface as a rejection". The
validator now rethrows anything other than the open-transaction error, and the attribution match
runs after the rejection is checked.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01V5mxNqhsJGMSr9SYiDUsTt
Dispatch-Task: harper-2958-fix-unit-test
@kriszyp
kriszyp force-pushed the fix/monitor-abort-log-commit-identity branch from 4b0cbc1 to b58cba8 Compare October 9, 2026 05:06
@kriszyp
kriszyp marked this pull request as ready for review October 9, 2026 12:26
@kriszyp
kriszyp merged commit 5cd7d85 into main Oct 9, 2026
54 checks passed
@kriszyp
kriszyp deleted the fix/monitor-abort-log-commit-identity branch October 9, 2026 12:26
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant