Skip to content

Commit d5b28f1

Browse files
elbenoelbeno
committed
🚸 Improve logging of compile-time values
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.
1 parent 11e9777 commit d5b28f1

File tree

5 files changed

+139
-9
lines changed

5 files changed

+139
-9
lines changed

‎CMakeLists.txt‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -120,7 +120,8 @@ target_sources(
120120
include/log/flavor.hpp
121121
include/log/level.hpp
122122
include/log/log.hpp
123-
include/log/module.hpp)
123+
include/log/module.hpp
124+
include/log/pp_map.hpp)
124125

125126
add_library(cib_msg INTERFACE)
126127
target_compile_features(cib_msg INTERFACE cxx_std_20)

‎include/log/log.hpp‎

Lines changed: 28 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@
44
#include <log/flavor.hpp>
55
#include <log/level.hpp>
66
#include <log/module.hpp>
7+
#include <log/pp_map.hpp>
78

89
#include <stdx/compiler.hpp>
910
#include <stdx/ct_format.hpp>
@@ -55,18 +56,42 @@ static auto log(TArgs &&...args) -> void {
5556
auto &cfg = get_config<Env, Ts...>();
5657
cfg.logger.template log<Env>(std::forward<TArgs>(args)...);
5758
}
59+
60+
namespace detail {
61+
template <typename F> constexpr auto cx_wrap(F f) {
62+
// NOLINTBEGIN(bugprone-branch-clone)
63+
if constexpr (requires { stdx::ct<decltype(f())::value>(); }) {
64+
return f();
65+
} else if constexpr (requires { stdx::ct<f()>(); }) {
66+
return stdx::ct<f()>();
67+
} else {
68+
return f();
69+
}
70+
// NOLINTEND(bugprone-branch-clone)
71+
}
72+
73+
template <stdx::ct_string Msg> constexpr auto cx_log_wrap(int, auto &&...args) {
74+
return stdx::ct_format<Msg>(FWD(args)...);
75+
}
76+
} // namespace detail
5877
} // namespace logging
5978

6079
// NOLINTBEGIN(cppcoreguidelines-macro-usage)
6180

81+
#define CIB_CX_WRAP(...) \
82+
__VA_OPT__(, logging::detail::cx_wrap([&] { return __VA_ARGS__; }))
83+
6284
#define CIB_LOG(MSG, ...) \
6385
logging::log<cib_log_env_t>(__FILE__, __LINE__, \
64-
stdx::ct_format<MSG>(__VA_ARGS__))
86+
logging::detail::cx_log_wrap<MSG>( \
87+
0 CIB_MAP(CIB_CX_WRAP, __VA_ARGS__)))
6588

6689
#define CIB_LOG_WITH_LEVEL(LEVEL, MSG, ...) \
6790
logging::log< \
6891
stdx::extend_env_t<cib_log_env_t, logging::get_level, LEVEL>>( \
69-
__FILE__, __LINE__, stdx::ct_format<MSG>(__VA_ARGS__))
92+
__FILE__, __LINE__, \
93+
logging::detail::cx_log_wrap<MSG>( \
94+
0 CIB_MAP(CIB_CX_WRAP, __VA_ARGS__)))
7095

7196
#define CIB_TRACE(...) \
7297
CIB_LOG_WITH_LEVEL(logging::level::TRACE __VA_OPT__(, ) __VA_ARGS__)
@@ -127,7 +152,7 @@ template <stdx::ct_string Fmt, typename Env, typename F, typename L>
127152

128153
#define CIB_FATAL(MSG, ...) \
129154
logging::detail::panic<MSG, cib_log_env_t>( \
130-
__FILE__, __LINE__ __VA_OPT__(, ) __VA_ARGS__)
155+
__FILE__, __LINE__ CIB_MAP(CIB_CX_WRAP, __VA_ARGS__))
131156

132157
#define CIB_ASSERT(expr, ...) \
133158
((expr) \

‎include/log/pp_map.hpp‎

Lines changed: 35 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,35 @@
1+
#pragma once
2+
3+
// NOLINTBEGIN(cppcoreguidelines-macro-usage)
4+
5+
#define CIB_EVAL0(...) __VA_ARGS__
6+
#define CIB_EVAL1(...) CIB_EVAL0(CIB_EVAL0(CIB_EVAL0(__VA_ARGS__)))
7+
#define CIB_EVAL2(...) CIB_EVAL1(CIB_EVAL1(CIB_EVAL1(__VA_ARGS__)))
8+
#define CIB_EVAL3(...) CIB_EVAL2(CIB_EVAL2(CIB_EVAL2(__VA_ARGS__)))
9+
#define CIB_EVAL4(...) CIB_EVAL3(CIB_EVAL3(CIB_EVAL3(__VA_ARGS__)))
10+
#define CIB_EVAL5(...) CIB_EVAL4(CIB_EVAL4(CIB_EVAL4(__VA_ARGS__)))
11+
#define CIB_EVAL(...) CIB_EVAL5(__VA_ARGS__)
12+
13+
#define CIB_MAP_END(...)
14+
#define CIB_MAP_OUT
15+
16+
#define CIB_EMPTY()
17+
#define CIB_DEFER(id) id CIB_EMPTY()
18+
19+
#define CIB_MAP_GET_END2() 0, CIB_MAP_END
20+
#define CIB_MAP_GET_END1(...) CIB_MAP_GET_END2
21+
#define CIB_MAP_GET_END(...) CIB_MAP_GET_END1
22+
#define CIB_MAP_NEXT0(test, next, ...) next CIB_MAP_OUT
23+
#define CIB_MAP_NEXT1(test, next) CIB_DEFER(CIB_MAP_NEXT0)(test, next, 0)
24+
#define CIB_MAP_NEXT(test, next) CIB_MAP_NEXT1(CIB_MAP_GET_END test, next)
25+
#define CIB_MAP_INC(X) CIB_MAP_INC_##X
26+
27+
#define CIB_MAP0(f, x, peek, ...) \
28+
f(x) CIB_DEFER(CIB_MAP_NEXT(peek, CIB_MAP1))(f, peek, __VA_ARGS__)
29+
#define CIB_MAP1(f, x, peek, ...) \
30+
f(x) CIB_DEFER(CIB_MAP_NEXT(peek, CIB_MAP0))(f, peek, __VA_ARGS__)
31+
32+
#define CIB_MAP(f, ...) \
33+
CIB_EVAL(CIB_MAP1(f, __VA_ARGS__, ()()(), ()()(), ()()(), 0))
34+
35+
// NOLINTEND(cppcoreguidelines-macro-usage)

‎test/log/encoder.cpp‎

Lines changed: 43 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -310,16 +310,57 @@ TEST_CASE("log version information (long with string)", "[mipi]") {
310310
CHECK(num_log_args_calls == 1);
311311
}
312312

313+
namespace {
314+
std::vector<std::uint32_t> expected_args{};
315+
316+
template <logging::level Level> struct test_log_injected_destination {
317+
template <typename... Args>
318+
auto log_by_args(std::uint32_t header, Args... args) {
319+
++num_log_args_calls;
320+
auto const Header = expected_msg_header(Level, test_module_id,
321+
std::size(expected_args));
322+
REQUIRE(header == Header);
323+
REQUIRE(sizeof...(Args) == std::size(expected_args));
324+
[&]<std::size_t... Is>(std::index_sequence<Is...>) {
325+
(check(args, expected_args[Is]), ...);
326+
}(std::make_index_sequence<sizeof...(Args)>{});
327+
}
328+
};
329+
} // namespace
330+
313331
template <>
314-
inline auto logging::config<> =
315-
logging::binary::config{test_log_args_destination<logging::level::TRACE>{}};
332+
inline auto logging::config<> = logging::binary::config{
333+
test_log_injected_destination<logging::level::TRACE>{}};
316334

317335
TEST_CASE("injection", "[mipi]") {
318336
test_critical_section::count = 0;
337+
expected_args.clear();
319338
CIB_TRACE("Hello");
320339
CHECK(test_critical_section::count == 2);
321340
}
322341

342+
TEST_CASE("injection - log runtime arg", "[mipi]") {
343+
test_critical_section::count = 0;
344+
expected_args = std::vector<std::uint32_t>{42, 17};
345+
auto x = 17;
346+
CIB_TRACE("Hello {}", x);
347+
CHECK(test_critical_section::count == 2);
348+
}
349+
350+
TEST_CASE("injection - log implicit compile-time arg", "[mipi]") {
351+
test_critical_section::count = 0;
352+
expected_args.clear();
353+
CIB_TRACE("Hello {}", 42);
354+
CHECK(test_critical_section::count == 2);
355+
}
356+
357+
TEST_CASE("injection - log explicit compile-time arg", "[mipi]") {
358+
test_critical_section::count = 0;
359+
expected_args.clear();
360+
CIB_TRACE("Hello {}", stdx::ct<42>());
361+
CHECK(test_critical_section::count == 2);
362+
}
363+
323364
namespace {
324365
int num_catalog_args_calls{};
325366

‎test/log/log.cpp‎

Lines changed: 31 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -87,7 +87,7 @@ TEST_CASE("CIB_FATAL pre-formats arguments passed to panic", "[log]") {
8787
CHECK(panicked);
8888
}
8989

90-
TEST_CASE("CIB_FATAL can format stack arguments", "[log]") {
90+
TEST_CASE("CIB_FATAL can format stack arguments (1)", "[log]") {
9191
reset_test_state();
9292
expected_why = "Hello {}";
9393
expected_args = std::make_tuple(stdx::make_tuple(42));
@@ -99,10 +99,38 @@ TEST_CASE("CIB_FATAL can format stack arguments", "[log]") {
9999
CHECK(panicked);
100100
}
101101

102+
TEST_CASE("CIB_FATAL can format stack arguments (2)", "[log]") {
103+
reset_test_state();
104+
expected_why = "Hello {}";
105+
expected_args =
106+
std::make_tuple(stdx::make_tuple(std::string_view{"world"}));
107+
108+
auto x = std::string_view{"world"};
109+
CIB_FATAL("Hello {}", x);
110+
CAPTURE(buffer);
111+
CHECK(buffer.find("Hello world") != std::string::npos);
112+
CHECK(panicked);
113+
}
114+
115+
TEST_CASE("CIB_FATAL formats compile-time arguments where possible", "[log]") {
116+
using namespace stdx::literals;
117+
reset_test_state();
118+
expected_why = "Hello 42";
119+
expected_args = std::make_tuple(stdx::make_tuple());
120+
121+
[]<stdx::ct_string S>() {
122+
CIB_FATAL("{} {}", S, 42);
123+
}.template operator()<"Hello">();
124+
125+
CAPTURE(buffer);
126+
CHECK(buffer.find("Hello 42") != std::string::npos);
127+
CHECK(panicked);
128+
}
129+
102130
TEST_CASE("CIB_FATAL passes extra arguments to panic", "[log]") {
103131
reset_test_state();
104132
expected_why = "Hello {}";
105-
expected_args = std::make_tuple(stdx::make_tuple(42), 17);
133+
expected_args = std::make_tuple(stdx::make_tuple(42), stdx::ct<17>());
106134

107135
auto x = 42;
108136
CIB_FATAL("Hello {}", x, 17);
@@ -124,7 +152,7 @@ TEST_CASE("CIB_ASSERT is equivalent to CIB_FATAL on failure", "[log]") {
124152
TEST_CASE("CIB_ASSERT passes arguments to panic", "[log]") {
125153
reset_test_state();
126154
expected_why = "Assertion failure: true == false";
127-
expected_args = std::make_tuple(stdx::make_tuple(), 42);
155+
expected_args = std::make_tuple(stdx::make_tuple(), stdx::ct<42>());
128156

129157
CIB_ASSERT(true == false, 42);
130158
CAPTURE(buffer);

0 commit comments

Comments
 (0)