🚸 Improve logging of compile-time values

elbeno · elbeno · commit 5c187349458e · 2025-07-03T09:50:49.000-06:00
Problem:
- It's easy to accidentally forget to wrap compile-time values (with `CX_VALUE`
  or `std::ct`) for logging, and accidentally get runtime values instead.
- Even when wrapping correctly, the resulting log call site is verbose.

Solution:
- Automatically preserve compile-time values where possible.
diff --git a/CMakeLists.txt b/CMakeLists.txt
@@ -120,7 +120,8 @@ target_sources(
               include/log/flavor.hpp
               include/log/level.hpp
               include/log/log.hpp
-              include/log/module.hpp)
+              include/log/module.hpp
+              include/log/pp_map.hpp)
 
 add_library(cib_msg INTERFACE)
 target_compile_features(cib_msg INTERFACE cxx_std_20)
diff --git a/include/log/log.hpp b/include/log/log.hpp
@@ -4,6 +4,7 @@
 #include <log/flavor.hpp>
 #include <log/level.hpp>
 #include <log/module.hpp>
+#include <log/pp_map.hpp>
 
 #include <stdx/compiler.hpp>
 #include <stdx/ct_format.hpp>
@@ -55,18 +56,50 @@ static auto log(TArgs &&...args) -> void {
     auto &cfg = get_config<Env, Ts...>();
     cfg.logger.template log<Env>(std::forward<TArgs>(args)...);
 }
+
+namespace detail {
+template <typename> constexpr auto is_already_ct = false;
+template <typename T, T V>
+constexpr auto is_already_ct<std::integral_constant<T, V>> = true;
+template <stdx::ct_string S>
+constexpr auto is_already_ct<stdx::cts_t<S>> = true;
+template <typename T>
+constexpr auto is_already_ct<stdx::type_identity<T>> = true;
+
+template <auto> constexpr auto test_ct() {}
+
+template <stdx::ct_string Msg> constexpr auto cx_log_wrap(int, auto &&...args) {
+    return stdx::ct_format<Msg>(FWD(args)...);
+}
+} // namespace detail
 } // namespace logging
 
 // NOLINTBEGIN(cppcoreguidelines-macro-usage)
 
+#define CIB_CX_WRAP1(X)                                                        \
+    [&](auto f) {                                                              \
+        if constexpr (::logging::detail::is_already_ct<decltype(f())>) {       \
+            return f();                                                        \
+        } else if constexpr (requires { ::logging::detail::test_ct<X>; }) {    \
+            return stdx::ct<f()>();                                            \
+        } else {                                                               \
+            return f();                                                        \
+        }                                                                      \
+    }([&] { return X; })
+
+#define CIB_CX_WRAP(...) __VA_OPT__(, CIB_CX_WRAP1(__VA_ARGS__))
+
 #define CIB_LOG(MSG, ...)                                                      \
     logging::log<cib_log_env_t>(__FILE__, __LINE__,                            \
-                                stdx::ct_format<MSG>(__VA_ARGS__))
+                                logging::detail::cx_log_wrap<MSG>(             \
+                                    0 CIB_MAP(CIB_CX_WRAP, __VA_ARGS__)))
 
 #define CIB_LOG_WITH_LEVEL(LEVEL, MSG, ...)                                    \
     logging::log<                                                              \
         stdx::extend_env_t<cib_log_env_t, logging::get_level, LEVEL>>(         \
-        __FILE__, __LINE__, stdx::ct_format<MSG>(__VA_ARGS__))
+        __FILE__, __LINE__,                                                    \
+        logging::detail::cx_log_wrap<MSG>(                                     \
+            0 CIB_MAP(CIB_CX_WRAP, __VA_ARGS__)))
 
 #define CIB_TRACE(...)                                                         \
     CIB_LOG_WITH_LEVEL(logging::level::TRACE __VA_OPT__(, ) __VA_ARGS__)
@@ -127,7 +160,7 @@ template <stdx::ct_string Fmt, typename Env, typename F, typename L>
 
 #define CIB_FATAL(MSG, ...)                                                    \
     logging::detail::panic<MSG, cib_log_env_t>(                                \
-        __FILE__, __LINE__ __VA_OPT__(, ) __VA_ARGS__)
+        __FILE__, __LINE__ CIB_MAP(CIB_CX_WRAP, __VA_ARGS__))
 
 #define CIB_ASSERT(expr, ...)                                                  \
     ((expr)                                                                    \
diff --git a/include/log/pp_map.hpp b/include/log/pp_map.hpp
@@ -0,0 +1,35 @@
+#pragma once
+
+// NOLINTBEGIN(cppcoreguidelines-macro-usage)
+
+#define CIB_EVAL0(...) __VA_ARGS__
+#define CIB_EVAL1(...) CIB_EVAL0(CIB_EVAL0(CIB_EVAL0(__VA_ARGS__)))
+#define CIB_EVAL2(...) CIB_EVAL1(CIB_EVAL1(CIB_EVAL1(__VA_ARGS__)))
+#define CIB_EVAL3(...) CIB_EVAL2(CIB_EVAL2(CIB_EVAL2(__VA_ARGS__)))
+#define CIB_EVAL4(...) CIB_EVAL3(CIB_EVAL3(CIB_EVAL3(__VA_ARGS__)))
+#define CIB_EVAL5(...) CIB_EVAL4(CIB_EVAL4(CIB_EVAL4(__VA_ARGS__)))
+#define CIB_EVAL(...) CIB_EVAL5(__VA_ARGS__)
+
+#define CIB_MAP_END(...)
+#define CIB_MAP_OUT
+
+#define CIB_EMPTY()
+#define CIB_DEFER(id) id CIB_EMPTY()
+
+#define CIB_MAP_GET_END2() 0, CIB_MAP_END
+#define CIB_MAP_GET_END1(...) CIB_MAP_GET_END2
+#define CIB_MAP_GET_END(...) CIB_MAP_GET_END1
+#define CIB_MAP_NEXT0(test, next, ...) next CIB_MAP_OUT
+#define CIB_MAP_NEXT1(test, next) CIB_DEFER(CIB_MAP_NEXT0)(test, next, 0)
+#define CIB_MAP_NEXT(test, next) CIB_MAP_NEXT1(CIB_MAP_GET_END test, next)
+#define CIB_MAP_INC(X) CIB_MAP_INC_##X
+
+#define CIB_MAP0(f, x, peek, ...)                                              \
+    f(x) CIB_DEFER(CIB_MAP_NEXT(peek, CIB_MAP1))(f, peek, __VA_ARGS__)
+#define CIB_MAP1(f, x, peek, ...)                                              \
+    f(x) CIB_DEFER(CIB_MAP_NEXT(peek, CIB_MAP0))(f, peek, __VA_ARGS__)
+
+#define CIB_MAP(f, ...)                                                        \
+    CIB_EVAL(CIB_MAP1(f, __VA_ARGS__, ()()(), ()()(), ()()(), 0))
+
+// NOLINTEND(cppcoreguidelines-macro-usage)
diff --git a/include/msg/callback.hpp b/include/msg/callback.hpp
@@ -46,15 +46,14 @@ struct callback {
     auto log_mismatch(auto const &data) const -> void {
         CIB_LOG_ENV(logging::get_level, logging::level::INFO);
         {
+            auto const desc = msg::call_with_message<Msg>(
+                [&]<typename T>(T &&t) -> decltype(matcher.describe_match(
+                                           std::forward<T>(t))) {
+                    return matcher.describe_match(std::forward<T>(t));
+                },
+                data);
             CIB_APPEND_LOG_ENV(typename Msg::env_t);
-            CIB_LOG(
-                "    {} - F:({})", stdx::cts_t<Name>{},
-                msg::call_with_message<Msg>(
-                    [&]<typename T>(T &&t) -> decltype(matcher.describe_match(
-                                               std::forward<T>(t))) {
-                        return matcher.describe_match(std::forward<T>(t));
-                    },
-                    data));
+            CIB_LOG("    {} - F:({})", stdx::cts_t<Name>{}, desc);
         }
     }
 
diff --git a/test/log/encoder.cpp b/test/log/encoder.cpp
@@ -310,16 +310,57 @@ TEST_CASE("log version information (long with string)", "[mipi]") {
     CHECK(num_log_args_calls == 1);
 }
 
+namespace {
+std::vector<std::uint32_t> expected_args{};
+
+template <logging::level Level> struct test_log_injected_destination {
+    template <typename... Args>
+    auto log_by_args(std::uint32_t header, Args... args) {
+        ++num_log_args_calls;
+        auto const Header = expected_msg_header(Level, test_module_id,
+                                                std::size(expected_args));
+        REQUIRE(header == Header);
+        REQUIRE(sizeof...(Args) == std::size(expected_args));
+        [&]<std::size_t... Is>(std::index_sequence<Is...>) {
+            (check(args, expected_args[Is]), ...);
+        }(std::make_index_sequence<sizeof...(Args)>{});
+    }
+};
+} // namespace
+
 template <>
-inline auto logging::config<> =
-    logging::binary::config{test_log_args_destination<logging::level::TRACE>{}};
+inline auto logging::config<> = logging::binary::config{
+    test_log_injected_destination<logging::level::TRACE>{}};
 
 TEST_CASE("injection", "[mipi]") {
     test_critical_section::count = 0;
+    expected_args.clear();
     CIB_TRACE("Hello");
     CHECK(test_critical_section::count == 2);
 }
 
+TEST_CASE("injection - log runtime arg", "[mipi]") {
+    test_critical_section::count = 0;
+    expected_args = std::vector<std::uint32_t>{42, 17};
+    auto x = 17;
+    CIB_TRACE("Hello {}", x);
+    CHECK(test_critical_section::count == 2);
+}
+
+TEST_CASE("injection - log implicit compile-time arg", "[mipi]") {
+    test_critical_section::count = 0;
+    expected_args.clear();
+    CIB_TRACE("Hello {}", 42);
+    CHECK(test_critical_section::count == 2);
+}
+
+TEST_CASE("injection - log explicit compile-time arg", "[mipi]") {
+    test_critical_section::count = 0;
+    expected_args.clear();
+    CIB_TRACE("Hello {}", stdx::ct<42>());
+    CHECK(test_critical_section::count == 2);
+}
+
 namespace {
 int num_catalog_args_calls{};
 
diff --git a/test/log/log.cpp b/test/log/log.cpp
@@ -87,7 +87,7 @@ TEST_CASE("CIB_FATAL pre-formats arguments passed to panic", "[log]") {
     CHECK(panicked);
 }
 
-TEST_CASE("CIB_FATAL can format stack arguments", "[log]") {
+TEST_CASE("CIB_FATAL can format stack arguments (1)", "[log]") {
     reset_test_state();
     expected_why = "Hello {}";
     expected_args = std::make_tuple(stdx::make_tuple(42));
@@ -99,10 +99,38 @@ TEST_CASE("CIB_FATAL can format stack arguments", "[log]") {
     CHECK(panicked);
 }
 
+TEST_CASE("CIB_FATAL can format stack arguments (2)", "[log]") {
+    reset_test_state();
+    expected_why = "Hello {}";
+    expected_args =
+        std::make_tuple(stdx::make_tuple(std::string_view{"world"}));
+
+    auto x = std::string_view{"world"};
+    CIB_FATAL("Hello {}", x);
+    CAPTURE(buffer);
+    CHECK(buffer.find("Hello world") != std::string::npos);
+    CHECK(panicked);
+}
+
+TEST_CASE("CIB_FATAL formats compile-time arguments where possible", "[log]") {
+    using namespace stdx::literals;
+    reset_test_state();
+    expected_why = "Hello 42";
+    expected_args = std::make_tuple(stdx::make_tuple());
+
+    []<stdx::ct_string S>() {
+        CIB_FATAL("{} {}", S, 42);
+    }.template operator()<"Hello">();
+
+    CAPTURE(buffer);
+    CHECK(buffer.find("Hello 42") != std::string::npos);
+    CHECK(panicked);
+}
+
 TEST_CASE("CIB_FATAL passes extra arguments to panic", "[log]") {
     reset_test_state();
     expected_why = "Hello {}";
-    expected_args = std::make_tuple(stdx::make_tuple(42), 17);
+    expected_args = std::make_tuple(stdx::make_tuple(42), stdx::ct<17>());
 
     auto x = 42;
     CIB_FATAL("Hello {}", x, 17);
@@ -124,7 +152,7 @@ TEST_CASE("CIB_ASSERT is equivalent to CIB_FATAL on failure", "[log]") {
 TEST_CASE("CIB_ASSERT passes arguments to panic", "[log]") {
     reset_test_state();
     expected_why = "Assertion failure: true == false";
-    expected_args = std::make_tuple(stdx::make_tuple(), 42);
+    expected_args = std::make_tuple(stdx::make_tuple(), stdx::ct<42>());
 
     CIB_ASSERT(true == false, 42);
     CAPTURE(buffer);
