Capture and inspect all logs in Catch2 tests

This fixes a long-standing race condition that existed with
test_utils::log_capture, which is has now been removed.

Tests now unconditionally capturing logs in the global thread-safe
test_utils::log_test_capture. This allows the test code to query captured
messages, and will echo the captured logs through a global Catch2 hook if the
test fails. By default, this mechanism will fail any test that logs a warning
or error, but it provides functions to relax that behavior either explicitly
through test_utils::allow_max_log_level or implicitly through runtime_fixture /
device_queue_fixture which permit system-dependent warnings to appear.

The "log.h" interface has also been simplified somewhat.

Author: fknorr

CHANGELOG.md

@@ -28,6 +28,7 @@ Versioning](http://semver.org/spec/v2.0.0.html).
 - In edge cases, command graph generation would fail to generate await-push commands when re-distributing reduction results (#223)
 - Command graph generation was missing an anti-dependency between push-commands of partial reduction results and the final reduction command (#223)
 - Don't create multiple smaller push-commands instead of a single large one in some rare situations (#229)
+- Unit tests that inspect logs contained a race that would cause spurious failures (??)
 
 ## [0.4.1] - 2023-09-08
 

include/config.h

@@ -2,8 +2,8 @@
 
 #include <cstddef>
 #include <optional>
-#include <string_view>
-#include <vector>
+
+#include "log.h"
 
 namespace celerity {
 namespace detail {
@@ -27,6 +27,8 @@ namespace detail {
 		 */
 		config(int* argc, char** argv[]);
 
+		log_level get_log_level() const { return m_log_lvl; }
+
 		const host_config& get_host_config() const { return m_host_cfg; }
 
 		/**
@@ -50,6 +52,7 @@ namespace detail {
 		std::optional<int> get_horizon_max_parallelism() const { return m_horizon_max_parallelism; }
 
 	  private:
+		log_level m_log_lvl;
 		host_config m_host_cfg;
 		std::optional<device_config> m_device_cfg;
 		std::optional<bool> m_enable_device_profiling;

include/log.h

@@ -1,20 +1,16 @@
 #pragma once
 
 #include <string>
-#include <string_view>
-#include <unordered_map>
-#include <utility>
-#include <variant>
 
 #include <spdlog/spdlog.h>
 
-#include "print_utils.h"
+#include "print_utils.h" // any translation unit that needs logging probably also wants pretty-printing
+#include "utils.h"
 
-#define CELERITY_LOG_SET_SCOPED_CTX(ctx) CELERITY_DETAIL_LOG_SET_SCOPED_CTX(ctx)
 
 #define CELERITY_LOG(level, ...)                                                                                                                               \
 	(::spdlog::should_log(level)                                                                                                                               \
-	        ? SPDLOG_LOGGER_CALL(::spdlog::default_logger_raw(), level, "{}{}", *::celerity::detail::active_log_ctx, ::fmt::format(__VA_ARGS__))               \
+	        ? SPDLOG_LOGGER_CALL(::spdlog::default_logger_raw(), level, "{}{}", ::celerity::detail::active_log_ctx->repr, ::fmt::format(__VA_ARGS__))          \
 	        : (void)0)
 
 // TODO Add a macro similar to SPDLOG_ACTIVE_LEVEL, configurable through CMake
@@ -25,68 +21,44 @@
 #define CELERITY_ERROR(...) CELERITY_LOG(::celerity::detail::log_level::err, __VA_ARGS__)
 #define CELERITY_CRITICAL(...) CELERITY_LOG(::celerity::detail::log_level::critical, __VA_ARGS__)
 
-namespace celerity {
-namespace detail {
+namespace celerity::detail {
 
-	using log_level = spdlog::level::level_enum;
+using log_level = spdlog::level::level_enum;
 
-	template <typename... Es>
-	struct log_map {
-		const std::tuple<Es...>& entries;
-		log_map(const std::tuple<Es...>& entries) : entries(entries) {}
-	};
-
-	struct log_context {
-		std::string value;
-		log_context() = default;
-		template <typename... Es>
-		explicit log_context(const std::tuple<Es...>& entries) {
-			static_assert(sizeof...(Es) % 2 == 0, "log_context requires key/value pairs");
-			value = fmt::format("[{}] ", log_map{entries});
-		}
-	};
-
-	inline const std::string null_log_ctx;
-	inline thread_local const std::string* active_log_ctx = &null_log_ctx;
+struct log_context {
+	std::string repr;
 
-	struct log_ctx_setter {
-		log_ctx_setter(log_context& ctx) { celerity::detail::active_log_ctx = &ctx.value; }
-		~log_ctx_setter() { celerity::detail::active_log_ctx = &celerity::detail::null_log_ctx; }
-	};
+	log_context() = default;
 
-#define CELERITY_DETAIL_LOG_SET_SCOPED_CTX(ctx)                                                                                                                \
-	log_ctx_setter _set_log_ctx_##__COUNTER__ { ctx }
-
-	template <typename Tuple, typename Callback>
-	constexpr void tuple_for_each_pair_impl(const Tuple&, Callback&&, std::index_sequence<>) {}
-
-	template <typename Tuple, size_t I1, size_t I2, size_t... Is, typename Callback>
-	constexpr void tuple_for_each_pair_impl(const Tuple& tuple, const Callback& cb, std::index_sequence<I1, I2, Is...>) {
-		cb(std::get<I1>(tuple), std::get<I2>(tuple));
-		tuple_for_each_pair_impl(tuple, cb, std::index_sequence<Is...>{});
-	}
-
-	template <typename Tuple, typename Callback>
-	constexpr void tuple_for_each_pair(const Tuple& tuple, const Callback& cb) {
-		static_assert(std::tuple_size_v<Tuple> % 2 == 0, "an even number of entries is required");
-		tuple_for_each_pair_impl(tuple, cb, std::make_index_sequence<std::tuple_size_v<Tuple>>{});
+	template <typename... Es>
+	explicit log_context(const std::tuple<Es...>& entries) {
+		static_assert(sizeof...(Es) % 2 == 0, "log_context requires key/value pairs");
+		if constexpr(sizeof...(Es) > 0) {
+			repr += "[";
+			int i = 0;
+			celerity::detail::utils::tuple_for_each_pair(entries, [&](const auto& a, const auto& b) {
+				if(i++ > 0) { repr += ", "; }
+				fmt::format_to(std::back_inserter(repr), "{}={}", a, b);
+			});
+			repr += "] ";
+		}
 	}
+};
 
-} // namespace detail
-} // namespace celerity
+inline const log_context null_log_ctx;
+inline thread_local const log_context* active_log_ctx = &null_log_ctx;
 
-template <typename... Es>
-struct fmt::formatter<celerity::detail::log_map<Es...>> {
-	constexpr auto parse(format_parse_context& ctx) { return ctx.begin(); }
+class set_log_context_guard {
+  public:
+	set_log_context_guard(const log_context& ctx) : m_ctx_before(celerity::detail::active_log_ctx) { celerity::detail::active_log_ctx = &ctx; }
+	set_log_context_guard(const set_log_context_guard&) = delete;
+	set_log_context_guard(set_log_context_guard&&) = delete;
+	set_log_context_guard& operator=(const set_log_context_guard&) = delete;
+	set_log_context_guard& operator=(set_log_context_guard&&) = delete;
+	~set_log_context_guard() { celerity::detail::active_log_ctx = m_ctx_before; }
 
-	template <typename FormatContext>
-	auto format(const celerity::detail::log_map<Es...>& map, FormatContext& ctx) {
-		auto&& out = ctx.out();
-		int i = 0;
-		tuple_for_each_pair(map.entries, [&i, &out](auto& a, auto& b) {
-			if(i++ > 0) { fmt::format_to(out, ", "); }
-			fmt::format_to(out, "{}={}", a, b);
-		});
-		return out;
-	}
+  private:
+	const log_context* m_ctx_before;
 };
+
+} // namespace celerity::detail

include/utils.h

@@ -60,36 +60,55 @@ struct pair_hash {
 	}
 };
 
-namespace utils_detail {
-
-	template <typename... Without, typename... ToKeep, typename T, typename... Ts>
-	static auto tuple_without_impl(const std::tuple<ToKeep...>& to_keep, const std::tuple<T, Ts...>& to_check) {
-		if constexpr((std::is_same_v<T, Without> || ...)) {
-			if constexpr(sizeof...(Ts) == 0) {
-				return to_keep;
-			} else {
-				return tuple_without_impl<Without...>(to_keep, std::tuple{std::get<Ts>(to_check)...});
-			}
+} // namespace celerity::detail::utils
+
+namespace celerity::detail::utils_detail {
+
+template <typename... Without, typename... ToKeep, typename T, typename... Ts>
+constexpr auto tuple_without_impl(const std::tuple<ToKeep...>& to_keep, const std::tuple<T, Ts...>& to_check) {
+	if constexpr((std::is_same_v<T, Without> || ...)) {
+		if constexpr(sizeof...(Ts) == 0) {
+			return to_keep;
 		} else {
-			if constexpr(sizeof...(Ts) == 0) {
-				return std::tuple_cat(to_keep, to_check);
-			} else {
-				return tuple_without_impl<Without...>(std::tuple_cat(to_keep, std::tuple{std::get<T>(to_check)}), std::tuple{std::get<Ts>(to_check)...});
-			}
+			return tuple_without_impl<Without...>(to_keep, std::tuple{std::get<Ts>(to_check)...});
+		}
+	} else {
+		if constexpr(sizeof...(Ts) == 0) {
+			return std::tuple_cat(to_keep, to_check);
+		} else {
+			return tuple_without_impl<Without...>(std::tuple_cat(to_keep, std::tuple{std::get<T>(to_check)}), std::tuple{std::get<Ts>(to_check)...});
 		}
 	}
+}
 
-} // namespace utils_detail
+template <typename Tuple, typename Callback>
+constexpr void tuple_for_each_pair_impl(const Tuple&, Callback&&, std::index_sequence<>) {}
+
+template <typename Tuple, size_t I1, size_t I2, size_t... Is, typename Callback>
+constexpr void tuple_for_each_pair_impl(const Tuple& tuple, const Callback& cb, std::index_sequence<I1, I2, Is...>) {
+	cb(std::get<I1>(tuple), std::get<I2>(tuple));
+	tuple_for_each_pair_impl(tuple, cb, std::index_sequence<Is...>{});
+}
+
+} // namespace celerity::detail::utils_detail
+
+namespace celerity::detail::utils {
 
 template <typename... Without, typename... Ts>
-static auto tuple_without(const std::tuple<Ts...>& tuple) {
+constexpr auto tuple_without(const std::tuple<Ts...>& tuple) {
 	if constexpr(sizeof...(Ts) > 0) {
 		return utils_detail::tuple_without_impl<Without...>({}, tuple);
 	} else {
 		return tuple;
 	}
 }
 
+template <typename Tuple, typename Callback>
+constexpr void tuple_for_each_pair(const Tuple& tuple, const Callback& cb) {
+	static_assert(std::tuple_size_v<Tuple> % 2 == 0, "an even number of entries is required");
+	utils_detail::tuple_for_each_pair_impl(tuple, cb, std::make_index_sequence<std::tuple_size_v<Tuple>>{});
+}
+
 /// Fiddles out the base name of a (possibly templated) struct or class from a full (possibly mangled) type name.
 /// The input parameter should be `typeid(Struct*)`, i.e. a _pointer_ to the desired struct type.
 std::string get_simplified_type_name_from_pointer(const std::type_info& pointer_type_info);

src/config.cc

@@ -170,17 +170,10 @@ namespace detail {
 			// ------------------------------- CELERITY_LOG_LEVEL ---------------------------------
 
 #if defined(CELERITY_DETAIL_ENABLE_DEBUG)
-			const auto log_lvl = parsed_and_validated_envs.get_or(env_log_level, log_level::debug);
+			m_log_lvl = parsed_and_validated_envs.get_or(env_log_level, log_level::debug);
 #else
-			const auto log_lvl = parsed_and_validated_envs.get_or(env_log_level, log_level::info);
+			m_log_lvl = parsed_and_validated_envs.get_or(env_log_level, log_level::info);
 #endif
-			// Set both the global log level and the default sink level so that the console logger adheres to CELERITY_LOG_LEVEL even if we temporarily
-			// override the global level in test_utils::log_capture.
-			// TODO do not modify global state in the constructor, but factor the LOG_LEVEL part out of detail::config entirely.
-			spdlog::set_level(log_lvl);
-			for(auto& sink : spdlog::default_logger_raw()->sinks()) {
-				sink->set_level(log_lvl);
-			}
 
 			// --------------------------------- CELERITY_DEVICES ---------------------------------
 

src/runtime.cc

@@ -121,7 +121,10 @@ namespace detail {
 		MPI_Comm_rank(MPI_COMM_WORLD, &world_rank);
 		m_local_nid = world_rank;
 
-		spdlog::set_pattern(fmt::format("[%Y-%m-%d %H:%M:%S.%e] [{:0{}}] [%^%l%$] %v", world_rank, int(ceil(log10(world_size)))));
+		if(!m_test_mode) { // do not touch logger settings in tests, where the full (trace) logs are captured
+			spdlog::set_level(m_cfg->get_log_level());
+			spdlog::set_pattern(fmt::format("[%Y-%m-%d %H:%M:%S.%e] [{:0{}}] [%^%l%$] %v", world_rank, int(ceil(log10(world_size)))));
+		}
 
 #ifndef __APPLE__
 		if(const uint32_t cores = affinity_cores_available(); cores < min_cores_needed) {

src/utils.cc

@@ -71,17 +71,17 @@ void set_panic_solution(panic_solution solution) { g_panic_solution.store(soluti
 
 [[noreturn]] void panic(const std::string& msg) {
 	switch(g_panic_solution.load(std::memory_order_relaxed)) {
-	case celerity::detail::utils::panic_solution::throw_logic_error: //
+	case celerity::detail::utils::panic_solution::throw_logic_error: {
 		throw std::logic_error(msg);
+	}
 	case celerity::detail::utils::panic_solution::log_and_abort:
-	default:
-		if(spdlog::should_log(spdlog::level::critical)) {
-			CELERITY_CRITICAL("panic: {}", msg);
-		} else {
-			fmt::print(stderr, "celerity-runtime panic: {}\n", msg);
-		}
+	default: {
+		// Print directly instead of logging: The abort message must not be hidden by log level setting, and in tests would be captured without the logging
+		// infrastructure having a chance of dumping the logs due to the abort.
+		fmt::print(stderr, "celerity-runtime panic: {}\n", msg);
 		std::abort();
 	}
+	}
 }
 
 void report_error(const error_policy policy, const std::string& msg) {

src/worker_job.cc

@@ -19,7 +19,8 @@ namespace detail {
 	// --------------------------------------------------------------------------------------------------------------------
 
 	void worker_job::update() {
-		CELERITY_LOG_SET_SCOPED_CTX(m_lctx);
+		set_log_context_guard lctx_guard(m_lctx);
+
 		assert(m_running && !m_done);
 		const auto before = std::chrono::steady_clock::now();
 		m_done = execute(m_pkg);
@@ -40,7 +41,8 @@ namespace detail {
 	}
 
 	void worker_job::start() {
-		CELERITY_LOG_SET_SCOPED_CTX(m_lctx);
+		set_log_context_guard lctx_guard(m_lctx);
+
 		assert(!m_running);
 		m_running = true;
 

test/CMakeLists.txt

@@ -50,8 +50,8 @@ set(TEST_TARGETS
   device_selection_tests
 )
 
-add_library(test_main test_main.cc grid_test_utils.cc)
-set_test_target_parameters(test_main test_main.cc grid_test_utils.cc)
+add_library(test_main test_main.cc test_utils.cc grid_test_utils.cc)
+set_test_target_parameters(test_main test_main.cc test_utils.cc grid_test_utils.cc)
 
 set(TEST_OBJ_LIST "")
 foreach(TEST_TARGET ${TEST_TARGETS})