roots: make the "idle" label useful

Apply the "idle" label only when the crawl is finished _and_ its
transid_max is up to date.  This makes the keyword "idle" better reflect
when bees is not only finished crawling, but also scanning the crawled
extents in the queue.

Signed-off-by: Zygo Blaxell <bees@furryterror.org>

docs/btrfs-kernel.md

@@ -55,6 +55,7 @@ These bugs are particularly popular among bees users, though not all are specifi
 | 5.4 | 5.11 | spurious tree checker failures on extent ref hash | 5.4.125, 5.10.43, 5.11.5, 5.12 and later | 1119a72e223f btrfs: tree-checker: do not error out if extent ref hash doesn't match
 | - | 5.11 | tree mod log issue #5 | 4.4.263, 4.9.263, 4.14.227, 4.19.183, 5.4.108, 5.10.26, 5.11.9, 5.12 and later | dbcc7d57bffc btrfs: fix race when cloning extent buffer during rewind of an old root
 | - | 5.12 | tree mod log issue #6 | 4.14.233, 4.19.191, 5.4.118, 5.10.36, 5.11.20, 5.12.3, 5.13 and later | f9690f426b21 btrfs: fix race when picking most recent mod log operation for an old root
+| 5.11 | 5.12 | subvols marked for deletion with `btrfs sub del` become permanently undeletable ("ghost" subvols) | 5.12 stopped creation of new ghost subvols | Partially fixed in 8d488a8c7ba2 btrfs: fix subvolume/snapshot deletion not triggered on mount.  Qu wrote a [patch](https://github.com/adam900710/linux/commit/9de990fcc8864c376eb28aa7482c54321f94acd4) to allow `btrfs sub del -i` to remove "ghost" subvols, but it was never merged upstream.
 | 4.15 | 5.16 | spurious warnings from `fs/fs-writeback.c` when `flushoncommit` is enabled | 5.15.27, 5.16.13, 5.17 and later | a0f0cf8341e3 btrfs: get rid of warning on transaction commit when using flushoncommit
 | - | 5.17 | crash during device removal can make filesystem unmountable | 5.15.54, 5.16.20, 5.17.3, 5.18 and later | bbac58698a55 btrfs: remove device item and update super block in the same transaction
 | - | 5.18 | wrong superblock num_devices makes filesystem unmountable | 4.14.283, 4.19.247, 5.4.198, 5.10.121, 5.15.46, 5.17.14, 5.18.3, 5.19 and later | d201238ccd2f btrfs: repair super block num_devices automatically

include/crucible/seeker.h

@@ -6,23 +6,23 @@
 #include <algorithm>
 #include <limits>
 
-#include <cstdint>
-
-#if 0
+// Debug stream
+#include <memory>
 #include <iostream>
 #include <sstream>
-#define DINIT(__x) __x
-#define DLOG(__x) do { logs << __x << std::endl; } while (false)
-#define DOUT(__err) do { __err << logs.str(); } while (false)
-#else
-#define DINIT(__x) do {} while (false)
-#define DLOG(__x) do {} while (false)
-#define DOUT(__x) do {} while (false)
-#endif
+
+#include <cstdint>
 
 namespace crucible {
 	using namespace std;
 
+	extern thread_local shared_ptr<ostream> tl_seeker_debug_str;
+	#define SEEKER_DEBUG_LOG(__x) do { \
+		if (tl_seeker_debug_str) { \
+			(*tl_seeker_debug_str) << __x << "\n"; \
+		} \
+	} while (false)
+
 	// Requirements for Container<Pos> Fetch(Pos lower, Pos upper):
 	// - fetches objects in Pos order, starting from lower (must be >= lower)
 	// - must return upper if present, may or may not return objects after that
@@ -49,113 +49,108 @@ namespace crucible {
 	Pos
 	seek_backward(Pos const target_pos, Fetch fetch, Pos min_step = 1, size_t max_loops = numeric_limits<size_t>::max())
 	{
-		DINIT(ostringstream logs);
-		try {
-			static const Pos end_pos = numeric_limits<Pos>::max();
-			// TBH this probably won't work if begin_pos != 0, i.e. any signed type
-			static const Pos begin_pos = numeric_limits<Pos>::min();
-			// Run a binary search looking for the highest key below target_pos.
-			// Initial upper bound of the search is target_pos.
-			// Find initial lower bound by doubling the size of the range until a key below target_pos
-			// is found, or the lower bound reaches the beginning of the search space.
-			// If the lower bound search reaches the beginning of the search space without finding a key,
-			// return the beginning of the search space; otherwise, perform a binary search between
-			// the bounds now established.
-			Pos lower_bound = 0;
-			Pos upper_bound = target_pos;
-			bool found_low = false;
-			Pos probe_pos = target_pos;
-			// We need one loop for each bit of the search space to find the lower bound,
-			// one loop for each bit of the search space to find the upper bound,
-			// and one extra loop to confirm the boundary is correct.
-			for (size_t loop_count = min(numeric_limits<Pos>::digits * size_t(2) + 1, max_loops); loop_count; --loop_count) {
-				DLOG("fetch(probe_pos = " << probe_pos << ", target_pos = " << target_pos << ")");
-				auto result = fetch(probe_pos, target_pos);
-				const Pos low_pos = result.empty() ? end_pos : *result.begin();
-				const Pos high_pos = result.empty() ? end_pos : *result.rbegin();
-				DLOG(" = " << low_pos << ".." << high_pos);
-				// check for correct behavior of the fetch function
-				THROW_CHECK2(out_of_range, high_pos, probe_pos, probe_pos <= high_pos);
-				THROW_CHECK2(out_of_range, low_pos, probe_pos, probe_pos <= low_pos);
-				THROW_CHECK2(out_of_range, low_pos, high_pos, low_pos <= high_pos);
-				if (!found_low) {
-					// if target_pos == end_pos then we will find it in every empty result set,
-					// so in that case we force the lower bound to be lower than end_pos
-					if ((target_pos == end_pos) ? (low_pos < target_pos) : (low_pos <= target_pos)) {
-						// found a lower bound, set the low bound there and switch to binary search
-						found_low = true;
-						lower_bound = low_pos;
-						DLOG("found_low = true, lower_bound = " << lower_bound);
-					} else {
-						// still looking for lower bound
-						// if probe_pos was begin_pos then we can stop with no result
-						if (probe_pos == begin_pos) {
-							DLOG("return: probe_pos == begin_pos " << begin_pos);
-							return begin_pos;
-						}
-						// double the range size, or use the distance between objects found so far
-						THROW_CHECK2(out_of_range, upper_bound, probe_pos, probe_pos <= upper_bound);
-						// already checked low_pos <= high_pos above
-						const Pos want_delta = max(upper_bound - probe_pos, min_step);
-						// avoid underflowing the beginning of the search space
-						const Pos have_delta = min(want_delta, probe_pos - begin_pos);
-						THROW_CHECK2(out_of_range, want_delta, have_delta, have_delta <= want_delta);
-						// move probe and try again
-						probe_pos = probe_pos - have_delta;
-						DLOG("probe_pos " << probe_pos << " = probe_pos - have_delta " << have_delta << " (want_delta " << want_delta << ")");
-						continue;
+		static const Pos end_pos = numeric_limits<Pos>::max();
+		// TBH this probably won't work if begin_pos != 0, i.e. any signed type
+		static const Pos begin_pos = numeric_limits<Pos>::min();
+		// Run a binary search looking for the highest key below target_pos.
+		// Initial upper bound of the search is target_pos.
+		// Find initial lower bound by doubling the size of the range until a key below target_pos
+		// is found, or the lower bound reaches the beginning of the search space.
+		// If the lower bound search reaches the beginning of the search space without finding a key,
+		// return the beginning of the search space; otherwise, perform a binary search between
+		// the bounds now established.
+		Pos lower_bound = 0;
+		Pos upper_bound = target_pos;
+		bool found_low = false;
+		Pos probe_pos = target_pos;
+		// We need one loop for each bit of the search space to find the lower bound,
+		// one loop for each bit of the search space to find the upper bound,
+		// and one extra loop to confirm the boundary is correct.
+		for (size_t loop_count = min((1 + numeric_limits<Pos>::digits) * size_t(2), max_loops); loop_count; --loop_count) {
+			SEEKER_DEBUG_LOG("fetch(probe_pos = " << probe_pos << ", target_pos = " << target_pos << ")");
+			auto result = fetch(probe_pos, target_pos);
+			const Pos low_pos = result.empty() ? end_pos : *result.begin();
+			const Pos high_pos = result.empty() ? end_pos : *result.rbegin();
+			SEEKER_DEBUG_LOG(" = " << low_pos << ".." << high_pos);
+			// check for correct behavior of the fetch function
+			THROW_CHECK2(out_of_range, high_pos, probe_pos, probe_pos <= high_pos);
+			THROW_CHECK2(out_of_range, low_pos, probe_pos, probe_pos <= low_pos);
+			THROW_CHECK2(out_of_range, low_pos, high_pos, low_pos <= high_pos);
+			if (!found_low) {
+				// if target_pos == end_pos then we will find it in every empty result set,
+				// so in that case we force the lower bound to be lower than end_pos
+				if ((target_pos == end_pos) ? (low_pos < target_pos) : (low_pos <= target_pos)) {
+					// found a lower bound, set the low bound there and switch to binary search
+					found_low = true;
+					lower_bound = low_pos;
+					SEEKER_DEBUG_LOG("found_low = true, lower_bound = " << lower_bound);
+				} else {
+					// still looking for lower bound
+					// if probe_pos was begin_pos then we can stop with no result
+					if (probe_pos == begin_pos) {
+						SEEKER_DEBUG_LOG("return: probe_pos == begin_pos " << begin_pos);
+						return begin_pos;
 					}
+					// double the range size, or use the distance between objects found so far
+					THROW_CHECK2(out_of_range, upper_bound, probe_pos, probe_pos <= upper_bound);
+					// already checked low_pos <= high_pos above
+					const Pos want_delta = max(upper_bound - probe_pos, min_step);
+					// avoid underflowing the beginning of the search space
+					const Pos have_delta = min(want_delta, probe_pos - begin_pos);
+					THROW_CHECK2(out_of_range, want_delta, have_delta, have_delta <= want_delta);
+					// move probe and try again
+					probe_pos = probe_pos - have_delta;
+					SEEKER_DEBUG_LOG("probe_pos " << probe_pos << " = probe_pos - have_delta " << have_delta << " (want_delta " << want_delta << ")");
+					continue;
 				}
-				if (low_pos <= target_pos && target_pos <= high_pos) {
-					// have keys on either side of target_pos in result
-					// search from the high end until we find the highest key below target
-					for (auto i = result.rbegin(); i != result.rend(); ++i) {
-						// more correctness checking for fetch
-						THROW_CHECK2(out_of_range, *i, probe_pos, probe_pos <= *i);
-						if (*i <= target_pos) {
-							DLOG("return: *i " << *i << " <= target_pos " << target_pos);
-							return *i;
-						}
-					}
-					// if the list is empty then low_pos = high_pos = end_pos
-					// if target_pos = end_pos also, then we will execute the loop
-					// above but not find any matching entries.
-					THROW_CHECK0(runtime_error, result.empty());
-				}
-				if (target_pos <= low_pos) {
-					// results are all too high, so probe_pos..low_pos is too high
-					// lower the high bound to the probe pos
-					upper_bound = probe_pos;
-					DLOG("upper_bound = probe_pos " << probe_pos);
-				}
-				if (high_pos < target_pos) {
-					// results are all too low, so probe_pos..high_pos is too low
-					// raise the low bound to the high_pos
-					DLOG("lower_bound = high_pos " << high_pos);
-					lower_bound = high_pos;
-				}
-				// compute a new probe pos at the middle of the range and try again
-				// we can't have a zero-size range here because we would not have set found_low yet
-				THROW_CHECK2(out_of_range, lower_bound, upper_bound, lower_bound <= upper_bound);
-				const Pos delta = (upper_bound - lower_bound) / 2;
-				probe_pos = lower_bound + delta;
-				if (delta < 1) {
-					// nothing can exist in the range (lower_bound, upper_bound)
-					// and an object is known to exist at lower_bound
-					DLOG("return: probe_pos == lower_bound " << lower_bound);
-					return lower_bound;
-				}
-				THROW_CHECK2(out_of_range, lower_bound, probe_pos, lower_bound <= probe_pos);
-				THROW_CHECK2(out_of_range, upper_bound, probe_pos, probe_pos <= upper_bound);
-				DLOG("loop: lower_bound " << lower_bound << ", probe_pos " << probe_pos << ", upper_bound " << upper_bound);
 			}
-			THROW_ERROR(runtime_error, "FIXME: should not reach this line: "
-				"lower_bound..upper_bound " << lower_bound << ".." << upper_bound << ", "
-				"found_low " << found_low);
-		} catch (...) {
-			DOUT(cerr);
-			throw;
+			if (low_pos <= target_pos && target_pos <= high_pos) {
+				// have keys on either side of target_pos in result
+				// search from the high end until we find the highest key below target
+				for (auto i = result.rbegin(); i != result.rend(); ++i) {
+					// more correctness checking for fetch
+					THROW_CHECK2(out_of_range, *i, probe_pos, probe_pos <= *i);
+					if (*i <= target_pos) {
+						SEEKER_DEBUG_LOG("return: *i " << *i << " <= target_pos " << target_pos);
+						return *i;
+					}
+				}
+				// if the list is empty then low_pos = high_pos = end_pos
+				// if target_pos = end_pos also, then we will execute the loop
+				// above but not find any matching entries.
+				THROW_CHECK0(runtime_error, result.empty());
+			}
+			if (target_pos <= low_pos) {
+				// results are all too high, so probe_pos..low_pos is too high
+				// lower the high bound to the probe pos, low_pos cannot be lower
+				SEEKER_DEBUG_LOG("upper_bound = probe_pos " << probe_pos);
+				upper_bound = probe_pos;
+			}
+			if (high_pos < target_pos) {
+				// results are all too low, so probe_pos..high_pos is too low
+				// raise the low bound to high_pos but not above upper_bound
+				const auto next_pos = min(high_pos, upper_bound);
+				SEEKER_DEBUG_LOG("lower_bound = next_pos " << next_pos);
+				lower_bound = next_pos;
+			}
+			// compute a new probe pos at the middle of the range and try again
+			// we can't have a zero-size range here because we would not have set found_low yet
+			THROW_CHECK2(out_of_range, lower_bound, upper_bound, lower_bound <= upper_bound);
+			const Pos delta = (upper_bound - lower_bound) / 2;
+			probe_pos = lower_bound + delta;
+			if (delta < 1) {
+				// nothing can exist in the range (lower_bound, upper_bound)
+				// and an object is known to exist at lower_bound
+				SEEKER_DEBUG_LOG("return: probe_pos == lower_bound " << lower_bound);
+				return lower_bound;
+			}
+			THROW_CHECK2(out_of_range, lower_bound, probe_pos, lower_bound <= probe_pos);
+			THROW_CHECK2(out_of_range, upper_bound, probe_pos, probe_pos <= upper_bound);
+			SEEKER_DEBUG_LOG("loop bottom: lower_bound " << lower_bound << ", probe_pos " << probe_pos << ", upper_bound " << upper_bound);
 		}
+		THROW_ERROR(runtime_error, "FIXME: should not reach this line: "
+			"lower_bound..upper_bound " << lower_bound << ".." << upper_bound << ", "
+			"found_low " << found_low);
 	}
 }
 

lib/Makefile

@@ -17,6 +17,7 @@ CRUCIBLE_OBJS = \
 	openat2.o \
 	path.o \
 	process.o \
+	seeker.o \
 	string.o \
 	table.o \
 	task.o \

lib/btrfs-tree.cc

@@ -418,6 +418,7 @@ namespace crucible {
 			++loops;
 			fill_sk(sk, unscale_logical(min(scaled_max_logical(), lower_bound)));
 			set<uint64_t> rv;
+			bool too_far = false;
 			do {
 				sk.nr_items = 4;
 				sk.do_ioctl(fd());
@@ -426,6 +427,7 @@ namespace crucible {
 					next_sk(sk, i);
 					// If hdr_stop or !hdr_match, don't inspect the item
 					if (hdr_stop(i)) {
+						too_far = true;
 						rv.insert(numeric_limits<uint64_t>::max());
 						BTFRLB_DEBUG("(stop)");
 						break;
@@ -438,22 +440,23 @@ namespace crucible {
 					BTFRLB_DEBUG(" " << to_hex(this_logical) << " " << i);
 					const auto scaled_hdr_logical = scale_logical(this_logical);
 					BTFRLB_DEBUG(" " << "(match)");
+					if (scaled_hdr_logical > upper_bound) {
+						too_far = true;
+						BTFRLB_DEBUG("(" << to_hex(scaled_hdr_logical) << " >= " << to_hex(upper_bound) << ")");
+						break;
+					}
 					if (this_logical <= logical && this_logical > closest_logical) {
 						closest_logical = this_logical;
 						closest_item = i;
 						BTFRLB_DEBUG("(closest)");
 					}
 					rv.insert(scaled_hdr_logical);
-					if (scaled_hdr_logical > upper_bound) {
-						BTFRLB_DEBUG("(" << to_hex(scaled_hdr_logical) << " >= " << to_hex(upper_bound) << ")");
-						break;
-					}
 					BTFRLB_DEBUG("(cont'd)");
 				}
 				BTFRLB_DEBUG(endl);
 				// We might get a search result that contains only non-matching items.
 				// Keep looping until we find any matching item or we run out of tree.
-			} while (rv.empty() && !sk.m_result.empty());
+			} while (!too_far && rv.empty() && !sk.m_result.empty());
 			return rv;
 		}, scale_logical(lookbehind_size()));
 		return closest_item;

lib/seeker.cc

@@ -0,0 +1,7 @@
+#include "crucible/seeker.h"
+
+namespace crucible {
+
+	thread_local shared_ptr<ostream> tl_seeker_debug_str;
+
+};

src/bees-context.cc

@@ -387,7 +387,7 @@ BeesContext::scan_one_extent(const BeesFileRange &bfr, const Extent &e)
 	if (e.flags() & Extent::PREALLOC) {
 		// Prealloc is all zero and we replace it with a hole.
 		// No special handling is required here.  Nuke it and move on.
-		BEESLOGINFO("prealloc extent " << e);
+		BEESLOGINFO("prealloc extent " << e << " in " << bfr);
 		// Must not extend past EOF
 		auto extent_size = min(e.end(), bfr.file_size()) - e.begin();
 		// Must hold tmpfile until dedupe is done

src/bees-roots.cc

@@ -5,6 +5,7 @@
 #include "crucible/cleanup.h"
 #include "crucible/ntoa.h"
 #include "crucible/openat2.h"
+#include "crucible/seeker.h"
 #include "crucible/string.h"
 #include "crucible/table.h"
 #include "crucible/task.h"
@@ -780,10 +781,6 @@ BeesScanModeExtent::SizeTier::create_extent_map(const uint64_t bytenr, const Pro
 
 	BtrfsExtentDataFetcher bedf(m_ctx->root_fd());
 
-	// Collect extent ref tasks as a series of stand-alone events
-	// chained after the first task created, then run the first one.
-	// This prevents other threads from starting to process an
-	// extent until we have all of its refs in the queue.
 	const auto refs_list = make_shared<list<ExtentRef>>();
 	for (const auto &i : log_ino.m_iors) {
 		catch_all([&](){
@@ -899,6 +896,9 @@ BeesScanModeExtent::scan()
 {
 	BEESTRACE("bsm scan");
 
+	// Do nothing if we are throttled
+	if (should_throttle()) return;
+
 	unique_lock<mutex> lock(m_mutex);
 	const auto size_tiers_copy = m_size_tiers;
 	lock.unlock();
@@ -934,12 +934,14 @@ BeesScanModeExtent::SizeTier::find_next_extent()
 
 	// Low-level extent search debugging
 	shared_ptr<ostringstream> debug_oss;
+	const bool debug_oss_only_exceptions = true;
 #if 0
 	// Enable a _lot_ of debugging output
 	debug_oss = make_shared<ostringstream>();
 #endif
 	if (debug_oss) {
 		BtrfsIoctlSearchKey::s_debug_ostream = debug_oss;
+		tl_seeker_debug_str = debug_oss;
 	}
 
 	// Write out the stats no matter how we exit
@@ -967,10 +969,13 @@ BeesScanModeExtent::SizeTier::find_next_extent()
 				);
 			}
 			if (debug_oss) {
-				BEESLOGDEBUG("debug oss trace:\n" << debug_oss->str());
+				if (!debug_oss_only_exceptions || exception_check()) {
+					BEESLOGDEBUG("debug oss trace:\n" << debug_oss->str());
+				}
 			}
 		}
 		BtrfsIoctlSearchKey::s_debug_ostream.reset();
+		tl_seeker_debug_str.reset();
 	});
 
 #define MNE_DEBUG(x) do { \
@@ -1003,7 +1008,9 @@ BeesScanModeExtent::SizeTier::find_next_extent()
 			// There is a lot of debug output.  Dump it if it gets too long
 			if (!debug_oss->str().empty()) {
 				if (crawl_time.age() > 1) {
-					BEESLOGDEBUG("debug oss trace (so far):\n" << debug_oss->str());
+					if (!debug_oss_only_exceptions) {
+						BEESLOGDEBUG("debug oss trace (so far):\n" << debug_oss->str());
+					}
 					debug_oss->str("");
 				}
 			}
@@ -1084,7 +1091,6 @@ BeesScanModeExtent::SizeTier::find_next_extent()
 			++size_low_count;
 
 			// Skip ahead over any below-min-size extents
-			BEESTRACE("min_size " << pretty(lower_size_bound) << " > scale_size " << pretty(m_fetcher.scale_size()));
 			const auto lsb_rounded = lower_size_bound & ~(m_fetcher.scale_size() - 1);
 			// Don't bother doing backward searches when skipping 128K or less.
 			// The search will cost more than reading 32 consecutive extent records.
@@ -1148,7 +1154,7 @@ BeesScanModeExtent::SizeTier::find_next_extent()
 		const auto hold_state = m_crawl->hold_state(this_state);
 		const auto sft = shared_from_this();
 		ostringstream oss;
-		oss << "map_" << to_hex(this_bytenr) << "_" << pretty(this_length);
+		oss << "map_" << hex << this_bytenr << dec << "_" << pretty(this_length);
 		Task create_map_task(oss.str(), [sft, this_bytenr, hold_state, this_length, find_next_task]() {
 			sft->create_extent_map(this_bytenr, hold_state, this_length, find_next_task);
 			BEESCOUNT(crawl_extent);
@@ -1323,23 +1329,25 @@ BeesScanModeExtent::next_transid()
 		}
 		const auto bytenr_offset = min(bi_last_bytenr, max(bytenr, bi.first_bytenr)) - bi.first_bytenr + bi.first_total;
 		const auto bytenr_norm = bytenr_offset / double(fs_size);
-		const auto time_so_far = now - min(now, this_state.m_started);
+		const auto eta_start = min(now, this_state.m_started);
+		const auto time_so_far = now - eta_start;
 		const string start_stamp = strf_localtime(this_state.m_started);
 		string eta_stamp = "-";
 		string eta_pretty = "-";
 		const auto &deferred_finished = deferred_map.at(subvol);
 		const bool finished = deferred_finished.second;
-		if (finished) {
-			// eta_stamp = "idle";
+		if (finished && m_roots->up_to_date(this_state)) {
+			eta_stamp = "idle";
 		} else if (time_so_far > 10 && bytenr_offset > 1024 * 1024 * 1024) {
 			const time_t eta_duration = time_so_far / bytenr_norm;
-			const time_t eta_time = eta_duration + now;
+			const time_t eta_time = eta_duration + eta_start;
+			const time_t eta_remain = eta_time - now;
 			eta_stamp = strf_localtime(eta_time);
-			eta_pretty = pretty_seconds(eta_duration);
+			eta_pretty = pretty_seconds(eta_remain);
 		}
 		const auto &mma = mes.m_map.at(subvol);
 		const auto mma_ratio = mes_sample_size_ok ? (mma.m_bytes / double(mes.m_total)) : 1.0;
-		const auto posn_text = Table::Text(finished ? "idle" : astringprintf("%06d", int(floor(bytenr_norm * 1000000))));
+		const auto posn_text = Table::Text(astringprintf("%06d", int(floor(bytenr_norm * 1000000))));
 		const auto size_text = Table::Text( mes_sample_size_ok ? pretty(fs_size * mma_ratio) : "-");
 		eta.insert_row(Table::endpos, vector<Table::Content> {
 			Table::Text(magic.m_max_size == numeric_limits<uint64_t>::max() ? "max" : pretty(magic.m_max_size)),
@@ -2303,16 +2311,20 @@ BeesCrawl::BeesCrawl(shared_ptr<BeesContext> ctx, BeesCrawlState initial_state)
 	}
 }
 
+bool
+BeesRoots::up_to_date(const BeesCrawlState &bcs)
+{
+	// If we are already at transid_max then we are up to date
+	return bcs.m_max_transid >= transid_max();
+}
+
 bool
 BeesCrawl::restart_crawl_unlocked()
 {
 	const auto roots = m_ctx->roots();
-	const auto next_transid = roots->transid_max();
-
 	auto crawl_state = get_state_end();
 
-	// If we are already at transid_max then we are still finished
-	m_finished = crawl_state.m_max_transid >= next_transid;
+	m_finished = roots->up_to_date(crawl_state);
 
 	if (m_finished) {
 		m_deferred = true;
@@ -2323,7 +2335,7 @@ BeesCrawl::restart_crawl_unlocked()
 
 		// Start new crawl
 		crawl_state.m_min_transid = crawl_state.m_max_transid;
-		crawl_state.m_max_transid = next_transid;
+		crawl_state.m_max_transid = roots->transid_max();
 		crawl_state.m_objectid = 0;
 		crawl_state.m_offset = 0;
 		crawl_state.m_started = current_time;

src/bees-trace.cc

@@ -8,21 +8,15 @@ thread_local BeesTracer *BeesTracer::tl_next_tracer = nullptr;
 thread_local bool BeesTracer::tl_first = true;
 thread_local bool BeesTracer::tl_silent = false;
 
+bool
+exception_check()
+{
 #if __cplusplus >= 201703
-static
-bool
-exception_check()
-{
 	return uncaught_exceptions();
-}
 #else
-static
-bool
-exception_check()
-{
 	return uncaught_exception();
-}
 #endif
+}
 
 BeesTracer::~BeesTracer()
 {

src/bees.cc

@@ -741,7 +741,7 @@ bees_main(int argc, char *argv[])
 			BEESLOGDEBUG("exception (ignored): " << s);
 			BEESCOUNT(exception_caught_silent);
 		} else {
-			BEESLOGNOTICE("\n\nTRACE: *** EXCEPTION ***\n\t" << s << "\n***\n");
+			BEESLOG(BEES_TRACE_LEVEL, "TRACE: EXCEPTION: " << s);
 			BEESCOUNT(exception_caught);
 		}
 	});

src/bees.h

@@ -588,8 +588,8 @@ class BeesRoots : public enable_shared_from_this<BeesRoots> {
 	void current_state_set(const BeesCrawlState &bcs);
 	bool crawl_batch(shared_ptr<BeesCrawl> crawl);
 	void clear_caches();
-
 	shared_ptr<BeesCrawl> insert_root(const BeesCrawlState &bcs);
+	bool up_to_date(const BeesCrawlState &bcs);
 
 friend class BeesCrawl;
 friend class BeesFdCache;
@@ -901,5 +901,6 @@ void bees_readahead_pair(int fd, off_t offset, size_t size, int fd2, off_t offse
 void bees_unreadahead(int fd, off_t offset, size_t size);
 void bees_throttle(double time_used, const char *context);
 string format_time(time_t t);
+bool exception_check();
 
 #endif

test/seeker.cc

@@ -19,7 +19,9 @@ seeker_finder(const vector<uint64_t> &vec, uint64_t lower, uint64_t upper)
 	if (ub != s.end()) ++ub;
 	if (ub != s.end()) ++ub;
 	for (; ub != s.end(); ++ub) {
-		if (*ub > upper) break;
+		if (*ub > upper) {
+			break;
+		}
 	}
 	return set<uint64_t>(lb, ub);
 }
@@ -28,7 +30,7 @@ static bool test_fails = false;
 
 static
 void
-seeker_test(const vector<uint64_t> &vec, uint64_t const target)
+seeker_test(const vector<uint64_t> &vec, uint64_t const target, bool const always_out = false)
 {
 	cerr << "Find " << target << " in {";
 	for (auto i : vec) {
@@ -36,11 +38,13 @@ seeker_test(const vector<uint64_t> &vec, uint64_t const target)
 	}
 	cerr << " } = ";
 	size_t loops = 0;
+	tl_seeker_debug_str = make_shared<ostringstream>();
+	bool local_test_fails = false;
 	bool excepted = catch_all([&]() {
-		auto found = seek_backward(target, [&](uint64_t lower, uint64_t upper) {
+		const auto found = seek_backward(target, [&](uint64_t lower, uint64_t upper) {
 			++loops;
 			return seeker_finder(vec, lower, upper);
-		});
+		}, uint64_t(32));
 		cerr << found;
 		uint64_t my_found = 0;
 		for (auto i : vec) {
@@ -52,13 +56,15 @@ seeker_test(const vector<uint64_t> &vec, uint64_t const target)
 			cerr << " (correct)";
 		} else {
 			cerr << " (INCORRECT - right answer is " << my_found << ")";
-			test_fails = true;
+			local_test_fails = true;
 		}
 	});
 	cerr << " (" << loops << " loops)" << endl;
-	if (excepted) {
-		test_fails = true;
+	if (excepted || local_test_fails || always_out) {
+		cerr << dynamic_pointer_cast<ostringstream>(tl_seeker_debug_str)->str();
 	}
+	test_fails = test_fails || local_test_fails;
+	tl_seeker_debug_str.reset();
 }
 
 static
@@ -89,6 +95,39 @@ test_seeker()
 	seeker_test(vector<uint64_t> { 0, numeric_limits<uint64_t>::max() }, numeric_limits<uint64_t>::max());
 	seeker_test(vector<uint64_t> { 0, numeric_limits<uint64_t>::max() }, numeric_limits<uint64_t>::max() - 1);
 	seeker_test(vector<uint64_t> { 0, numeric_limits<uint64_t>::max() - 1 }, numeric_limits<uint64_t>::max());
+
+	seeker_test(vector<uint64_t> { 0, 1, 2, 4, 8 }, 0);
+	seeker_test(vector<uint64_t> { 0, 1, 2, 4, 8 }, 1);
+	seeker_test(vector<uint64_t> { 0, 1, 2, 4, 8 }, 2);
+	seeker_test(vector<uint64_t> { 0, 1, 2, 4, 8 }, 3);
+	seeker_test(vector<uint64_t> { 0, 1, 2, 4, 8 }, 4);
+	seeker_test(vector<uint64_t> { 0, 1, 2, 4, 8 }, 5);
+	seeker_test(vector<uint64_t> { 0, 1, 2, 4, 8 }, 6);
+	seeker_test(vector<uint64_t> { 0, 1, 2, 4, 8 }, 7);
+	seeker_test(vector<uint64_t> { 0, 1, 2, 4, 8 }, 8);
+	seeker_test(vector<uint64_t> { 0, 1, 2, 4, 8 }, 9);
+	seeker_test(vector<uint64_t> { 0, 1, 2, 4, 8 }, numeric_limits<uint64_t>::max() );
+	seeker_test(vector<uint64_t> { 0, 1, 2, 4, 8 }, numeric_limits<uint64_t>::max() - 1 );
+	seeker_test(vector<uint64_t> { 0, 1, 2, 4, 8 }, numeric_limits<uint64_t>::max() - 2 );
+	seeker_test(vector<uint64_t> { 0, 1, 2, 4, 8 }, numeric_limits<uint64_t>::max() - 3 );
+	seeker_test(vector<uint64_t> { 0, 1, 2, 4, 8 }, numeric_limits<uint64_t>::max() - 4 );
+	seeker_test(vector<uint64_t> { 0, 1, 2, 4, 8 }, numeric_limits<uint64_t>::max() - 5 );
+	seeker_test(vector<uint64_t> { 0, 1, 2, 4, 8 }, numeric_limits<uint64_t>::max() - 6 );
+	seeker_test(vector<uint64_t> { 0, 1, 2, 4, 8 }, numeric_limits<uint64_t>::max() - 7 );
+	seeker_test(vector<uint64_t> { 0, 1, 2, 4, 8 }, numeric_limits<uint64_t>::max() - 8 );
+
+	// Pulled from a bees debug log
+	seeker_test(vector<uint64_t> {
+		6821962845,
+		6821962848,
+		6821963411,
+		6821963422,
+		6821963536,
+		6821963539,
+		6821963835, // <- appeared during the search, causing an exception
+		6821963841,
+		6822575316,
+	}, 6821971036, true);
 }