Fix commit map remove notfound

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;
+			}
 		}
 
 		/*

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); }
 }

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