From 0c632106365062b36db464d67ce398a2df527077 Mon Sep 17 00:00:00 2001 From: Mark Hannum Date: Thu, 16 Jul 2026 10:40:56 -0400 Subject: [PATCH 1/2] Tolerate missing entries when removing from the commit-LSN map The commit-LSN map is a windowed, in-memory cache: it is pruned as log files are deleted, is rebuilt only from the last checkpoint forward on restart, and (on physical replicants) need not span a log range that is being rewound / truncated. It therefore does not contain every committed transaction that a recovery backward pass may walk over. Recovery's undo path (records newer than trunc_lsn / past a recovery timestamp) calls __txn_commit_map_remove and, until now, treated a "not found" result as a fatal error. That aborted the entire backward pass -- e.g. a physical replicant truncating its txn log would fail with "Could not find transaction N in the map" and be unable to make progress. This became reachable because snapshot isolation was made the default: the commit-map machinery used to be gated by get_commit_lsn_map_switch_value() (which folded in the now-removed gbl_snapisol/gbl_modsnap flags and was 0 on a physrep without enable_snapshot_isolation), and is now gated only by gbl_utxnid_log (on by default). The recovery add path is guarded by opcode == TXN_COMMIT, so the map only ever holds commits; the removal path had no matching tolerance for entries that were legitimately never present. Make a missing entry benign: - __txn_commit_map_remove_nolock now returns DB_NOTFOUND (was 1) on a miss, logs at WARN (was ERROR), and bumps gbl_commit_map_remove_miss so a real map-population regression is still observable. The counter is surfaced in 'bdb clminfo' as "Remove misses: N". - The four recovery undo sites swallow DB_NOTFOUND to 0 and fall through to record the undo, so the backward pass continues. Genuine errors are still fatal. (The swallow must happen here: returning DB_NOTFOUND up to the backward-pass loop would still be treated as a failure.) __txn_child_recover is left strict: it only removes after a guarding __txn_commit_map_get, so a miss there would indicate a real inconsistency. Co-Authored-By: Claude Opus 4.8 (1M context) Signed-off-by: Mark Hannum --- berkdb/txn/txn_rec.c | 76 ++++++++++++++++++++++++++++++++++--------- berkdb/txn/txn_util.c | 42 +++++++++++++++++++++--- 2 files changed, 98 insertions(+), 20 deletions(-) diff --git a/berkdb/txn/txn_rec.c b/berkdb/txn/txn_rec.c index 952a41df43..b20489ccd2 100644 --- a/berkdb/txn/txn_rec.c +++ b/berkdb/txn/txn_rec.c @@ -224,10 +224,21 @@ __txn_dist_commit_recover(dbenv, dbtp, lsnp, op, info) * so we treat this as an abort even if it was a commit record. */ - if (commit_lsn_map && (ret = __txn_commit_map_remove(dbenv, argp->txnid->utxnid))) { - logmsg(LOGMSG_ERROR, "%s: Failed to remove %"PRIu64" from the commit map\n", __func__, - argp->txnid->utxnid); - goto quiet_err; + if (commit_lsn_map) { + ret = __txn_commit_map_remove(dbenv, argp->txnid->utxnid); + if (ret == DB_NOTFOUND) { + /* + * Benign: the commit-LSN map is a windowed cache and need + * not contain every committed txn the backward pass undoes + * (log-file pruning, rebuild-from-checkpoint on restart, + * physrep rewinds). Nothing to un-track; continue the pass. + */ + ret = 0; + } else if (ret != 0) { + logmsg(LOGMSG_ERROR, "%s: Failed to remove %"PRIu64" from the commit map\n", __func__, + argp->txnid->utxnid); + goto quiet_err; + } } ret = __db_txnlist_update(dbenv, @@ -481,10 +492,21 @@ __txn_regop_gen_recover(dbenv, dbtp, lsnp, op, info) (!IS_ZERO_LSN(headp->trunc_lsn) && log_compare(&headp->trunc_lsn, lsnp) < 0)) { - if (commit_lsn_map && (ret = __txn_commit_map_remove(dbenv, argp->txnid->utxnid))) { - logmsg(LOGMSG_ERROR, "%s: Failed to remove %"PRIu64" from the commit map\n", __func__, - argp->txnid->utxnid); - goto quiet_err; + if (commit_lsn_map) { + ret = __txn_commit_map_remove(dbenv, argp->txnid->utxnid); + if (ret == DB_NOTFOUND) { + /* + * Benign: the commit-LSN map is a windowed cache and need + * not contain every committed txn the backward pass undoes + * (log-file pruning, rebuild-from-checkpoint on restart, + * physrep rewinds). Nothing to un-track; continue the pass. + */ + ret = 0; + } else if (ret != 0) { + logmsg(LOGMSG_ERROR, "%s: Failed to remove %"PRIu64" from the commit map\n", __func__, + argp->txnid->utxnid); + goto quiet_err; + } } /* @@ -606,10 +628,21 @@ __txn_regop_recover(dbenv, dbtp, lsnp, op, info) * so we treat this as an abort even if it was a commit record. */ - if (commit_lsn_map && (ret = __txn_commit_map_remove(dbenv, argp->txnid->utxnid))) { - logmsg(LOGMSG_ERROR, "%s: Failed to remove %"PRIu64" from the commit map\n", __func__, - argp->txnid->utxnid); - goto quiet_err; + if (commit_lsn_map) { + ret = __txn_commit_map_remove(dbenv, argp->txnid->utxnid); + if (ret == DB_NOTFOUND) { + /* + * Benign: the commit-LSN map is a windowed cache and need + * not contain every committed txn the backward pass undoes + * (log-file pruning, rebuild-from-checkpoint on restart, + * physrep rewinds). Nothing to un-track; continue the pass. + */ + ret = 0; + } else if (ret != 0) { + logmsg(LOGMSG_ERROR, "%s: Failed to remove %"PRIu64" from the commit map\n", __func__, + argp->txnid->utxnid); + goto quiet_err; + } } ret = __db_txnlist_update(dbenv, @@ -838,10 +871,21 @@ __txn_regop_rowlocks_recover(dbenv, dbtp, lsnp, op, info) __txn_deallocate_ltrans(dbenv, lt); } - if (commit_lsn_map && (ret = __txn_commit_map_remove(dbenv, argp->txnid->utxnid))) { - logmsg(LOGMSG_ERROR, "%s: Failed to remove %"PRIu64" from the commit map\n", __func__, - argp->txnid->utxnid); - goto quiet_err; + if (commit_lsn_map) { + ret = __txn_commit_map_remove(dbenv, argp->txnid->utxnid); + if (ret == DB_NOTFOUND) { + /* + * Benign: the commit-LSN map is a windowed cache and need + * not contain every committed txn the backward pass undoes + * (log-file pruning, rebuild-from-checkpoint on restart, + * physrep rewinds). Nothing to un-track; continue the pass. + */ + ret = 0; + } else if (ret != 0) { + logmsg(LOGMSG_ERROR, "%s: Failed to remove %"PRIu64" from the commit map\n", __func__, + argp->txnid->utxnid); + goto quiet_err; + } } /* diff --git a/berkdb/txn/txn_util.c b/berkdb/txn/txn_util.c index 778785cb71..6cbd477272 100644 --- a/berkdb/txn/txn_util.c +++ b/berkdb/txn/txn_util.c @@ -40,6 +40,15 @@ int dist_txn_abort_write_blkseq(void *bdb_state, void *bskey, int bskeylen); extern int set_commit_context_prepared(unsigned long long context); extern int gbl_utxnid_log; +/* + * Count of times we were asked to remove a utxnid that wasn't present in the + * commit-LSN map. This is an expected condition (the map is a windowed cache; + * see __txn_commit_map_remove_nolock), so it is not fatal -- but a spike here + * outside of physrep rewinds / recover-to-lsn can indicate a real map-population + * bug, so it is surfaced as an observable counter. + */ +int64_t gbl_commit_map_remove_miss = 0; + typedef struct __txn_event TXN_EVENT; struct __txn_event { TXN_EVENT_T op; @@ -505,8 +514,31 @@ static int __txn_commit_map_remove_nolock(dbenv, utxnid, delete_from_logfile_lis UTXNID_TRACK * const txn = hash_find(txmap->transactions, &utxnid); if (!txn) { - logmsg(LOGMSG_ERROR, "%s: Could not find transaction %"PRIu64" in the map\n", __func__, utxnid); - ret = 1; + /* + * The commit-LSN map is a windowed, in-memory cache: it is pruned + * as log files are deleted, is rebuilt only from the last + * checkpoint forward on restart, and (on physical replicants) need + * not span a range that is being rewound / truncated. A missing + * entry is therefore an expected condition, not corruption. Report + * it as DB_NOTFOUND and let the caller decide -- recovery's backward + * pass treats it as a no-op so it can continue. + */ + ++gbl_commit_map_remove_miss; + /* + * On a large physrep rewind every committed txn in the undo window + * can miss, so rate-limit the log to at most one line per second. + * gbl_commit_map_remove_miss (see 'bdb clminfo') is the durable, + * always-on signal. Safe: this runs under txmap_mutexp. + */ + static int lastpr = 0; + const int now = comdb2_time_epoch(); + if (now != lastpr) { + logmsg(LOGMSG_WARN, "%s: transaction %"PRIu64" not in commit map " + "(nothing to remove); total misses %"PRId64"\n", + __func__, utxnid, gbl_commit_map_remove_miss); + lastpr = now; + } + ret = DB_NOTFOUND; goto err; } @@ -566,9 +598,11 @@ void __txn_commit_map_print_info(DB_ENV *dbenv, loglvl lvl, int should_lock) { if (should_lock) { Pthread_mutex_lock(&txmap->txmap_mutexp); } logmsg(lvl, "Highest logfile: %"PRId64"; " - "Smallest logfile: %"PRId64"\n", + "Smallest logfile: %"PRId64"; " + "Remove misses: %"PRId64"\n", txmap->highest_logfile, - txmap->smallest_logfile); + txmap->smallest_logfile, + gbl_commit_map_remove_miss); if (should_lock) { Pthread_mutex_unlock(&txmap->txmap_mutexp); } } From f54afe13449d0f7f17059fa7878d958d4da0a18c Mon Sep 17 00:00:00 2001 From: Mark Hannum Date: Thu, 16 Jul 2026 10:40:57 -0400 Subject: [PATCH 2/2] test: recover-to-lsn tolerates commit-map entries missing during undo Add a regression test for the commit-LSN map "not found on remove" fix. It reproduces the exact failing condition deterministically, without needing a physical replicant: - run committed traffic and capture an early recovery lsn (post-flush), - generate more committed traffic spanning higher logfiles (the range a recover-to-lsn will undo), - use clm_delete_logfile to drop a logfile's entries from the in-memory map while leaving the actual log records intact -- so the backward pass still walks those committed txns but they are absent from the map, - truncate_log back to the early lsn. Before the fix the backward pass aborted ("Could not find transaction N in the map"); now it must complete. The test asserts the node stays healthy, the pre-recovery-lsn state survives (undone traffic is gone), and that the miss path was actually exercised (via the "Remove misses" counter reported by 'bdb clminfo'). Co-Authored-By: Claude Opus 4.8 (1M context) Signed-off-by: Mark Hannum --- tests/commit_lsn_map.test/runit | 92 +++++++++++++++++++++++++++++++++ 1 file changed, 92 insertions(+) diff --git a/tests/commit_lsn_map.test/runit b/tests/commit_lsn_map.test/runit index 34d8751907..ca71cfa707 100755 --- a/tests/commit_lsn_map.test/runit +++ b/tests/commit_lsn_map.test/runit @@ -261,6 +261,10 @@ extract_highest_logfile_from_clminfo() { grep -oP '(?<=Highest logfile: )[-]?[0-9]+' <<<"$1" } +extract_remove_misses_from_clminfo() { + grep -oP '(?<=Remove misses: )[-]?[0-9]+' <<<"$1" +} + verify_txmap_has_expected_min_max_files() { trap 'error $LINENO' ERR @@ -400,11 +404,99 @@ test_recover_to_lsn() { verify_correct_utxnids_in_map "$utxnids_to_recover" "$utxnids_to_be_deleted_during_recovery" "$master" } +test_recover_to_lsn_missing_map_entries() { + trap 'error $LINENO' ERR + + # Regression test: a recover-to-lsn backward pass must tolerate undoing a + # committed transaction that is absent from the commit-LSN map, rather than + # aborting the whole pass. The map is a windowed in-memory cache, so it need + # not contain every committed txn that recovery walks over (e.g. on a + # physical replicant, or across a restart / log-file prune). Before the fix, + # such a miss failed with "Could not find transaction N in the map" and the + # node could not truncate its log. + + # Given: some traffic, then an early recovery point captured after a flush. + cdb2sql ${CDB2_OPTIONS} $dbnm default 'create table tmiss(i int)' > /dev/null + cdb2sql ${CDB2_OPTIONS} $dbnm default 'insert into tmiss values(1)' > /dev/null + cdb2sql ${CDB2_OPTIONS} $dbnm default 'exec procedure sys.cmd.send("flush")' > /dev/null + + local recovery_lsn recovery_lsn_file + recovery_lsn=$(cdb2sql --tabs ${CDB2_OPTIONS} --host $master $dbnm default \ + 'exec procedure sys.cmd.send("bdb cluster")' | grep MASTER | sed 's/.*lsn //g ; s/ .*//g') + recovery_lsn_file=$(echo "$recovery_lsn" | cut -d: -f 1) + readonly recovery_lsn recovery_lsn_file + + # More committed traffic that recovery will undo, spanning higher logfiles. + insert_values 10 tmiss 1 + pushlogs $(( recovery_lsn_file + 3 )) + insert_values 10 tmiss 1 + + # Pick a logfile in the undo range that currently has map entries and drop + # just those entries from the in-memory map. The log records themselves are + # untouched, so the backward pass will still walk these committed txns -- + # but they are now missing from the map, reproducing the bug's condition. + local hole_file + hole_file=$(cdb2sql --tabs ${CDB2_OPTIONS} --host $master $dbnm \ + "select min(commitlsnfile) from comdb2_transaction_commit where commitlsnfile > $recovery_lsn_file") + readonly hole_file + if [[ -z "$hole_file" || "$hole_file" == "NULL" ]]; then + echo "FAIL: no committed txns in the undo range to remove from the map" + exit 1 + fi + + local misses_before + misses_before=$(extract_remove_misses_from_clminfo "$(get_clminfo $master)") + misses_before=${misses_before:-0} + readonly misses_before + + cdb2sql ${CDB2_OPTIONS} --host $master $dbnm \ + "exec procedure sys.cmd.send('clm_delete_logfile $hole_file')" > /dev/null + + # When: recover/truncate back to the early lsn, walking the missing entries. + cdb2sql ${CDB2_OPTIONS} --host $master $dbnm \ + "exec procedure sys.cmd.truncate_log(\"{$recovery_lsn}\")" + + # Then: the node is healthy (this query fails if the backward pass aborted + # or the node went down) ... + local alive + alive=$(cdb2sql --tabs ${CDB2_OPTIONS} --host $master $dbnm 'select 1') + if [[ "$alive" != "1" ]]; then + echo "FAIL: master unhealthy after recover-to-lsn across missing map entries" + exit 1 + fi + + # ... the pre-recovery-lsn state survived and the undone traffic is gone ... + local rowcount + rowcount=$(cdb2sql --tabs ${CDB2_OPTIONS} --host $master $dbnm 'select COUNT(*) from tmiss') + if [[ "$rowcount" != "1" ]]; then + echo "FAIL: expected 1 row in tmiss after recovery, got $rowcount" + exit 1 + fi + + # ... and we actually exercised the missing-entry path. + local misses_after + misses_after=$(extract_remove_misses_from_clminfo "$(get_clminfo $master)") + misses_after=${misses_after:-0} + readonly misses_after + if (( misses_after <= misses_before )); then + echo "FAIL: expected commit-map remove misses to increase ($misses_before -> $misses_after)" + exit 1 + fi + + # ... and the recovered table is internally consistent. + # + # Leave tmiss in place: dropping a table immediately after a recover-to-lsn + # can race with the truncate and leave residue that the suite's end-of-test + # verify trips on. test_recover_to_lsn likewise leaves its table behind. + do_verify tmiss +} + if [ "$TESTCASE" == "commit_lsn_map_delete_generated" ]; then set -o pipefail test_recover_to_lsn test_delete + test_recover_to_lsn_missing_map_entries else test_add fi