Skip to content

Commit b9c6e61

Browse files
elbenomjcaisse-intel
elbeno
authored and
mjcaisse-intel
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 b9c6e61

File tree

7 files changed

+163
-19
lines changed

7 files changed

+163
-19
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: 36 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,50 @@ 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> constexpr auto is_already_ct = false;
62+
template <typename T, T V>
63+
constexpr auto is_already_ct<std::integral_constant<T, V>> = true;
64+
template <stdx::ct_string S>
65+
constexpr auto is_already_ct<stdx::cts_t<S>> = true;
66+
template <typename T>
67+
constexpr auto is_already_ct<stdx::type_identity<T>> = true;
68+
69+
template <stdx::ct_string Msg> constexpr auto cx_log_wrap(int, auto &&...args) {
70+
return stdx::ct_format<Msg>(FWD(args)...);
71+
}
72+
} // namespace detail
5873
} // namespace logging
5974

6075
// NOLINTBEGIN(cppcoreguidelines-macro-usage)
6176

77+
#define CIB_CX_WRAP1(X) \
78+
[&](auto f) { \
79+
if constexpr (::logging::detail::is_already_ct<decltype(f())>) { \
80+
return f(); \
81+
} else if constexpr (requires { \
82+
stdx::ct<[&]() constexpr { return X; }()>; \
83+
}) { \
84+
return stdx::ct<f()>(); \
85+
} else { \
86+
return f(); \
87+
} \
88+
}([&] { return X; })
89+
90+
#define CIB_CX_WRAP(...) __VA_OPT__(, CIB_CX_WRAP1(__VA_ARGS__))
91+
6292
#define CIB_LOG(MSG, ...) \
6393
logging::log<cib_log_env_t>(__FILE__, __LINE__, \
64-
stdx::ct_format<MSG>(__VA_ARGS__))
94+
logging::detail::cx_log_wrap<MSG>( \
95+
0 CIB_MAP(CIB_CX_WRAP, __VA_ARGS__)))
6596

6697
#define CIB_LOG_WITH_LEVEL(LEVEL, MSG, ...) \
6798
logging::log< \
6899
stdx::extend_env_t<cib_log_env_t, logging::get_level, LEVEL>>( \
69-
__FILE__, __LINE__, stdx::ct_format<MSG>(__VA_ARGS__))
100+
__FILE__, __LINE__, \
101+
logging::detail::cx_log_wrap<MSG>( \
102+
0 CIB_MAP(CIB_CX_WRAP, __VA_ARGS__)))
70103

71104
#define CIB_TRACE(...) \
72105
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>
127160

128161
#define CIB_FATAL(MSG, ...) \
129162
logging::detail::panic<MSG, cib_log_env_t>( \
130-
__FILE__, __LINE__ __VA_OPT__(, ) __VA_ARGS__)
163+
__FILE__, __LINE__ CIB_MAP(CIB_CX_WRAP, __VA_ARGS__))
131164

132165
#define CIB_ASSERT(expr, ...) \
133166
((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)

‎include/msg/callback.hpp

Lines changed: 7 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -46,15 +46,14 @@ struct callback {
4646
auto log_mismatch(auto const &data) const -> void {
4747
CIB_LOG_ENV(logging::get_level, logging::level::INFO);
4848
{
49+
auto const desc = msg::call_with_message<Msg>(
50+
[&]<typename T>(T &&t) -> decltype(matcher.describe_match(
51+
std::forward<T>(t))) {
52+
return matcher.describe_match(std::forward<T>(t));
53+
},
54+
data);
4955
CIB_APPEND_LOG_ENV(typename Msg::env_t);
50-
CIB_LOG(
51-
" {} - F:({})", stdx::cts_t<Name>{},
52-
msg::call_with_message<Msg>(
53-
[&]<typename T>(T &&t) -> decltype(matcher.describe_match(
54-
std::forward<T>(t))) {
55-
return matcher.describe_match(std::forward<T>(t));
56-
},
57-
data));
56+
CIB_LOG(" {} - F:({})", stdx::cts_t<Name>{}, desc);
5857
}
5958
}
6059

‎test/log/encoder.cpp

Lines changed: 50 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -310,16 +310,64 @@ 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 (int)", "[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 implicit compile-time arg (string)", "[mipi]") {
358+
test_critical_section::count = 0;
359+
expected_args.clear();
360+
CIB_TRACE("Hello {}", stdx::ct_string{"world"});
361+
CHECK(test_critical_section::count == 2);
362+
}
363+
364+
TEST_CASE("injection - log explicit compile-time arg", "[mipi]") {
365+
test_critical_section::count = 0;
366+
expected_args.clear();
367+
CIB_TRACE("Hello {}", stdx::ct<42>());
368+
CHECK(test_critical_section::count == 2);
369+
}
370+
323371
namespace {
324372
int num_catalog_args_calls{};
325373

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

‎test/msg/message.cpp

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -378,8 +378,8 @@ TEST_CASE("less_than_or_equal_to matcher", "[message]") {
378378
}
379379

380380
TEST_CASE("describe a message", "[message]") {
381-
test_msg msg{"f1"_field = 0xba11, "f2"_field = 0x42, "f3"_field = 0xd00d};
382-
CIB_INFO("{}", msg.describe());
381+
test_msg m{"f1"_field = 0xba11, "f2"_field = 0x42, "f3"_field = 0xd00d};
382+
CIB_INFO("{}", m.describe());
383383
CAPTURE(log_buffer);
384384
CHECK(log_buffer.find("msg(f1: 0xba11, id: 0x80, f3: 0xd00d, f2: 0x42)") !=
385385
std::string::npos);

0 commit comments

Comments
 (0)