From 9563778062e6491fa043131f51d661bf72089b40 Mon Sep 17 00:00:00 2001 From: Kam Cheung Ting Date: Mon, 15 Jun 2026 10:51:13 +0000 Subject: [PATCH 1/7] feat(logging): add LOG_* logging macros (4/6) Fourth block: the application-facing macros, the only part most callers touch. - ICEBERG_LOG_{TRACE,DEBUG,INFO,WARN,ERROR,CRITICAL,FATAL} plus the generic ICEBERG_LOG(level, ...), ICEBERG_LOG_TO(logger, level, ...) for an explicit logger, and ICEBERG_LOG_RUNTIME_FMT for a runtime (non-literal) format string. - ICEBERG_LOG_ACTIVE_LEVEL is a compile-time severity floor: statements below it are removed entirely via `if constexpr` (no format call site, no source location emitted). ICEBERG_LOG_FATAL is never gated by the floor -- its abort is always compiled in; it emits, best-effort Flush()es the same logger it emitted to, then std::abort(). - Filtering is decided solely by Logger::ShouldLog(); formatting is wrapped in try/catch so logging never throws (a format failure routes to EmitFormatError). - Bare Java-style aliases (LOG_INFO, ...) are opt-in via ICEBERG_LOG_SHORT_MACROS to avoid polluting consumers / colliding with glog/abseil. Header-only addition to logger.h. macros_test covers injection, the guard-before-format short-circuit, never-throws, and FATAL aborts; macros_active_level_test verifies compile-time stripping in a kOff translation unit. Co-authored-by: Isaac --- meson.build | 6 +- src/iceberg/logging/logger.h | 180 ++++++++++++++++++- src/iceberg/test/CMakeLists.txt | 8 +- src/iceberg/test/macros_active_level_test.cc | 60 +++++++ src/iceberg/test/macros_test.cc | 150 ++++++++++++++++ src/iceberg/test/meson.build | 2 + 6 files changed, 402 insertions(+), 4 deletions(-) create mode 100644 src/iceberg/test/macros_active_level_test.cc create mode 100644 src/iceberg/test/macros_test.cc diff --git a/meson.build b/meson.build index 199ac1fe9..a76d3abf6 100644 --- a/meson.build +++ b/meson.build @@ -33,7 +33,11 @@ project( cpp = meson.get_compiler('cpp') # Hide two noisy MSVC warnings (C4251/C4275) about standard-library types used in # our public classes. They're harmless because the whole library ships as one DLL. -args = cpp.get_supported_arguments(['/bigobj', '/wd4251', '/wd4275']) +# /Zc:preprocessor: MSVC's conforming preprocessor, required for the __VA_OPT__ +# used by the logging macros. get_supported_arguments drops these on non-MSVC. +args = cpp.get_supported_arguments( + ['/bigobj', '/wd4251', '/wd4275', '/Zc:preprocessor'], +) add_project_arguments(args, language: 'cpp') subdir('src') diff --git a/src/iceberg/logging/logger.h b/src/iceberg/logging/logger.h index 66f81501a..be56da71d 100644 --- a/src/iceberg/logging/logger.h +++ b/src/iceberg/logging/logger.h @@ -28,6 +28,7 @@ #include #include +#include #include #include #include @@ -339,7 +340,7 @@ void FormatAndEmit(Logger& logger, LogLevel level, const std::source_location& l if (!logger.ShouldLog(level)) return; try { Emit(logger, level, loc, std::format(fmt, std::forward(args)...)); - } catch (...) { + } catch (const std::exception&) { EmitFormatError(logger, level, loc); } } @@ -371,3 +372,180 @@ void Log(Logger& logger, LogLevel level, } } // namespace iceberg + +// --------------------------------------------------------------------------- +// Logging macros. +// +// Every macro takes a std::format string followed by its arguments. The +// rendered line depends on the active backend (see cerr_logger.h for the +// std::cerr layout, or the spdlog pattern); the examples below show the call +// site and, for the default CerrLogger, the line it produces. +// +// ICEBERG_LOG_TRACE("entering scan for {}", table); +// 2026-06-16T10:59:41.186Z trace [12345] table_scan.cc:88] entering scan for db.t +// ICEBERG_LOG_DEBUG("cache miss key={}", key); +// 2026-06-16T10:59:41.186Z debug [12345] cache.cc:42] cache miss key=manifest-7 +// ICEBERG_LOG_INFO("loaded {} manifests in {} ms", n, ms); +// 2026-06-16T10:59:41.186Z info [12345] table_scan.cc:91] loaded 5 manifests in 12 ms +// ICEBERG_LOG_WARN("retry {} after {}", attempt, err); +// 2026-06-16T10:59:41.186Z warn [12345] io.cc:51] retry 2 after timeout +// ICEBERG_LOG_ERROR("commit failed: {}", status); +// 2026-06-16T10:59:41.186Z error [12345] txn.cc:77] commit failed: conflict +// ICEBERG_LOG_CRITICAL("metadata unreadable at {}", path); +// 2026-06-16T10:59:41.186Z critical [12345] meta.cc:30] metadata unreadable at +// s3://b/m.json +// ICEBERG_LOG_FATAL("unrecoverable: {}", reason); // emits, flushes, then +// std::abort() +// 2026-06-16T10:59:41.186Z fatal [12345] boot.cc:19] unrecoverable: bad config +// +// Less common forms: +// ICEBERG_LOG(level, "level chosen at runtime: {}", x); // runtime severity +// ICEBERG_LOG_TO(logger, level, "to an explicit logger {}", y); +// ICEBERG_LOG_RUNTIME_FMT(level, fmt_string, args...); // non-literal format +// +// With ICEBERG_LOG_SHORT_MACROS defined, bare aliases (LOG_INFO, ...) are also +// available. A format string is mandatory; zero extra args is fine +// (ICEBERG_LOG_INFO("done")). +// --------------------------------------------------------------------------- + +/// \brief Compile-time severity floor: statements below this level are removed +/// entirely from the build (their format call sites and source_location literals +/// are never emitted). Defaults to keeping everything. ICEBERG_LOG_FATAL is never +/// gated by this floor -- its abort is always compiled in. +#ifndef ICEBERG_LOG_ACTIVE_LEVEL +# define ICEBERG_LOG_ACTIVE_LEVEL ::iceberg::LogLevel::kTrace +#endif + +// Internal: fixed-severity emit with compile-time floor then the authoritative +// Logger::ShouldLog (the single source of truth for runtime filtering), with +// formatting only on the taken path, never throwing. +#define ICEBERG_INTERNAL_LOG(level_, FMT_, ...) \ + do { \ + if constexpr ((level_) >= ICEBERG_LOG_ACTIVE_LEVEL) { \ + const auto& _ib_logger = ::iceberg::internal::CurrentLogger(); \ + if (_ib_logger && _ib_logger->ShouldLog(level_)) { \ + try { \ + ::iceberg::internal::Emit(*_ib_logger, (level_), \ + ::std::source_location::current(), \ + ::std::format(FMT_ __VA_OPT__(, ) __VA_ARGS__)); \ + } catch (const std::exception&) { \ + ::iceberg::internal::EmitFormatError(*_ib_logger, (level_), \ + ::std::source_location::current()); \ + } \ + } \ + } \ + } while (0) + +#define ICEBERG_LOG_TRACE(...) \ + ICEBERG_INTERNAL_LOG(::iceberg::LogLevel::kTrace, __VA_ARGS__) +#define ICEBERG_LOG_DEBUG(...) \ + ICEBERG_INTERNAL_LOG(::iceberg::LogLevel::kDebug, __VA_ARGS__) +#define ICEBERG_LOG_INFO(...) \ + ICEBERG_INTERNAL_LOG(::iceberg::LogLevel::kInfo, __VA_ARGS__) +#define ICEBERG_LOG_WARN(...) \ + ICEBERG_INTERNAL_LOG(::iceberg::LogLevel::kWarn, __VA_ARGS__) +#define ICEBERG_LOG_ERROR(...) \ + ICEBERG_INTERNAL_LOG(::iceberg::LogLevel::kError, __VA_ARGS__) +#define ICEBERG_LOG_CRITICAL(...) \ + ICEBERG_INTERNAL_LOG(::iceberg::LogLevel::kCritical, __VA_ARGS__) + +// FATAL: emit if enabled (never compile-stripped), then ALWAYS flush + abort. +// Acquires the effective (scoped-or-default) logger ONCE -- honoring any active +// ScopedLogger binding -- and uses that same instance for emit and flush, so a +// concurrent SetDefaultLogger cannot flush a different logger than it emitted to. +#define ICEBERG_LOG_FATAL(FMT_, ...) \ + do { \ + auto _ib_logger = ::iceberg::GetCurrentLogger(); \ + if (_ib_logger && _ib_logger->ShouldLog(::iceberg::LogLevel::kFatal)) { \ + try { \ + ::iceberg::internal::Emit(*_ib_logger, ::iceberg::LogLevel::kFatal, \ + ::std::source_location::current(), \ + ::std::format(FMT_ __VA_OPT__(, ) __VA_ARGS__)); \ + } catch (const std::exception&) { \ + ::iceberg::internal::EmitFormatError(*_ib_logger, ::iceberg::LogLevel::kFatal, \ + ::std::source_location::current()); \ + } \ + } \ + if (_ib_logger) _ib_logger->Flush(); \ + ::std::abort(); \ + } while (0) + +// Generic, runtime-level form against the default logger. No compile-time floor +// (the level is not a constant). Acquires the logger once; aborts when level == kFatal +// (flushing that same logger first). +#define ICEBERG_LOG(level_, FMT_, ...) \ + do { \ + const ::iceberg::LogLevel _ib_lvl = (level_); \ + const auto& _ib_logger = ::iceberg::internal::CurrentLogger(); \ + if (_ib_logger && _ib_logger->ShouldLog(_ib_lvl)) { \ + try { \ + ::iceberg::internal::Emit(*_ib_logger, _ib_lvl, \ + ::std::source_location::current(), \ + ::std::format(FMT_ __VA_OPT__(, ) __VA_ARGS__)); \ + } catch (const std::exception&) { \ + ::iceberg::internal::EmitFormatError(*_ib_logger, _ib_lvl, \ + ::std::source_location::current()); \ + } \ + } \ + if (_ib_lvl == ::iceberg::LogLevel::kFatal) { \ + if (_ib_logger) _ib_logger->Flush(); \ + ::std::abort(); \ + } \ + } while (0) + +// Generic form targeting an EXPLICIT logger (must be an lvalue Logger&). Honors +// only that logger's ShouldLog. Aborts when level == kFatal. +#define ICEBERG_LOG_TO(logger_, level_, FMT_, ...) \ + do { \ + ::iceberg::Logger& _ib_logger = (logger_); \ + const ::iceberg::LogLevel _ib_lvl = (level_); \ + if (_ib_logger.ShouldLog(_ib_lvl)) { \ + try { \ + ::iceberg::internal::Emit(_ib_logger, _ib_lvl, \ + ::std::source_location::current(), \ + ::std::format(FMT_ __VA_OPT__(, ) __VA_ARGS__)); \ + } catch (const std::exception&) { \ + ::iceberg::internal::EmitFormatError(_ib_logger, _ib_lvl, \ + ::std::source_location::current()); \ + } \ + } \ + if (_ib_lvl == ::iceberg::LogLevel::kFatal) { \ + _ib_logger.Flush(); \ + ::std::abort(); \ + } \ + } while (0) + +// Runtime (non-literal) format string against the default logger. Acquires the +// logger once; aborts when level == kFatal (flushing that same logger first). +#define ICEBERG_LOG_RUNTIME_FMT(level_, FMT_, ...) \ + do { \ + const ::iceberg::LogLevel _ib_lvl = (level_); \ + const auto& _ib_logger = ::iceberg::internal::CurrentLogger(); \ + if (_ib_logger && _ib_logger->ShouldLog(_ib_lvl)) { \ + try { \ + ::iceberg::internal::Emit( \ + *_ib_logger, _ib_lvl, ::std::source_location::current(), \ + ::iceberg::internal::VFormat((FMT_)__VA_OPT__(, ) __VA_ARGS__)); \ + } catch (const std::exception&) { \ + ::iceberg::internal::EmitFormatError(*_ib_logger, _ib_lvl, \ + ::std::source_location::current()); \ + } \ + } \ + if (_ib_lvl == ::iceberg::LogLevel::kFatal) { \ + if (_ib_logger) _ib_logger->Flush(); \ + ::std::abort(); \ + } \ + } while (0) + +// Bare, Java-style aliases. Opt-IN only (define ICEBERG_LOG_SHORT_MACROS before +// including this header) to avoid colliding with glog/abseil/windows.h in +// consumer translation units. No bare LOG(level) is provided. +#ifdef ICEBERG_LOG_SHORT_MACROS +# define LOG_TRACE(...) ICEBERG_LOG_TRACE(__VA_ARGS__) +# define LOG_DEBUG(...) ICEBERG_LOG_DEBUG(__VA_ARGS__) +# define LOG_INFO(...) ICEBERG_LOG_INFO(__VA_ARGS__) +# define LOG_WARN(...) ICEBERG_LOG_WARN(__VA_ARGS__) +# define LOG_ERROR(...) ICEBERG_LOG_ERROR(__VA_ARGS__) +# define LOG_CRITICAL(...) ICEBERG_LOG_CRITICAL(__VA_ARGS__) +# define LOG_FATAL(...) ICEBERG_LOG_FATAL(__VA_ARGS__) +#endif // ICEBERG_LOG_SHORT_MACROS diff --git a/src/iceberg/test/CMakeLists.txt b/src/iceberg/test/CMakeLists.txt index 98129a6d2..30a581129 100644 --- a/src/iceberg/test/CMakeLists.txt +++ b/src/iceberg/test/CMakeLists.txt @@ -62,7 +62,9 @@ function(add_iceberg_test test_name) endif() if(MSVC_TOOLCHAIN) - target_compile_options(${test_name} PRIVATE /bigobj) + # /Zc:preprocessor: conforming preprocessor for the __VA_OPT__ in the logging + # macros (MSVC's traditional preprocessor rejects it). + target_compile_options(${test_name} PRIVATE /bigobj /Zc:preprocessor) endif() add_test(NAME ${test_name} COMMAND ${test_name}) @@ -103,7 +105,9 @@ add_iceberg_test(logging_test SOURCES cerr_logger_test.cc log_level_test.cc - logger_test.cc) + logger_test.cc + macros_active_level_test.cc + macros_test.cc) add_iceberg_test(expression_test SOURCES diff --git a/src/iceberg/test/macros_active_level_test.cc b/src/iceberg/test/macros_active_level_test.cc new file mode 100644 index 000000000..c0e138a29 --- /dev/null +++ b/src/iceberg/test/macros_active_level_test.cc @@ -0,0 +1,60 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +// Compile-time floor set to kOff for this translation unit: every fixed-severity +// macro below kFatal must be stripped to nothing, while ICEBERG_LOG_FATAL must +// still abort (its abort is never gated by the compile-time floor). +#define ICEBERG_LOG_ACTIVE_LEVEL ::iceberg::LogLevel::kOff + +#include + +#include + +#include "iceberg/logging/log_level.h" +#include "iceberg/logging/logger.h" +#include "iceberg/test/logging_test_helpers.h" + +namespace iceberg { + +TEST(MacrosActiveLevelTest, BelowFloorStatementsAreCompiledOut) { + auto logger = std::make_shared(); + logger->SetLevel(LogLevel::kTrace); + ScopedDefaultLogger guard(logger); + + int calls = 0; + // counted() is only "called" from the compile-time-stripped macros below, so the + // analyzer sees its init as a dead store -- which is exactly what this verifies. + // NOLINTNEXTLINE(clang-analyzer-deadcode.DeadStores) + auto counted = [&calls]() { + ++calls; + return 1; + }; + // Stripped at compile time -> arguments never evaluated, nothing emitted, + // even though the runtime logger would accept these levels. + ICEBERG_LOG_INFO("{}", counted()); + ICEBERG_LOG_CRITICAL("{}", counted()); + EXPECT_EQ(calls, 0); + EXPECT_EQ(logger->count(), 0u); +} + +TEST(MacrosActiveLevelDeathTest, FatalStillAbortsWhenEverythingElseStripped) { + EXPECT_DEATH({ ICEBERG_LOG_FATAL("still fatal"); }, ""); +} + +} // namespace iceberg diff --git a/src/iceberg/test/macros_test.cc b/src/iceberg/test/macros_test.cc new file mode 100644 index 000000000..28ac8f526 --- /dev/null +++ b/src/iceberg/test/macros_test.cc @@ -0,0 +1,150 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +#include + +#include + +#include "iceberg/logging/cerr_logger.h" +#include "iceberg/logging/log_level.h" +#include "iceberg/logging/logger.h" +#include "iceberg/test/logging_test_helpers.h" + +namespace iceberg { + +namespace { + +std::shared_ptr InstallCapturing(LogLevel level = LogLevel::kTrace) { + auto logger = std::make_shared(); + logger->SetLevel(level); + return logger; +} + +} // namespace + +TEST(MacrosTest, InfoFormatsAndCapturesLocation) { + auto logger = InstallCapturing(); + ScopedDefaultLogger guard(logger); + ICEBERG_LOG_INFO("x={}", 42); + auto records = logger->records(); + ASSERT_EQ(records.size(), 1u); + EXPECT_EQ(records[0].level, LogLevel::kInfo); + EXPECT_EQ(records[0].message, "x=42"); + EXPECT_NE(records[0].location.line(), 0u); +} + +TEST(MacrosTest, RuntimeLevelFiltersBelowThreshold) { + auto logger = InstallCapturing(); + ScopedDefaultLogger guard(logger); + SetDefaultLevel(LogLevel::kError); + ICEBERG_LOG_INFO("dropped"); + ICEBERG_LOG_ERROR("kept"); + auto records = logger->records(); + ASSERT_EQ(records.size(), 1u); + EXPECT_EQ(records[0].message, "kept"); +} + +TEST(MacrosTest, DisabledLevelDoesNotEvaluateArguments) { + auto logger = InstallCapturing(); + ScopedDefaultLogger guard(logger); + SetDefaultLevel(LogLevel::kError); + int calls = 0; + auto counted = [&calls]() { + ++calls; + return 1; + }; + ICEBERG_LOG_INFO("{}", counted()); + EXPECT_EQ(calls, 0); +} + +TEST(MacrosTest, DanglingElseBindsCorrectly) { + auto logger = InstallCapturing(); + ScopedDefaultLogger guard(logger); + bool took_else = false; + // Intentionally brace-free: this verifies the macro keeps dangling-else binding + // correct. Adding braces would defeat the test, so suppress the tidy check. + // NOLINTBEGIN(google-readability-braces-around-statements) + if (false) + ICEBERG_LOG_INFO("if-branch"); + else + took_else = true; + // NOLINTEND(google-readability-braces-around-statements) + EXPECT_TRUE(took_else); + EXPECT_EQ(logger->count(), 0u); +} + +TEST(MacrosTest, GenericRuntimeLevelMacroCompilesAndLogs) { + auto logger = InstallCapturing(); + ScopedDefaultLogger guard(logger); + LogLevel level = LogLevel::kWarn; + ICEBERG_LOG(level, "n={}", 7); + auto records = logger->records(); + ASSERT_EQ(records.size(), 1u); + EXPECT_EQ(records[0].message, "n=7"); + EXPECT_EQ(records[0].level, LogLevel::kWarn); +} + +TEST(MacrosTest, LogToHonorsOnlyExplicitLoggerNotDefaultGate) { + auto sink = InstallCapturing(); + ScopedDefaultLogger guard(InstallCapturing()); + SetDefaultLevel(LogLevel::kOff); // default gate would block everything + ICEBERG_LOG_TO(*sink, LogLevel::kInfo, "explicit {}", 1); + EXPECT_EQ(sink->count(), 1u); +} + +TEST(MacrosTest, NeverThrowsOnBadRuntimeFormat) { + auto logger = InstallCapturing(); + ScopedDefaultLogger guard(logger); + // Invalid runtime format string -> std::vformat throws -> swallowed -> fallback. + EXPECT_NO_THROW(ICEBERG_LOG_RUNTIME_FMT(LogLevel::kInfo, "{")); + auto records = logger->records(); + ASSERT_EQ(records.size(), 1u); + EXPECT_EQ(records[0].message, ""); +} + +TEST(MacrosDeathTest, FatalEmitsThenAborts) { + // Default logger writes to std::cerr; the message must appear before abort. + EXPECT_DEATH({ ICEBERG_LOG_FATAL("fatalmsg {}", 7); }, "fatalmsg 7"); +} + +TEST(MacrosDeathTest, FatalAbortsEvenWhenRuntimeDisabled) { + EXPECT_DEATH( + { + SetDefaultLevel(LogLevel::kOff); + ICEBERG_LOG_FATAL("suppressed"); + }, + ""); +} + +TEST(MacrosDeathTest, GenericRuntimeFatalEmitsThenAborts) { + // ICEBERG_LOG with a runtime kFatal level must also emit then abort. + EXPECT_DEATH({ ICEBERG_LOG(LogLevel::kFatal, "gfatal {}", 1); }, "gfatal 1"); +} + +TEST(MacrosDeathTest, LogToFatalEmitsThenAborts) { + // ICEBERG_LOG_TO with kFatal must emit to the explicit logger then abort. + EXPECT_DEATH( + { + CerrLogger sink(LogLevel::kTrace); + ICEBERG_LOG_TO(sink, LogLevel::kFatal, "tofatal {}", 2); + }, + "tofatal 2"); +} + +} // namespace iceberg diff --git a/src/iceberg/test/meson.build b/src/iceberg/test/meson.build index 0e5399347..b8217d3cd 100644 --- a/src/iceberg/test/meson.build +++ b/src/iceberg/test/meson.build @@ -67,6 +67,8 @@ iceberg_tests = { 'cerr_logger_test.cc', 'log_level_test.cc', 'logger_test.cc', + 'macros_active_level_test.cc', + 'macros_test.cc', ), }, 'expression_test': { From e30d45f6b24826f46e6076d83e18bcd68cda3662 Mon Sep 17 00:00:00 2001 From: Kam Cheung Ting Date: Tue, 30 Jun 2026 20:35:58 +0000 Subject: [PATCH 2/7] docs(logging): explain the catch(const std::exception&) choice Note in FormatAndEmit and the ICEBERG_INTERNAL_LOG comment that the only throws are std::format_error/std::bad_alloc (same recovery), and that catching std::exception rather than (...) lets a non-std unwind such as abi::__forced_unwind (thread cancellation) propagate. Co-authored-by: Isaac --- src/iceberg/logging/logger.h | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/src/iceberg/logging/logger.h b/src/iceberg/logging/logger.h index be56da71d..6a0812288 100644 --- a/src/iceberg/logging/logger.h +++ b/src/iceberg/logging/logger.h @@ -341,6 +341,9 @@ void FormatAndEmit(Logger& logger, LogLevel level, const std::source_location& l try { Emit(logger, level, loc, std::format(fmt, std::forward(args)...)); } catch (const std::exception&) { + // The only throws here are std::format_error / std::bad_alloc -- same recovery + // for both (drop, emit a fixed marker). Catch std::exception, not (...), so a + // non-std unwind like abi::__forced_unwind (thread cancellation) propagates. EmitFormatError(logger, level, loc); } } @@ -418,7 +421,9 @@ void Log(Logger& logger, LogLevel level, // Internal: fixed-severity emit with compile-time floor then the authoritative // Logger::ShouldLog (the single source of truth for runtime filtering), with -// formatting only on the taken path, never throwing. +// formatting only on the taken path, never throwing. The catch handles +// std::exception (std::format_error / std::bad_alloc) -- not (...) -- so a non-std +// unwind such as abi::__forced_unwind (thread cancellation) still propagates. #define ICEBERG_INTERNAL_LOG(level_, FMT_, ...) \ do { \ if constexpr ((level_) >= ICEBERG_LOG_ACTIVE_LEVEL) { \ From e549ec21d1c136116c175e3ab157d4551bc7750f Mon Sep 17 00:00:00 2001 From: Kam Cheung Ting Date: Thu, 16 Jul 2026 06:12:12 +0000 Subject: [PATCH 3/7] fix(logging): address #725 review (catch-all, /Zc:preprocessor, docs, FATAL test) - Revert the 6 catch sites to catch(...) so the noexcept "logging never throws" guarantee holds even when a user-defined std::formatter throws a non-std type (catch(const std::exception&) would let it reach std::terminate). - Apply /Zc:preprocessor to the iceberg library targets PUBLICly on MSVC, not only to tests: logger.h is public and uses __VA_OPT__, so the library build and consumers need the conforming preprocessor too. - Soften the compile-time-floor doc: `if constexpr` discards the emit but the statement must still be well-formed (bad format string is still a compile error). - Add the missing opening '[' to the logger.h example output lines to match CerrLogger's [file:line] layout. - Add MacrosDeathTest.FatalRoutesThroughScopedLogger locking in that ICEBERG_LOG_FATAL routes through the active ScopedLogger (GetCurrentLogger). Co-authored-by: Isaac --- src/iceberg/CMakeLists.txt | 12 ++++++++ src/iceberg/logging/logger.h | 51 +++++++++++++++++---------------- src/iceberg/test/macros_test.cc | 14 +++++++++ 3 files changed, 53 insertions(+), 24 deletions(-) diff --git a/src/iceberg/CMakeLists.txt b/src/iceberg/CMakeLists.txt index 1cd1d4467..c011a7a0c 100644 --- a/src/iceberg/CMakeLists.txt +++ b/src/iceberg/CMakeLists.txt @@ -193,6 +193,18 @@ add_iceberg_lib(iceberg OUTPUTS ICEBERG_LIBRARIES) +# The logging macros in the public logger.h use __VA_OPT__, which MSVC's +# traditional preprocessor rejects. Require the conforming preprocessor PUBLICly +# so both these library targets (logger.cc includes logger.h) and downstream +# consumers of the installed header get it on MSVC. +if(MSVC_TOOLCHAIN) + foreach(_iceberg_lib iceberg_shared iceberg_static) + if(TARGET ${_iceberg_lib}) + target_compile_options(${_iceberg_lib} PUBLIC /Zc:preprocessor) + endif() + endforeach() +endif() + set(ICEBERG_DATA_SOURCES data/data_writer.cc data/delete_filter.cc diff --git a/src/iceberg/logging/logger.h b/src/iceberg/logging/logger.h index 6a0812288..b4411494c 100644 --- a/src/iceberg/logging/logger.h +++ b/src/iceberg/logging/logger.h @@ -28,7 +28,6 @@ #include #include -#include #include #include #include @@ -340,10 +339,10 @@ void FormatAndEmit(Logger& logger, LogLevel level, const std::source_location& l if (!logger.ShouldLog(level)) return; try { Emit(logger, level, loc, std::format(fmt, std::forward(args)...)); - } catch (const std::exception&) { - // The only throws here are std::format_error / std::bad_alloc -- same recovery - // for both (drop, emit a fixed marker). Catch std::exception, not (...), so a - // non-std unwind like abi::__forced_unwind (thread cancellation) propagates. + } catch (...) { + // Catch-all upholds the noexcept "logging never throws" guarantee: a + // user-defined std::formatter may throw a non-std::exception type, and this + // function is noexcept, so anything escaping here would call std::terminate. EmitFormatError(logger, level, loc); } } @@ -385,21 +384,22 @@ void Log(Logger& logger, LogLevel level, // site and, for the default CerrLogger, the line it produces. // // ICEBERG_LOG_TRACE("entering scan for {}", table); -// 2026-06-16T10:59:41.186Z trace [12345] table_scan.cc:88] entering scan for db.t +// 2026-06-16T10:59:41.186Z trace [12345] [table_scan.cc:88] entering scan for db.t // ICEBERG_LOG_DEBUG("cache miss key={}", key); -// 2026-06-16T10:59:41.186Z debug [12345] cache.cc:42] cache miss key=manifest-7 +// 2026-06-16T10:59:41.186Z debug [12345] [cache.cc:42] cache miss key=manifest-7 // ICEBERG_LOG_INFO("loaded {} manifests in {} ms", n, ms); -// 2026-06-16T10:59:41.186Z info [12345] table_scan.cc:91] loaded 5 manifests in 12 ms +// 2026-06-16T10:59:41.186Z info [12345] [table_scan.cc:91] loaded 5 manifests in 12 +// ms // ICEBERG_LOG_WARN("retry {} after {}", attempt, err); -// 2026-06-16T10:59:41.186Z warn [12345] io.cc:51] retry 2 after timeout +// 2026-06-16T10:59:41.186Z warn [12345] [io.cc:51] retry 2 after timeout // ICEBERG_LOG_ERROR("commit failed: {}", status); -// 2026-06-16T10:59:41.186Z error [12345] txn.cc:77] commit failed: conflict +// 2026-06-16T10:59:41.186Z error [12345] [txn.cc:77] commit failed: conflict // ICEBERG_LOG_CRITICAL("metadata unreadable at {}", path); -// 2026-06-16T10:59:41.186Z critical [12345] meta.cc:30] metadata unreadable at +// 2026-06-16T10:59:41.186Z critical [12345] [meta.cc:30] metadata unreadable at // s3://b/m.json // ICEBERG_LOG_FATAL("unrecoverable: {}", reason); // emits, flushes, then // std::abort() -// 2026-06-16T10:59:41.186Z fatal [12345] boot.cc:19] unrecoverable: bad config +// 2026-06-16T10:59:41.186Z fatal [12345] [boot.cc:19] unrecoverable: bad config // // Less common forms: // ICEBERG_LOG(level, "level chosen at runtime: {}", x); // runtime severity @@ -411,19 +411,22 @@ void Log(Logger& logger, LogLevel level, // (ICEBERG_LOG_INFO("done")). // --------------------------------------------------------------------------- -/// \brief Compile-time severity floor: statements below this level are removed -/// entirely from the build (their format call sites and source_location literals -/// are never emitted). Defaults to keeping everything. ICEBERG_LOG_FATAL is never -/// gated by this floor -- its abort is always compiled in. +/// \brief Compile-time severity floor: statements below this level are discarded +/// via `if constexpr`, so no emit code runs and no format call / source_location +/// is generated for them (the compiler is free to optimize the dead branch away). +/// The statement must still be well-formed -- a bad format string or a +/// non-formattable argument is a compile error even when the branch is discarded. +/// Defaults to keeping everything. ICEBERG_LOG_FATAL is never gated by this floor +/// -- its abort is always compiled in. #ifndef ICEBERG_LOG_ACTIVE_LEVEL # define ICEBERG_LOG_ACTIVE_LEVEL ::iceberg::LogLevel::kTrace #endif // Internal: fixed-severity emit with compile-time floor then the authoritative // Logger::ShouldLog (the single source of truth for runtime filtering), with -// formatting only on the taken path, never throwing. The catch handles -// std::exception (std::format_error / std::bad_alloc) -- not (...) -- so a non-std -// unwind such as abi::__forced_unwind (thread cancellation) still propagates. +// formatting only on the taken path, never throwing. The catch-all upholds the +// "logging never throws" guarantee even when a user-defined std::formatter throws +// a non-std::exception type (a std::format_error/bad_alloc route to EmitFormatError). #define ICEBERG_INTERNAL_LOG(level_, FMT_, ...) \ do { \ if constexpr ((level_) >= ICEBERG_LOG_ACTIVE_LEVEL) { \ @@ -433,7 +436,7 @@ void Log(Logger& logger, LogLevel level, ::iceberg::internal::Emit(*_ib_logger, (level_), \ ::std::source_location::current(), \ ::std::format(FMT_ __VA_OPT__(, ) __VA_ARGS__)); \ - } catch (const std::exception&) { \ + } catch (...) { \ ::iceberg::internal::EmitFormatError(*_ib_logger, (level_), \ ::std::source_location::current()); \ } \ @@ -466,7 +469,7 @@ void Log(Logger& logger, LogLevel level, ::iceberg::internal::Emit(*_ib_logger, ::iceberg::LogLevel::kFatal, \ ::std::source_location::current(), \ ::std::format(FMT_ __VA_OPT__(, ) __VA_ARGS__)); \ - } catch (const std::exception&) { \ + } catch (...) { \ ::iceberg::internal::EmitFormatError(*_ib_logger, ::iceberg::LogLevel::kFatal, \ ::std::source_location::current()); \ } \ @@ -487,7 +490,7 @@ void Log(Logger& logger, LogLevel level, ::iceberg::internal::Emit(*_ib_logger, _ib_lvl, \ ::std::source_location::current(), \ ::std::format(FMT_ __VA_OPT__(, ) __VA_ARGS__)); \ - } catch (const std::exception&) { \ + } catch (...) { \ ::iceberg::internal::EmitFormatError(*_ib_logger, _ib_lvl, \ ::std::source_location::current()); \ } \ @@ -509,7 +512,7 @@ void Log(Logger& logger, LogLevel level, ::iceberg::internal::Emit(_ib_logger, _ib_lvl, \ ::std::source_location::current(), \ ::std::format(FMT_ __VA_OPT__(, ) __VA_ARGS__)); \ - } catch (const std::exception&) { \ + } catch (...) { \ ::iceberg::internal::EmitFormatError(_ib_logger, _ib_lvl, \ ::std::source_location::current()); \ } \ @@ -531,7 +534,7 @@ void Log(Logger& logger, LogLevel level, ::iceberg::internal::Emit( \ *_ib_logger, _ib_lvl, ::std::source_location::current(), \ ::iceberg::internal::VFormat((FMT_)__VA_OPT__(, ) __VA_ARGS__)); \ - } catch (const std::exception&) { \ + } catch (...) { \ ::iceberg::internal::EmitFormatError(*_ib_logger, _ib_lvl, \ ::std::source_location::current()); \ } \ diff --git a/src/iceberg/test/macros_test.cc b/src/iceberg/test/macros_test.cc index 28ac8f526..fb26f12fd 100644 --- a/src/iceberg/test/macros_test.cc +++ b/src/iceberg/test/macros_test.cc @@ -147,4 +147,18 @@ TEST(MacrosDeathTest, LogToFatalEmitsThenAborts) { "tofatal 2"); } +// Regression guard: ICEBERG_LOG_FATAL must route through the active ScopedLogger +// binding (GetCurrentLogger), not the process default (GetDefaultLogger). A scoped +// CerrLogger emits the record before the abort; the message must reach that sink. +TEST(MacrosDeathTest, FatalRoutesThroughScopedLogger) { + EXPECT_DEATH( + { + SetDefaultLevel(LogLevel::kOff); // default gate off -> only the scope emits + auto scoped = std::make_shared(LogLevel::kTrace); + ScopedLogger bind(scoped); + ICEBERG_LOG_FATAL("scopedfatal {}", 9); + }, + "scopedfatal 9"); +} + } // namespace iceberg From 8f7c826ac1fde7bf1c950e4ef9fd7cf1dadf74ba Mon Sep 17 00:00:00 2001 From: Kam Cheung Ting Date: Thu, 16 Jul 2026 06:53:50 +0000 Subject: [PATCH 4/7] refactor(logging): split macros into log_macros.h + short_log_macros.h Adopt the structure from the #824 prototype (keeping our if constexpr gating): - logger.h is now the C++ API only; ICEBERG_LOG_* macros move to log_macros.h, and the bare LOG_* aliases move behind an opt-in short_log_macros.h (replacing the ICEBERG_LOG_SHORT_MACROS define). - Dedup the five macro bodies onto shared internal helpers (EmitIfEnabled + LogToCurrent / LogToCurrentRuntime / LogToExplicitRuntime / LogFatal) that take a lazy [&]()->std::string message thunk invoked only past ShouldLog, so disabled logs still don't evaluate their args. Keeps catch(...), the GetCurrentLogger() fatal path, and if constexpr compile-time floor. - VFormat moves to log_macros.h (only ICEBERG_LOG_RUNTIME_FMT uses it). Co-authored-by: Isaac --- src/iceberg/logging/log_macros.h | 229 +++++++++++++++++++ src/iceberg/logging/logger.h | 217 +----------------- src/iceberg/logging/meson.build | 8 +- src/iceberg/logging/short_log_macros.h | 38 +++ src/iceberg/test/macros_active_level_test.cc | 1 + src/iceberg/test/macros_test.cc | 1 + 6 files changed, 287 insertions(+), 207 deletions(-) create mode 100644 src/iceberg/logging/log_macros.h create mode 100644 src/iceberg/logging/short_log_macros.h diff --git a/src/iceberg/logging/log_macros.h b/src/iceberg/logging/log_macros.h new file mode 100644 index 000000000..3d8d014ac --- /dev/null +++ b/src/iceberg/logging/log_macros.h @@ -0,0 +1,229 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +#pragma once + +/// \file iceberg/logging/log_macros.h +/// \brief Iceberg-prefixed logging macros (ICEBERG_LOG_*). +/// +/// Kept out of logger.h so consumers of the C++ logging API (Logger, Log(), +/// ScopedLogger) are not forced to pull in these macros or the conforming +/// preprocessor they require. Include this header to use the macros; include +/// short_log_macros.h for the bare LOG_* aliases. + +#include +#include +#include +#include +#include +#include +#include + +#include "iceberg/logging/log_level.h" +#include "iceberg/logging/logger.h" + +namespace iceberg::internal { + +/// \brief Runtime (non-literal) format-string helper for ICEBERG_LOG_RUNTIME_FMT. +/// +/// std::format requires a compile-time format string; this routes a runtime +/// string through std::vformat. Args are bound as named lvalues and the +/// arg-store is held in a named variable so it outlives the vformat call +/// (C++23 make_format_args rejects rvalues -- P2905 / LWG3631). +template +std::string VFormat(std::string_view fmt, Args&&... args) { + auto store = std::make_format_args(args...); + return std::vformat(fmt, store); +} + +/// \brief Gate on \p logger.ShouldLog, then format (via \p make_message) and emit. +/// +/// \p make_message is a callable returning the formatted std::string; it is +/// invoked only after the level passes ShouldLog, so a disabled log never +/// evaluates its format arguments. Never throws: a std::formatter that throws +/// (any type) routes to EmitFormatError, so the noexcept logging contract holds. +template +void EmitIfEnabled(Logger& logger, LogLevel level, const std::source_location& location, + MakeMessage&& make_message) noexcept { + if (!logger.ShouldLog(level)) return; + try { + Emit(logger, level, location, std::forward(make_message)()); + } catch (...) { + EmitFormatError(logger, level, location); + } +} + +/// \brief Emit to the current (scoped-or-default) logger if enabled. +template +void LogToCurrent(LogLevel level, const std::source_location& location, + MakeMessage&& make_message) noexcept { + const std::shared_ptr& logger = CurrentLogger(); + if (logger) { + EmitIfEnabled(*logger, level, location, std::forward(make_message)); + } +} + +/// \brief Runtime-level variant against the current logger: emit if enabled, then +/// flush + abort when level == kFatal (using the same acquired logger). +template +void LogToCurrentRuntime(LogLevel level, const std::source_location& location, + MakeMessage&& make_message) noexcept { + const std::shared_ptr& logger = CurrentLogger(); + if (logger) { + EmitIfEnabled(*logger, level, location, std::forward(make_message)); + } + if (level == LogLevel::kFatal) { + if (logger) logger->Flush(); + std::abort(); + } +} + +/// \brief Runtime-level variant against an explicit logger: emit if enabled, then +/// flush + abort when level == kFatal. +template +void LogToExplicitRuntime(Logger& logger, LogLevel level, + const std::source_location& location, + MakeMessage&& make_message) noexcept { + EmitIfEnabled(logger, level, location, std::forward(make_message)); + if (level == LogLevel::kFatal) { + logger.Flush(); + std::abort(); + } +} + +/// \brief Fatal path: acquire the effective (scoped-or-default) logger ONCE, emit +/// if enabled, flush that same logger, then abort. Never returns. +template +[[noreturn]] void LogFatal(const std::source_location& location, + MakeMessage&& make_message) noexcept { + auto logger = GetCurrentLogger(); + if (logger) { + EmitIfEnabled(*logger, LogLevel::kFatal, location, + std::forward(make_message)); + logger->Flush(); + } + std::abort(); +} + +} // namespace iceberg::internal + +// --------------------------------------------------------------------------- +// Logging macros. +// +// Every macro takes a std::format string followed by its arguments. The +// rendered line depends on the active backend (see cerr_logger.h for the +// std::cerr layout, or the spdlog pattern); the examples below show the call +// site and, for the default CerrLogger, the line it produces. +// +// ICEBERG_LOG_TRACE("entering scan for {}", table); +// 2026-06-16T10:59:41.186Z trace [12345] [table_scan.cc:88] entering scan for db.t +// ICEBERG_LOG_DEBUG("cache miss key={}", key); +// 2026-06-16T10:59:41.186Z debug [12345] [cache.cc:42] cache miss key=manifest-7 +// ICEBERG_LOG_INFO("loaded {} manifests in {} ms", n, ms); +// 2026-06-16T10:59:41.186Z info [12345] [table_scan.cc:91] loaded 5 manifests in 12 +// ms +// ICEBERG_LOG_WARN("retry {} after {}", attempt, err); +// 2026-06-16T10:59:41.186Z warn [12345] [io.cc:51] retry 2 after timeout +// ICEBERG_LOG_ERROR("commit failed: {}", status); +// 2026-06-16T10:59:41.186Z error [12345] [txn.cc:77] commit failed: conflict +// ICEBERG_LOG_CRITICAL("metadata unreadable at {}", path); +// 2026-06-16T10:59:41.186Z critical [12345] [meta.cc:30] metadata unreadable at +// s3://b/m.json +// ICEBERG_LOG_FATAL("unrecoverable: {}", reason); // emits, flushes, then +// std::abort() +// 2026-06-16T10:59:41.186Z fatal [12345] [boot.cc:19] unrecoverable: bad config +// +// Less common forms: +// ICEBERG_LOG(level, "level chosen at runtime: {}", x); // runtime severity +// ICEBERG_LOG_TO(logger, level, "to an explicit logger {}", y); +// ICEBERG_LOG_RUNTIME_FMT(level, fmt_string, args...); // non-literal format +// +// Include short_log_macros.h for bare aliases (LOG_INFO, ...). A format string is +// mandatory; zero extra args is fine (ICEBERG_LOG_INFO("done")). +// --------------------------------------------------------------------------- + +/// \brief Compile-time severity floor: statements below this level are discarded +/// via `if constexpr`, so no emit code runs and no format call / source_location +/// is generated for them (the compiler is free to optimize the dead branch away). +/// The statement must still be well-formed -- a bad format string or a +/// non-formattable argument is a compile error even when the branch is discarded. +/// Defaults to keeping everything. ICEBERG_LOG_FATAL is never gated by this floor +/// -- its abort is always compiled in. +#ifndef ICEBERG_LOG_ACTIVE_LEVEL +# define ICEBERG_LOG_ACTIVE_LEVEL ::iceberg::LogLevel::kTrace +#endif + +// A message-builder lambda that formats lazily (only invoked past ShouldLog by the +// EmitIfEnabled helpers), so disabled logs never evaluate their arguments. +#define ICEBERG_INTERNAL_LOG_MESSAGE(FMT_, ...) \ + [&]() -> ::std::string { return ::std::format((FMT_)__VA_OPT__(, ) __VA_ARGS__); } + +// Fixed-severity emit with a compile-time floor (`if constexpr`) then the shared +// current-logger path. Formatting happens only on the taken path and never throws. +#define ICEBERG_INTERNAL_LOG(level_, FMT_, ...) \ + do { \ + if constexpr ((level_) >= ICEBERG_LOG_ACTIVE_LEVEL) { \ + ::iceberg::internal::LogToCurrent( \ + (level_), ::std::source_location::current(), \ + ICEBERG_INTERNAL_LOG_MESSAGE(FMT_ __VA_OPT__(, ) __VA_ARGS__)); \ + } \ + } while (0) + +#define ICEBERG_LOG_TRACE(...) \ + ICEBERG_INTERNAL_LOG(::iceberg::LogLevel::kTrace, __VA_ARGS__) +#define ICEBERG_LOG_DEBUG(...) \ + ICEBERG_INTERNAL_LOG(::iceberg::LogLevel::kDebug, __VA_ARGS__) +#define ICEBERG_LOG_INFO(...) \ + ICEBERG_INTERNAL_LOG(::iceberg::LogLevel::kInfo, __VA_ARGS__) +#define ICEBERG_LOG_WARN(...) \ + ICEBERG_INTERNAL_LOG(::iceberg::LogLevel::kWarn, __VA_ARGS__) +#define ICEBERG_LOG_ERROR(...) \ + ICEBERG_INTERNAL_LOG(::iceberg::LogLevel::kError, __VA_ARGS__) +#define ICEBERG_LOG_CRITICAL(...) \ + ICEBERG_INTERNAL_LOG(::iceberg::LogLevel::kCritical, __VA_ARGS__) + +// FATAL: emit if enabled (never compile-stripped), then ALWAYS flush + abort. +// Acquires the effective (scoped-or-default) logger ONCE so a concurrent +// SetDefaultLogger cannot flush a different logger than it emitted to. +#define ICEBERG_LOG_FATAL(FMT_, ...) \ + ::iceberg::internal::LogFatal( \ + ::std::source_location::current(), \ + ICEBERG_INTERNAL_LOG_MESSAGE(FMT_ __VA_OPT__(, ) __VA_ARGS__)) + +// Generic, runtime-level form against the default logger. No compile-time floor +// (the level is not a constant). Aborts when level == kFatal. +#define ICEBERG_LOG(level_, FMT_, ...) \ + ::iceberg::internal::LogToCurrentRuntime( \ + (level_), ::std::source_location::current(), \ + ICEBERG_INTERNAL_LOG_MESSAGE(FMT_ __VA_OPT__(, ) __VA_ARGS__)) + +// Generic form targeting an EXPLICIT logger (must be an lvalue Logger&). Honors +// only that logger's ShouldLog. Aborts when level == kFatal. +#define ICEBERG_LOG_TO(logger_, level_, FMT_, ...) \ + ::iceberg::internal::LogToExplicitRuntime( \ + (logger_), (level_), ::std::source_location::current(), \ + ICEBERG_INTERNAL_LOG_MESSAGE(FMT_ __VA_OPT__(, ) __VA_ARGS__)) + +// Runtime (non-literal) format string against the default logger. Aborts when +// level == kFatal. +#define ICEBERG_LOG_RUNTIME_FMT(level_, FMT_, ...) \ + ::iceberg::internal::LogToCurrentRuntime( \ + (level_), ::std::source_location::current(), [&]() -> ::std::string { \ + return ::iceberg::internal::VFormat((FMT_)__VA_OPT__(, ) __VA_ARGS__); \ + }) diff --git a/src/iceberg/logging/logger.h b/src/iceberg/logging/logger.h index b4411494c..3034103ea 100644 --- a/src/iceberg/logging/logger.h +++ b/src/iceberg/logging/logger.h @@ -56,7 +56,7 @@ struct ICEBERG_EXPORT LogAttribute { /// \brief A single log record handed to a Logger. /// -/// The formatted message is owned (moved in by the logging macros), so a sink +/// The formatted message is owned (moved in when emitted), so a sink /// may safely retain the record beyond the Log() call. The member set must not /// depend on the build's logging backend (the spdlog backend never appears here). /// Use LogMessage::Builder for a readable way to assemble one, especially with @@ -134,11 +134,11 @@ inline constexpr std::string_view kPatternProperty = "pattern"; /// \brief Pluggable logging sink. /// -/// ShouldLog() is the single authority for runtime filtering -- the macros call -/// it on every (compile-time-enabled) statement, so level changes by any path -/// take effect immediately. Implementations must be thread-safe and must not +/// ShouldLog() is the single authority for runtime filtering -- the logging path +/// calls it on every (compile-time-enabled) statement, so level changes by any +/// path take effect immediately. Implementations must be thread-safe and must not /// throw. They must also obey: -/// - No reentrancy: Log()/Flush() must not call the logging macros or +/// - No reentrancy: Log()/Flush() must not call the logging API or /// GetDefaultLogger() (UB -- deadlock with mutex-based sinks). /// - level() is an accessor consistent with ShouldLog (used by SetDefaultLevel /// and introspection); ShouldLog may implement finer logic than a level compare. @@ -187,7 +187,7 @@ class ICEBERG_EXPORT Logger { /// \brief Return the process-global default logger (never null). /// /// Off the hot path -- acquires the slot lock and returns an owning copy. The -/// logging macros use the cheaper internal hot-path accessor instead. +/// logging path uses the cheaper internal hot-path accessor instead. ICEBERG_EXPORT std::shared_ptr GetDefaultLogger(); /// \brief Return the effective logger for this thread (never null): the active @@ -214,7 +214,7 @@ ICEBERG_EXPORT void SetDefaultLevel(LogLevel level); /// \brief Bind a logger for the current thread until this object leaves scope. /// /// The default logging path on this thread -- CurrentLogger(), Log(level, ...), -/// and the LOG_* macros -- routes to \p logger instead of the global default; +/// and the ICEBERG_LOG_* macros -- routes to \p logger instead of the global default; /// explicit Log(logger, ...) is unaffected. Bindings nest and restore on exit, and /// nullptr masks any enclosing binding back to the global default. Lets an engine /// route Iceberg's own logs into a per catalog/session/query/task context with no @@ -247,8 +247,8 @@ class ICEBERG_EXPORT ScopedLogger { }; // --------------------------------------------------------------------------- -// Using the API directly (the LOG_* macros that wrap this are added later in -// the stack). Example: a custom sink, installed as the process default. +// Using the API directly (the ICEBERG_LOG_* macros that wrap this live in +// log_macros.h). Example: a custom sink, installed as the process default. // // class MySink : public Logger { // public: @@ -285,8 +285,8 @@ ICEBERG_EXPORT const std::shared_ptr& CurrentLogger() noexcept; /// \brief Build a LogMessage from the already-formatted text and dispatch it. /// -/// Declared ICEBERG_EXPORT because the logging macros expand into this call in -/// consumer translation units. +/// Declared ICEBERG_EXPORT because the logging helpers/macros expand into this +/// call in consumer translation units. ICEBERG_EXPORT void Emit(Logger& logger, LogLevel level, const std::source_location& location, std::string&& message); @@ -298,18 +298,6 @@ ICEBERG_EXPORT void Emit(Logger& logger, LogLevel level, ICEBERG_EXPORT void EmitFormatError(Logger& logger, LogLevel level, const std::source_location& location) noexcept; -/// \brief Runtime (non-literal) format-string helper. -/// -/// std::format requires a compile-time format string; this routes a runtime -/// string through std::vformat. Args are bound as named lvalues and the -/// arg-store is held in a named variable so it outlives the vformat call -/// (C++23 make_format_args rejects rvalues -- P2905 / LWG3631). -template -std::string VFormat(std::string_view fmt, Args&&... args) { - auto store = std::make_format_args(args...); - return std::vformat(fmt, store); -} - /// \brief A checked format string bundled with the caller's source_location. /// /// The consteval constructor preserves std::format's compile-time format-string @@ -374,186 +362,3 @@ void Log(Logger& logger, LogLevel level, } } // namespace iceberg - -// --------------------------------------------------------------------------- -// Logging macros. -// -// Every macro takes a std::format string followed by its arguments. The -// rendered line depends on the active backend (see cerr_logger.h for the -// std::cerr layout, or the spdlog pattern); the examples below show the call -// site and, for the default CerrLogger, the line it produces. -// -// ICEBERG_LOG_TRACE("entering scan for {}", table); -// 2026-06-16T10:59:41.186Z trace [12345] [table_scan.cc:88] entering scan for db.t -// ICEBERG_LOG_DEBUG("cache miss key={}", key); -// 2026-06-16T10:59:41.186Z debug [12345] [cache.cc:42] cache miss key=manifest-7 -// ICEBERG_LOG_INFO("loaded {} manifests in {} ms", n, ms); -// 2026-06-16T10:59:41.186Z info [12345] [table_scan.cc:91] loaded 5 manifests in 12 -// ms -// ICEBERG_LOG_WARN("retry {} after {}", attempt, err); -// 2026-06-16T10:59:41.186Z warn [12345] [io.cc:51] retry 2 after timeout -// ICEBERG_LOG_ERROR("commit failed: {}", status); -// 2026-06-16T10:59:41.186Z error [12345] [txn.cc:77] commit failed: conflict -// ICEBERG_LOG_CRITICAL("metadata unreadable at {}", path); -// 2026-06-16T10:59:41.186Z critical [12345] [meta.cc:30] metadata unreadable at -// s3://b/m.json -// ICEBERG_LOG_FATAL("unrecoverable: {}", reason); // emits, flushes, then -// std::abort() -// 2026-06-16T10:59:41.186Z fatal [12345] [boot.cc:19] unrecoverable: bad config -// -// Less common forms: -// ICEBERG_LOG(level, "level chosen at runtime: {}", x); // runtime severity -// ICEBERG_LOG_TO(logger, level, "to an explicit logger {}", y); -// ICEBERG_LOG_RUNTIME_FMT(level, fmt_string, args...); // non-literal format -// -// With ICEBERG_LOG_SHORT_MACROS defined, bare aliases (LOG_INFO, ...) are also -// available. A format string is mandatory; zero extra args is fine -// (ICEBERG_LOG_INFO("done")). -// --------------------------------------------------------------------------- - -/// \brief Compile-time severity floor: statements below this level are discarded -/// via `if constexpr`, so no emit code runs and no format call / source_location -/// is generated for them (the compiler is free to optimize the dead branch away). -/// The statement must still be well-formed -- a bad format string or a -/// non-formattable argument is a compile error even when the branch is discarded. -/// Defaults to keeping everything. ICEBERG_LOG_FATAL is never gated by this floor -/// -- its abort is always compiled in. -#ifndef ICEBERG_LOG_ACTIVE_LEVEL -# define ICEBERG_LOG_ACTIVE_LEVEL ::iceberg::LogLevel::kTrace -#endif - -// Internal: fixed-severity emit with compile-time floor then the authoritative -// Logger::ShouldLog (the single source of truth for runtime filtering), with -// formatting only on the taken path, never throwing. The catch-all upholds the -// "logging never throws" guarantee even when a user-defined std::formatter throws -// a non-std::exception type (a std::format_error/bad_alloc route to EmitFormatError). -#define ICEBERG_INTERNAL_LOG(level_, FMT_, ...) \ - do { \ - if constexpr ((level_) >= ICEBERG_LOG_ACTIVE_LEVEL) { \ - const auto& _ib_logger = ::iceberg::internal::CurrentLogger(); \ - if (_ib_logger && _ib_logger->ShouldLog(level_)) { \ - try { \ - ::iceberg::internal::Emit(*_ib_logger, (level_), \ - ::std::source_location::current(), \ - ::std::format(FMT_ __VA_OPT__(, ) __VA_ARGS__)); \ - } catch (...) { \ - ::iceberg::internal::EmitFormatError(*_ib_logger, (level_), \ - ::std::source_location::current()); \ - } \ - } \ - } \ - } while (0) - -#define ICEBERG_LOG_TRACE(...) \ - ICEBERG_INTERNAL_LOG(::iceberg::LogLevel::kTrace, __VA_ARGS__) -#define ICEBERG_LOG_DEBUG(...) \ - ICEBERG_INTERNAL_LOG(::iceberg::LogLevel::kDebug, __VA_ARGS__) -#define ICEBERG_LOG_INFO(...) \ - ICEBERG_INTERNAL_LOG(::iceberg::LogLevel::kInfo, __VA_ARGS__) -#define ICEBERG_LOG_WARN(...) \ - ICEBERG_INTERNAL_LOG(::iceberg::LogLevel::kWarn, __VA_ARGS__) -#define ICEBERG_LOG_ERROR(...) \ - ICEBERG_INTERNAL_LOG(::iceberg::LogLevel::kError, __VA_ARGS__) -#define ICEBERG_LOG_CRITICAL(...) \ - ICEBERG_INTERNAL_LOG(::iceberg::LogLevel::kCritical, __VA_ARGS__) - -// FATAL: emit if enabled (never compile-stripped), then ALWAYS flush + abort. -// Acquires the effective (scoped-or-default) logger ONCE -- honoring any active -// ScopedLogger binding -- and uses that same instance for emit and flush, so a -// concurrent SetDefaultLogger cannot flush a different logger than it emitted to. -#define ICEBERG_LOG_FATAL(FMT_, ...) \ - do { \ - auto _ib_logger = ::iceberg::GetCurrentLogger(); \ - if (_ib_logger && _ib_logger->ShouldLog(::iceberg::LogLevel::kFatal)) { \ - try { \ - ::iceberg::internal::Emit(*_ib_logger, ::iceberg::LogLevel::kFatal, \ - ::std::source_location::current(), \ - ::std::format(FMT_ __VA_OPT__(, ) __VA_ARGS__)); \ - } catch (...) { \ - ::iceberg::internal::EmitFormatError(*_ib_logger, ::iceberg::LogLevel::kFatal, \ - ::std::source_location::current()); \ - } \ - } \ - if (_ib_logger) _ib_logger->Flush(); \ - ::std::abort(); \ - } while (0) - -// Generic, runtime-level form against the default logger. No compile-time floor -// (the level is not a constant). Acquires the logger once; aborts when level == kFatal -// (flushing that same logger first). -#define ICEBERG_LOG(level_, FMT_, ...) \ - do { \ - const ::iceberg::LogLevel _ib_lvl = (level_); \ - const auto& _ib_logger = ::iceberg::internal::CurrentLogger(); \ - if (_ib_logger && _ib_logger->ShouldLog(_ib_lvl)) { \ - try { \ - ::iceberg::internal::Emit(*_ib_logger, _ib_lvl, \ - ::std::source_location::current(), \ - ::std::format(FMT_ __VA_OPT__(, ) __VA_ARGS__)); \ - } catch (...) { \ - ::iceberg::internal::EmitFormatError(*_ib_logger, _ib_lvl, \ - ::std::source_location::current()); \ - } \ - } \ - if (_ib_lvl == ::iceberg::LogLevel::kFatal) { \ - if (_ib_logger) _ib_logger->Flush(); \ - ::std::abort(); \ - } \ - } while (0) - -// Generic form targeting an EXPLICIT logger (must be an lvalue Logger&). Honors -// only that logger's ShouldLog. Aborts when level == kFatal. -#define ICEBERG_LOG_TO(logger_, level_, FMT_, ...) \ - do { \ - ::iceberg::Logger& _ib_logger = (logger_); \ - const ::iceberg::LogLevel _ib_lvl = (level_); \ - if (_ib_logger.ShouldLog(_ib_lvl)) { \ - try { \ - ::iceberg::internal::Emit(_ib_logger, _ib_lvl, \ - ::std::source_location::current(), \ - ::std::format(FMT_ __VA_OPT__(, ) __VA_ARGS__)); \ - } catch (...) { \ - ::iceberg::internal::EmitFormatError(_ib_logger, _ib_lvl, \ - ::std::source_location::current()); \ - } \ - } \ - if (_ib_lvl == ::iceberg::LogLevel::kFatal) { \ - _ib_logger.Flush(); \ - ::std::abort(); \ - } \ - } while (0) - -// Runtime (non-literal) format string against the default logger. Acquires the -// logger once; aborts when level == kFatal (flushing that same logger first). -#define ICEBERG_LOG_RUNTIME_FMT(level_, FMT_, ...) \ - do { \ - const ::iceberg::LogLevel _ib_lvl = (level_); \ - const auto& _ib_logger = ::iceberg::internal::CurrentLogger(); \ - if (_ib_logger && _ib_logger->ShouldLog(_ib_lvl)) { \ - try { \ - ::iceberg::internal::Emit( \ - *_ib_logger, _ib_lvl, ::std::source_location::current(), \ - ::iceberg::internal::VFormat((FMT_)__VA_OPT__(, ) __VA_ARGS__)); \ - } catch (...) { \ - ::iceberg::internal::EmitFormatError(*_ib_logger, _ib_lvl, \ - ::std::source_location::current()); \ - } \ - } \ - if (_ib_lvl == ::iceberg::LogLevel::kFatal) { \ - if (_ib_logger) _ib_logger->Flush(); \ - ::std::abort(); \ - } \ - } while (0) - -// Bare, Java-style aliases. Opt-IN only (define ICEBERG_LOG_SHORT_MACROS before -// including this header) to avoid colliding with glog/abseil/windows.h in -// consumer translation units. No bare LOG(level) is provided. -#ifdef ICEBERG_LOG_SHORT_MACROS -# define LOG_TRACE(...) ICEBERG_LOG_TRACE(__VA_ARGS__) -# define LOG_DEBUG(...) ICEBERG_LOG_DEBUG(__VA_ARGS__) -# define LOG_INFO(...) ICEBERG_LOG_INFO(__VA_ARGS__) -# define LOG_WARN(...) ICEBERG_LOG_WARN(__VA_ARGS__) -# define LOG_ERROR(...) ICEBERG_LOG_ERROR(__VA_ARGS__) -# define LOG_CRITICAL(...) ICEBERG_LOG_CRITICAL(__VA_ARGS__) -# define LOG_FATAL(...) ICEBERG_LOG_FATAL(__VA_ARGS__) -#endif // ICEBERG_LOG_SHORT_MACROS diff --git a/src/iceberg/logging/meson.build b/src/iceberg/logging/meson.build index e4ca111f4..901855a7c 100644 --- a/src/iceberg/logging/meson.build +++ b/src/iceberg/logging/meson.build @@ -16,6 +16,12 @@ # under the License. install_headers( - ['cerr_logger.h', 'log_level.h', 'logger.h'], + [ + 'cerr_logger.h', + 'log_level.h', + 'log_macros.h', + 'logger.h', + 'short_log_macros.h', + ], subdir: 'iceberg/logging', ) diff --git a/src/iceberg/logging/short_log_macros.h b/src/iceberg/logging/short_log_macros.h new file mode 100644 index 000000000..3aff53091 --- /dev/null +++ b/src/iceberg/logging/short_log_macros.h @@ -0,0 +1,38 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +#pragma once + +/// \file iceberg/logging/short_log_macros.h +/// \brief Opt-in bare LOG_* aliases for the ICEBERG_LOG_* macros. +/// +/// Separate opt-in header (not pulled in by logger.h or log_macros.h) so the +/// short, unprefixed names never leak into consumers by default -- they would +/// collide with glog/abseil/windows.h. Include this header explicitly to use +/// them. No bare LOG(level) is provided. + +#include "iceberg/logging/log_macros.h" + +#define LOG_TRACE(...) ICEBERG_LOG_TRACE(__VA_ARGS__) +#define LOG_DEBUG(...) ICEBERG_LOG_DEBUG(__VA_ARGS__) +#define LOG_INFO(...) ICEBERG_LOG_INFO(__VA_ARGS__) +#define LOG_WARN(...) ICEBERG_LOG_WARN(__VA_ARGS__) +#define LOG_ERROR(...) ICEBERG_LOG_ERROR(__VA_ARGS__) +#define LOG_CRITICAL(...) ICEBERG_LOG_CRITICAL(__VA_ARGS__) +#define LOG_FATAL(...) ICEBERG_LOG_FATAL(__VA_ARGS__) diff --git a/src/iceberg/test/macros_active_level_test.cc b/src/iceberg/test/macros_active_level_test.cc index c0e138a29..c97cb01a9 100644 --- a/src/iceberg/test/macros_active_level_test.cc +++ b/src/iceberg/test/macros_active_level_test.cc @@ -27,6 +27,7 @@ #include #include "iceberg/logging/log_level.h" +#include "iceberg/logging/log_macros.h" #include "iceberg/logging/logger.h" #include "iceberg/test/logging_test_helpers.h" diff --git a/src/iceberg/test/macros_test.cc b/src/iceberg/test/macros_test.cc index fb26f12fd..2d4712fd1 100644 --- a/src/iceberg/test/macros_test.cc +++ b/src/iceberg/test/macros_test.cc @@ -23,6 +23,7 @@ #include "iceberg/logging/cerr_logger.h" #include "iceberg/logging/log_level.h" +#include "iceberg/logging/log_macros.h" #include "iceberg/logging/logger.h" #include "iceberg/test/logging_test_helpers.h" From 7f2094ed6d54e591c607abf55fe9569ff23498d2 Mon Sep 17 00:00:00 2001 From: Kam Cheung Ting Date: Thu, 16 Jul 2026 07:07:43 +0000 Subject: [PATCH 5/7] =?UTF-8?q?feat(logging):=20add=20registerable=20Fatal?= =?UTF-8?q?Handler=20before=20abort=20(#725=20review=20=E2=91=A4)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Address the extensibility comment: let an embedder (JNI, Python host, crash reporter) run a hook on the fatal path before std::abort() to flush resources or print a stack trace. - Add FatalHandler = std::function plus thread-safe SetFatalHandler/GetFatalHandler (leaked, teardown-safe slot in logger.cc). - Wire it into LogFatal: format the message once, emit-if-enabled + flush, run the handler (message passed even when the record is filtered out), then abort. A throwing handler cannot prevent the abort. - Death tests: handler runs with the formatted message, receives the call-site location, and still fires when the record is suppressed. Co-authored-by: Isaac --- src/iceberg/CMakeLists.txt | 8 +++--- src/iceberg/logging/log_macros.h | 25 ++++++++++++++++--- src/iceberg/logging/logger.cc | 29 ++++++++++++++++++++++ src/iceberg/logging/logger.h | 21 ++++++++++++++++ src/iceberg/test/macros_test.cc | 42 ++++++++++++++++++++++++++++++++ 5 files changed, 118 insertions(+), 7 deletions(-) diff --git a/src/iceberg/CMakeLists.txt b/src/iceberg/CMakeLists.txt index c011a7a0c..280202ad3 100644 --- a/src/iceberg/CMakeLists.txt +++ b/src/iceberg/CMakeLists.txt @@ -193,10 +193,10 @@ add_iceberg_lib(iceberg OUTPUTS ICEBERG_LIBRARIES) -# The logging macros in the public logger.h use __VA_OPT__, which MSVC's -# traditional preprocessor rejects. Require the conforming preprocessor PUBLICly -# so both these library targets (logger.cc includes logger.h) and downstream -# consumers of the installed header get it on MSVC. +# The logging macros in the installed public header log_macros.h use __VA_OPT__, +# which MSVC's traditional preprocessor rejects. Require the conforming +# preprocessor PUBLICly so downstream consumers that include log_macros.h get it +# on MSVC (and any library TU that includes it does too). if(MSVC_TOOLCHAIN) foreach(_iceberg_lib iceberg_shared iceberg_static) if(TARGET ${_iceberg_lib}) diff --git a/src/iceberg/logging/log_macros.h b/src/iceberg/logging/log_macros.h index 3d8d014ac..cbf33dc36 100644 --- a/src/iceberg/logging/log_macros.h +++ b/src/iceberg/logging/log_macros.h @@ -108,16 +108,35 @@ void LogToExplicitRuntime(Logger& logger, LogLevel level, } /// \brief Fatal path: acquire the effective (scoped-or-default) logger ONCE, emit -/// if enabled, flush that same logger, then abort. Never returns. +/// if enabled, flush that same logger, run any registered FatalHandler, then +/// abort. Never returns. +/// +/// The message is always formatted here (independent of ShouldLog) so the handler +/// receives it even when the fatal record itself is filtered out. The handler runs +/// after emit+flush and before abort; if it does not itself terminate the process, +/// std::abort() still runs. template [[noreturn]] void LogFatal(const std::source_location& location, MakeMessage&& make_message) noexcept { + std::string message; + try { + message = std::forward(make_message)(); + } catch (...) { + message = ""; + } auto logger = GetCurrentLogger(); if (logger) { - EmitIfEnabled(*logger, LogLevel::kFatal, location, - std::forward(make_message)); + if (logger->ShouldLog(LogLevel::kFatal)) { + Emit(*logger, LogLevel::kFatal, location, std::string(message)); + } logger->Flush(); } + if (auto handler = GetFatalHandler()) { + try { + handler(location, message); + } catch (...) { // a throwing handler must not prevent the abort + } + } std::abort(); } diff --git a/src/iceberg/logging/logger.cc b/src/iceberg/logging/logger.cc index a8db67ca9..77895e36f 100644 --- a/src/iceberg/logging/logger.cc +++ b/src/iceberg/logging/logger.cc @@ -106,6 +106,35 @@ void SetDefaultLevel(LogLevel level) { slot.logger->SetLevel(level); } +namespace { + +/// \brief Immortal (leaked, hence teardown-safe) home for the fatal handler and +/// its mutex. Leaked like Slot() so GetFatalHandler() is valid even during static +/// teardown / from the fatal path at any time. +struct FatalHandlerSlot { + std::mutex mtx; + FatalHandler handler; +}; + +FatalHandlerSlot& FatalSlot() { + static auto* slot = new FatalHandlerSlot(); + return *slot; +} + +} // namespace + +void SetFatalHandler(FatalHandler handler) { + FatalHandlerSlot& slot = FatalSlot(); + std::lock_guard lock(slot.mtx); + slot.handler = std::move(handler); +} + +FatalHandler GetFatalHandler() { + FatalHandlerSlot& slot = FatalSlot(); + std::lock_guard lock(slot.mtx); + return slot.handler; // copy under lock; safe to invoke without holding the lock +} + namespace internal { namespace { diff --git a/src/iceberg/logging/logger.h b/src/iceberg/logging/logger.h index 3034103ea..0a9647f66 100644 --- a/src/iceberg/logging/logger.h +++ b/src/iceberg/logging/logger.h @@ -29,6 +29,7 @@ #include #include #include +#include #include #include #include @@ -211,6 +212,26 @@ ICEBERG_EXPORT void SetDefaultLogger(std::shared_ptr logger); /// means (this, SetLevel on a held handle, or Initialize) takes effect immediately. ICEBERG_EXPORT void SetDefaultLevel(LogLevel level); +/// \brief A hook invoked on the fatal-log path just before std::abort(). +/// +/// Receives the fatal record's source location and already-formatted message. +/// Runs after the record has been emitted and the logger flushed, so an embedder +/// (JNI, a Python host, a crash reporter) can print a stack trace, flush its own +/// resources, or translate the abort. It must not return normally on the +/// expectation of cancelling the abort -- ICEBERG_LOG_FATAL always terminates; if +/// the handler itself does not exit the process, std::abort() still runs after it. +using FatalHandler = + std::function; + +/// \brief Install (or clear, with nullptr) the process-global fatal handler. +/// +/// Thread-safe. Intended to be set once at startup. Replaces any previous handler. +ICEBERG_EXPORT void SetFatalHandler(FatalHandler handler); + +/// \brief Return the installed fatal handler (empty if none). Used by the fatal +/// logging path; thread-safe. +ICEBERG_EXPORT FatalHandler GetFatalHandler(); + /// \brief Bind a logger for the current thread until this object leaves scope. /// /// The default logging path on this thread -- CurrentLogger(), Log(level, ...), diff --git a/src/iceberg/test/macros_test.cc b/src/iceberg/test/macros_test.cc index 2d4712fd1..a92e03795 100644 --- a/src/iceberg/test/macros_test.cc +++ b/src/iceberg/test/macros_test.cc @@ -17,7 +17,10 @@ * under the License. */ +#include #include +#include +#include #include @@ -162,4 +165,43 @@ TEST(MacrosDeathTest, FatalRoutesThroughScopedLogger) { "scopedfatal 9"); } +// A registered FatalHandler runs on the fatal path (after emit+flush) and receives +// the formatted message; the process still aborts afterwards. +TEST(MacrosDeathTest, FatalHandlerRunsWithFormattedMessageBeforeAbort) { + EXPECT_DEATH( + { + SetFatalHandler([](const std::source_location&, std::string_view message) { + std::cerr << "HANDLER[" << message << "]\n"; + }); + ICEBERG_LOG_FATAL("boom {}", 42); + }, + "HANDLER\\[boom 42\\]"); +} + +// The handler receives the caller's source location. +TEST(MacrosDeathTest, FatalHandlerReceivesCallSiteLocation) { + EXPECT_DEATH( + { + SetFatalHandler([](const std::source_location& loc, std::string_view) { + std::cerr << "LOC:" << (loc.line() > 0 ? "ok" : "bad") << "\n"; + }); + ICEBERG_LOG_FATAL("x"); + }, + "LOC:ok"); +} + +// The handler is a termination hook independent of log filtering: it still fires +// (with the formatted message) when the fatal record itself is suppressed. +TEST(MacrosDeathTest, FatalHandlerRunsEvenWhenRecordSuppressed) { + EXPECT_DEATH( + { + SetDefaultLevel(LogLevel::kOff); + SetFatalHandler([](const std::source_location&, std::string_view message) { + std::cerr << "H[" << message << "]\n"; + }); + ICEBERG_LOG_FATAL("suppressed {}", 7); + }, + "H\\[suppressed 7\\]"); +} + } // namespace iceberg From fd92bc26e54a22470fd26ab38d81ebb84d0d423b Mon Sep 17 00:00:00 2001 From: Kam Cheung Ting Date: Mon, 15 Jun 2026 10:54:20 +0000 Subject: [PATCH 6/7] feat(logging): add spdlog backend behind ICEBERG_SPDLOG (5/6) Fifth block: the default production backend and the build option that selects it. - SpdLogger wraps spdlog::logger (kCritical/kFatal -> spdlog critical, others 1:1), forwarding the pre-formatted message and source location. Synchronous only in v1 (spdlog's source_loc is a non-owning const char*, unsafe with async sinks). It lives in logging/internal/, is gated by #ifdef ICEBERG_HAS_SPDLOG, and is NOT installed -- consumers obtain it via the default logger or the registry, never by including spdlog headers. - New ICEBERG_SPDLOG CMake option (default ON). config.h is ALWAYS generated (only ICEBERG_HAS_SPDLOG's definedness varies) so logger.cc compiles in both configurations; MakeDefaultLogger() prefers SpdLogger when compiled in, else CerrLogger. - Critically, ICEBERG_SPDLOG=OFF now UNWIRES the previously-unconditional spdlog link (interface-lib lists + resolve_spdlog_dependency), not just the new source -- so an OFF build has no spdlog dependency at all. spdlog_logger_test (compiled only on the ON path) covers the level mapping including fatal->critical and source-location forwarding. Co-authored-by: Isaac --- CMakeLists.txt | 1 + .../IcebergThirdpartyToolchain.cmake | 4 +- src/iceberg/CMakeLists.txt | 28 ++++- src/iceberg/logging/config.h.in | 30 +++++ src/iceberg/logging/internal/spdlog_logger.cc | 103 +++++++++++++++++ src/iceberg/logging/internal/spdlog_logger.h | 89 +++++++++++++++ src/iceberg/logging/logger.cc | 18 ++- src/iceberg/logging/meson.build | 10 ++ src/iceberg/meson.build | 3 + src/iceberg/test/CMakeLists.txt | 3 +- src/iceberg/test/meson.build | 1 + src/iceberg/test/spdlog_logger_test.cc | 106 ++++++++++++++++++ 12 files changed, 387 insertions(+), 9 deletions(-) create mode 100644 src/iceberg/logging/config.h.in create mode 100644 src/iceberg/logging/internal/spdlog_logger.cc create mode 100644 src/iceberg/logging/internal/spdlog_logger.h create mode 100644 src/iceberg/test/spdlog_logger_test.cc diff --git a/CMakeLists.txt b/CMakeLists.txt index 7cbd5e55e..0882be68f 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -54,6 +54,7 @@ option(ICEBERG_S3 "Build with S3 support" OFF) option(ICEBERG_SIGV4 "Build with SigV4 support" OFF) option(ICEBERG_BUNDLE_AWSSDK "Bundle AWS SDK for S3/SigV4 support" ON) option(ICEBERG_BUNDLE_THRIFT "Bundle Thrift (from Arrow) for Hive catalog" ON) +option(ICEBERG_SPDLOG "Use spdlog as the default logging backend" ON) option(ICEBERG_ENABLE_ASAN "Enable Address Sanitizer" OFF) option(ICEBERG_ENABLE_UBSAN "Enable Undefined Behavior Sanitizer" OFF) diff --git a/cmake_modules/IcebergThirdpartyToolchain.cmake b/cmake_modules/IcebergThirdpartyToolchain.cmake index 86e840097..89bbe9b7e 100644 --- a/cmake_modules/IcebergThirdpartyToolchain.cmake +++ b/cmake_modules/IcebergThirdpartyToolchain.cmake @@ -806,7 +806,9 @@ resolve_nanoarrow_dependency() resolve_croaring_dependency() resolve_utf8proc_dependency() resolve_nlohmann_json_dependency() -resolve_spdlog_dependency() +if(ICEBERG_SPDLOG) + resolve_spdlog_dependency() +endif() if(ICEBERG_S3 OR ICEBERG_SIGV4) if(ICEBERG_SIGV4 AND NOT ICEBERG_BUILD_REST) diff --git a/src/iceberg/CMakeLists.txt b/src/iceberg/CMakeLists.txt index 280202ad3..c892616cb 100644 --- a/src/iceberg/CMakeLists.txt +++ b/src/iceberg/CMakeLists.txt @@ -17,6 +17,18 @@ set(ICEBERG_INCLUDES "$" "$") + +# Generate the logging backend config header. ALWAYS generated (not gated by +# ICEBERG_SPDLOG) so logging/logger.cc can include it in both ON and OFF builds; +# only the definedness of ICEBERG_HAS_SPDLOG varies. Generated into the build +# tree (already on ICEBERG_INCLUDES), included as "iceberg/logging/config.h", and +# NOT installed (it must never appear in a public/installed header). +if(ICEBERG_SPDLOG) + set(ICEBERG_HAS_SPDLOG ON) +endif() +configure_file("${CMAKE_CURRENT_SOURCE_DIR}/logging/config.h.in" + "${CMAKE_CURRENT_BINARY_DIR}/logging/config.h") + set(ICEBERG_SOURCES arrow_c_data_guard_internal.cc arrow_c_data_util.cc @@ -154,29 +166,37 @@ list(APPEND ICEBERG_STATIC_BUILD_INTERFACE_LIBS "$,nanoarrow::nanoarrow_static,$,nanoarrow::nanoarrow_static,nanoarrow::nanoarrow_shared>>" nlohmann_json::nlohmann_json - spdlog::spdlog utf8proc::utf8proc ZLIB::ZLIB) list(APPEND ICEBERG_SHARED_BUILD_INTERFACE_LIBS "$,nanoarrow::nanoarrow_static,$,nanoarrow::nanoarrow_shared,nanoarrow::nanoarrow_static>>" nlohmann_json::nlohmann_json - spdlog::spdlog utf8proc::utf8proc ZLIB::ZLIB) list(APPEND ICEBERG_STATIC_INSTALL_INTERFACE_LIBS "$,iceberg::nanoarrow_static,$,nanoarrow::nanoarrow_static,nanoarrow::nanoarrow_shared>>" "$,iceberg::nlohmann_json,$,nlohmann_json::nlohmann_json,nlohmann_json::nlohmann_json>>" - "$,iceberg::spdlog,spdlog::spdlog>" "$,iceberg::utf8proc,utf8proc::utf8proc>") list(APPEND ICEBERG_SHARED_INSTALL_INTERFACE_LIBS "$,iceberg::nanoarrow_static,$,nanoarrow::nanoarrow_shared,nanoarrow::nanoarrow_static>>" "$,iceberg::nlohmann_json,$,nlohmann_json::nlohmann_json,nlohmann_json::nlohmann_json>>" - "$,iceberg::spdlog,spdlog::spdlog>" "$,iceberg::utf8proc,utf8proc::utf8proc>") +# spdlog backend: linked and compiled only when ICEBERG_SPDLOG is ON. When OFF, +# the core library has no spdlog dependency and CerrLogger is the default sink. +if(ICEBERG_SPDLOG) + list(APPEND ICEBERG_SOURCES logging/internal/spdlog_logger.cc) + list(APPEND ICEBERG_STATIC_BUILD_INTERFACE_LIBS spdlog::spdlog) + list(APPEND ICEBERG_SHARED_BUILD_INTERFACE_LIBS spdlog::spdlog) + list(APPEND ICEBERG_STATIC_INSTALL_INTERFACE_LIBS + "$,iceberg::spdlog,spdlog::spdlog>") + list(APPEND ICEBERG_SHARED_INSTALL_INTERFACE_LIBS + "$,iceberg::spdlog,spdlog::spdlog>") +endif() + add_iceberg_lib(iceberg SOURCES ${ICEBERG_SOURCES} diff --git a/src/iceberg/logging/config.h.in b/src/iceberg/logging/config.h.in new file mode 100644 index 000000000..1b1e0d02c --- /dev/null +++ b/src/iceberg/logging/config.h.in @@ -0,0 +1,30 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +#pragma once + +// Internal, build-generated configuration for the logging backend. +// This header is NOT installed and must only be included from .cc files +// (logger.cc, internal/spdlog_logger.cc) -- never from a public header. +// +// ICEBERG_HAS_SPDLOG is defined when the project is built with -DICEBERG_SPDLOG=ON +// and left undefined otherwise. Always test it with #ifdef / #ifndef, never #if +// (it carries no value). + +#cmakedefine ICEBERG_HAS_SPDLOG diff --git a/src/iceberg/logging/internal/spdlog_logger.cc b/src/iceberg/logging/internal/spdlog_logger.cc new file mode 100644 index 000000000..4ede3f402 --- /dev/null +++ b/src/iceberg/logging/internal/spdlog_logger.cc @@ -0,0 +1,103 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +#include "iceberg/logging/internal/spdlog_logger.h" + +#ifdef ICEBERG_HAS_SPDLOG + +# include +# include +# include +# include + +# include +# include + +namespace iceberg::internal { + +namespace { + +spdlog::level::level_enum ToSpdLevel(LogLevel level) noexcept { + switch (level) { + case LogLevel::kTrace: + return spdlog::level::trace; + case LogLevel::kDebug: + return spdlog::level::debug; + case LogLevel::kInfo: + return spdlog::level::info; + case LogLevel::kWarn: + return spdlog::level::warn; + case LogLevel::kError: + return spdlog::level::err; + case LogLevel::kCritical: + case LogLevel::kFatal: + // spdlog has no "fatal"; the process abort is owned by the macro layer. + return spdlog::level::critical; + case LogLevel::kOff: + return spdlog::level::off; + } + return spdlog::level::off; +} + +} // namespace + +SpdLogger::SpdLogger(LogLevel level) + : SpdLogger(std::make_shared( + "iceberg", std::make_shared()), + level) {} + +Status SpdLogger::Initialize( + const std::unordered_map& properties) { + if (auto it = properties.find(std::string(kPatternProperty)); it != properties.end()) { + logger_->set_pattern(it->second); + } + // Apply "level" via the base implementation. + return Logger::Initialize(properties); +} + +SpdLogger::SpdLogger(std::shared_ptr logger, LogLevel level) + : logger_(std::move(logger)), level_(level) { + if (logger_) { + logger_->set_level(spdlog::level::trace); // filtering is done by ShouldLog + } +} + +void SpdLogger::Log(LogMessage&& message) noexcept { + try { + spdlog::source_loc loc{message.location.file_name(), + static_cast(message.location.line()), + message.location.function_name()}; + // Pass the pre-formatted text as an argument ("{}") so any braces in the + // message are not re-interpreted as a format string. + logger_->log(loc, ToSpdLevel(message.level), "{}", message.message); + } catch (...) { + // Logging must never throw. + } +} + +void SpdLogger::Flush() noexcept { + try { + logger_->flush(); + } catch (...) { + } +} + +} // namespace iceberg::internal + +#endif // ICEBERG_HAS_SPDLOG diff --git a/src/iceberg/logging/internal/spdlog_logger.h b/src/iceberg/logging/internal/spdlog_logger.h new file mode 100644 index 000000000..649ed3073 --- /dev/null +++ b/src/iceberg/logging/internal/spdlog_logger.h @@ -0,0 +1,89 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +#pragma once + +/// \file iceberg/logging/internal/spdlog_logger.h +/// \brief spdlog-backed logging sink. +/// +/// INTERNAL, NOT INSTALLED. It is only included from .cc files (logger.cc and +/// spdlog_logger.cc) after config.h, and only when the project is built with +/// ICEBERG_SPDLOG=ON. SpdLogger is not a consumer-constructible public type -- +/// applications obtain it via the default logger or the "logger-impl"="spdlog" +/// registry factory. + +#include "iceberg/logging/config.h" + +#ifdef ICEBERG_HAS_SPDLOG + +# include +# include + +# include + +# include "iceberg/logging/log_level.h" +# include "iceberg/logging/logger.h" + +namespace iceberg::internal { + +/// \brief Logger backed by spdlog (synchronous only in v1). +/// +/// Synchronous because spdlog::source_loc holds non-owning const char* that are +/// unsafe to forward into an async logger (spdlog #3227). +/// ICEBERG_EXPORT so the symbol is linkable from in-tree tests (and any +/// internal consumer) under -fvisibility=hidden / MSVC DLL builds. The header +/// is still not installed -- this is a binary-visibility detail, not public API. +class ICEBERG_EXPORT SpdLogger : public Logger { + public: + /// \brief Construct over a default stderr-backed spdlog logger. + explicit SpdLogger(LogLevel level = LogLevel::kInfo); + + /// \brief Construct over a caller-provided spdlog logger. + /// + /// The logger MUST be synchronous. Log() forwards spdlog::source_loc, which + /// borrows the std::source_location's const char* pointers; an async spdlog + /// logger would queue them past their lifetime (spdlog #3227 -> UB). This is a + /// caller contract -- spdlog exposes no reliable sync/async query to assert on. + explicit SpdLogger(std::shared_ptr logger, + LogLevel level = LogLevel::kInfo); + + /// \brief Apply the "pattern" property (spdlog set_pattern), then "level". + Status Initialize( + const std::unordered_map& properties) override; + + bool ShouldLog(LogLevel level) const noexcept override { + return level >= level_.load(std::memory_order_relaxed); + } + void Log(LogMessage&& message) noexcept override; + void SetLevel(LogLevel level) noexcept override { + level_.store(level, std::memory_order_relaxed); + } + LogLevel level() const noexcept override { + return level_.load(std::memory_order_relaxed); + } + void Flush() noexcept override; + + private: + std::shared_ptr logger_; + std::atomic level_; +}; + +} // namespace iceberg::internal + +#endif // ICEBERG_HAS_SPDLOG diff --git a/src/iceberg/logging/logger.cc b/src/iceberg/logging/logger.cc index 77895e36f..657687456 100644 --- a/src/iceberg/logging/logger.cc +++ b/src/iceberg/logging/logger.cc @@ -26,7 +26,13 @@ #include #include +// Build-generated, .cc-only (never from a public header). Defines +// ICEBERG_HAS_SPDLOG when built with -DICEBERG_SPDLOG=ON; tested with #ifdef. #include "iceberg/logging/cerr_logger.h" +#include "iceberg/logging/config.h" +#ifdef ICEBERG_HAS_SPDLOG +# include "iceberg/logging/internal/spdlog_logger.h" +#endif namespace iceberg { @@ -44,9 +50,15 @@ class NoopLogger final : public Logger { /// \brief Construct the process default logger for this build configuration. /// -/// Uses the always-available std::cerr sink. The spdlog backend (preferred when -/// compiled in) is wired into this factory in a later block. -std::shared_ptr MakeDefaultLogger() { return std::make_shared(); } +/// Prefers the spdlog backend when compiled in; otherwise the always-available +/// std::cerr logger. +std::shared_ptr MakeDefaultLogger() { +#ifdef ICEBERG_HAS_SPDLOG + return std::make_shared(); +#else + return std::make_shared(); +#endif +} /// \brief The process-global default-logger slot. struct DefaultSlot { diff --git a/src/iceberg/logging/meson.build b/src/iceberg/logging/meson.build index 901855a7c..e26318368 100644 --- a/src/iceberg/logging/meson.build +++ b/src/iceberg/logging/meson.build @@ -15,6 +15,16 @@ # specific language governing permissions and limitations # under the License. +# Generate the .cc-only logging backend config header. The meson build always +# links spdlog, so ICEBERG_HAS_SPDLOG is always defined here. Generated into +# build/src/iceberg/logging/config.h (resolved via include_directories('..'), +# which exposes both the source and build trees); not installed. +logging_config_data = configuration_data() +logging_config_data.set('ICEBERG_HAS_SPDLOG', 1) +configure_file(output: 'config.h', configuration: logging_config_data) + +# Public logging headers. The build-generated config.h and the internal +# SpdLogger header are intentionally NOT installed. install_headers( [ 'cerr_logger.h', diff --git a/src/iceberg/meson.build b/src/iceberg/meson.build index 1de293cb5..b247b2942 100644 --- a/src/iceberg/meson.build +++ b/src/iceberg/meson.build @@ -63,6 +63,8 @@ configure_file( install_dir: get_option('includedir') / 'iceberg', ) +# Generate iceberg/logging/config.h (must precede the library() that compiles +# the logging sources which include it). subdir('logging') iceberg_include_dir = include_directories('..') @@ -100,6 +102,7 @@ iceberg_sources = files( 'json_serde.cc', 'location_provider.cc', 'logging/cerr_logger.cc', + 'logging/internal/spdlog_logger.cc', 'logging/logger.cc', 'manifest/manifest_adapter.cc', 'manifest/manifest_entry.cc', diff --git a/src/iceberg/test/CMakeLists.txt b/src/iceberg/test/CMakeLists.txt index 30a581129..09872df9e 100644 --- a/src/iceberg/test/CMakeLists.txt +++ b/src/iceberg/test/CMakeLists.txt @@ -107,7 +107,8 @@ add_iceberg_test(logging_test log_level_test.cc logger_test.cc macros_active_level_test.cc - macros_test.cc) + macros_test.cc + spdlog_logger_test.cc) add_iceberg_test(expression_test SOURCES diff --git a/src/iceberg/test/meson.build b/src/iceberg/test/meson.build index b8217d3cd..a3d1e3c50 100644 --- a/src/iceberg/test/meson.build +++ b/src/iceberg/test/meson.build @@ -69,6 +69,7 @@ iceberg_tests = { 'logger_test.cc', 'macros_active_level_test.cc', 'macros_test.cc', + 'spdlog_logger_test.cc', ), }, 'expression_test': { diff --git a/src/iceberg/test/spdlog_logger_test.cc b/src/iceberg/test/spdlog_logger_test.cc new file mode 100644 index 000000000..30bbe6ff7 --- /dev/null +++ b/src/iceberg/test/spdlog_logger_test.cc @@ -0,0 +1,106 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +// Internal/build-generated header is acceptable in a test TU (not installed). +#include "iceberg/logging/config.h" + +#ifdef ICEBERG_HAS_SPDLOG + +# include +# include +# include +# include +# include + +# include +# include +# include + +# include "iceberg/logging/internal/spdlog_logger.h" +# include "iceberg/logging/log_level.h" +# include "iceberg/logging/logger.h" + +namespace iceberg { + +namespace { + +LogMessage MakeMessage(LogLevel level, std::string text) { + return LogMessage{.level = level, + .message = std::move(text), + .location = std::source_location::current(), + .attributes = {}}; +} + +internal::SpdLogger MakeCapturing(std::ostringstream& out, + LogLevel level = LogLevel::kTrace) { + auto sink = std::make_shared(out); + auto spd = std::make_shared("test", sink); + return internal::SpdLogger(spd, level); +} + +} // namespace + +TEST(SpdLoggerTest, DefaultLevelIsInfo) { + internal::SpdLogger logger; + EXPECT_EQ(logger.level(), LogLevel::kInfo); + EXPECT_FALSE(logger.ShouldLog(LogLevel::kDebug)); + EXPECT_TRUE(logger.ShouldLog(LogLevel::kError)); +} + +TEST(SpdLoggerTest, ForwardsMessageToSink) { + std::ostringstream out; + auto logger = MakeCapturing(out); + logger.Log(MakeMessage(LogLevel::kError, "boom 42")); + logger.Flush(); + EXPECT_NE(out.str().find("boom 42"), std::string::npos); +} + +TEST(SpdLoggerTest, MessageBracesAreNotInterpreted) { + std::ostringstream out; + auto logger = MakeCapturing(out); + // A pre-formatted message containing braces must pass through verbatim. + logger.Log(MakeMessage(LogLevel::kInfo, "literal {not a placeholder}")); + logger.Flush(); + EXPECT_NE(out.str().find("literal {not a placeholder}"), std::string::npos); +} + +TEST(SpdLoggerTest, CriticalAndFatalBothEmit) { + std::ostringstream out; + auto logger = MakeCapturing(out); + logger.Log(MakeMessage(LogLevel::kCritical, "crit")); + logger.Log(MakeMessage(LogLevel::kFatal, "fatal-tag")); + logger.Flush(); + EXPECT_NE(out.str().find("crit"), std::string::npos); + EXPECT_NE(out.str().find("fatal-tag"), std::string::npos); +} + +TEST(SpdLoggerTest, PatternPropertyChangesLayout) { + std::ostringstream out; + auto logger = MakeCapturing(out); + auto status = + logger.Initialize({{std::string(kPatternProperty), std::string("PFX %v")}}); + ASSERT_TRUE(status.has_value()); + logger.Log(MakeMessage(LogLevel::kError, "hello")); + logger.Flush(); + EXPECT_NE(out.str().find("PFX hello"), std::string::npos); +} + +} // namespace iceberg + +#endif // ICEBERG_HAS_SPDLOG From aaa1ebfa33b59d73e88aa9d9b8f86a7d06b72246 Mon Sep 17 00:00:00 2001 From: Kam Cheung Ting Date: Mon, 15 Jun 2026 10:56:03 +0000 Subject: [PATCH 7/7] feat(logging): add Loggers registry (6/6) Final block: configuration-driven backend selection, mirroring MetricsReporters. - Loggers::Register(type, factory) registers a named backend; Loggers::Load(props) builds one, selecting the type from the "logger-impl" property key. - Built-in factories: "noop", "cerr", and (only when built with ICEBERG_SPDLOG) "spdlog". With no logger-impl set, the default is spdlog when compiled in, else cerr -- logs by default, an intentional divergence from the metrics registry's noop default. - Loggers::LoadAndSetDefault(props) loads a logger and installs it as the process default. This completes the system end to end: levels -> Logger interface + default logger -> CerrLogger/SpdLogger backends -> macros -> configuration-driven selection. loggers_test covers load default/noop/cerr, unknown-type errors, empty-factory rejection, custom Register, and LoadAndSetDefault. Adds logging_end_to_end_test, which drives the public surface as an application does -- now that every layer is present: configure a backend via the registry, install it as the default, log through the LOG_* macros, and observe real output. Covers registry -> default-slot -> macro -> backend -> std::cerr output, level filtering through the full macro path, the compiled-backend identity of the default (spdlog when ON, cerr when OFF), the "spdlog" factory by name, and a macro statement reaching a real spdlog sink. Co-authored-by: Isaac --- src/iceberg/CMakeLists.txt | 1 + src/iceberg/logging/loggers.cc | 147 +++++++++++++++++ src/iceberg/logging/loggers.h | 68 ++++++++ src/iceberg/logging/meson.build | 1 + src/iceberg/meson.build | 1 + src/iceberg/test/CMakeLists.txt | 2 + src/iceberg/test/loggers_test.cc | 105 ++++++++++++ src/iceberg/test/logging_end_to_end_test.cc | 168 ++++++++++++++++++++ src/iceberg/test/meson.build | 2 + 9 files changed, 495 insertions(+) create mode 100644 src/iceberg/logging/loggers.cc create mode 100644 src/iceberg/logging/loggers.h create mode 100644 src/iceberg/test/loggers_test.cc create mode 100644 src/iceberg/test/logging_end_to_end_test.cc diff --git a/src/iceberg/CMakeLists.txt b/src/iceberg/CMakeLists.txt index c892616cb..0d676ca5a 100644 --- a/src/iceberg/CMakeLists.txt +++ b/src/iceberg/CMakeLists.txt @@ -65,6 +65,7 @@ set(ICEBERG_SOURCES location_provider.cc logging/cerr_logger.cc logging/logger.cc + logging/loggers.cc manifest/manifest_adapter.cc manifest/manifest_entry.cc manifest/manifest_filter_manager.cc diff --git a/src/iceberg/logging/loggers.cc b/src/iceberg/logging/loggers.cc new file mode 100644 index 000000000..479703036 --- /dev/null +++ b/src/iceberg/logging/loggers.cc @@ -0,0 +1,147 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +#include "iceberg/logging/loggers.h" + +#include +#include +#include +#include +#include +#include +#include + +// Build-generated, .cc-only. Defines ICEBERG_HAS_SPDLOG; tested with #ifdef. +#include "iceberg/logging/cerr_logger.h" +#include "iceberg/logging/config.h" +#include "iceberg/util/macros.h" +#ifdef ICEBERG_HAS_SPDLOG +# include "iceberg/logging/internal/spdlog_logger.h" +#endif + +namespace iceberg { + +namespace { + +/// \brief Registry-constructible no-op logger (Load returns unique_ptr). +class NoopLogger final : public Logger { + public: + bool ShouldLog(LogLevel /*level*/) const noexcept override { return false; } + void Log(LogMessage&& /*message*/) noexcept override {} + void SetLevel(LogLevel /*level*/) noexcept override {} + LogLevel level() const noexcept override { return LogLevel::kOff; } + bool IsNoop() const override { return true; } +}; + +/// \brief Extract the logger type, defaulting to the compiled-in backend. +std::string InferLoggerType( + const std::unordered_map& properties) { + auto it = properties.find(std::string(kLoggerImpl)); + if (it != properties.end() && !it->second.empty()) { + return it->second; + } +#ifdef ICEBERG_HAS_SPDLOG + return std::string(kLoggerTypeSpdlog); +#else + return std::string(kLoggerTypeCerr); +#endif +} + +struct LoggerRegistryState { + std::shared_mutex mtx; + std::unordered_map map; +}; + +LoggerRegistryState& GetRegistry() { + static auto* state = + new LoggerRegistryState{.map = { + {std::string(kLoggerTypeNoop), + [](const std::unordered_map&) + -> Result> { + return std::make_unique(); + }}, + {std::string(kLoggerTypeCerr), + [](const std::unordered_map&) + -> Result> { + return std::make_unique(); + }}, +#ifdef ICEBERG_HAS_SPDLOG + {std::string(kLoggerTypeSpdlog), + [](const std::unordered_map&) + -> Result> { + return std::make_unique(); + }}, +#endif + }}; + return *state; +} + +} // namespace + +Status Loggers::Register(std::string_view logger_type, LoggerFactory factory) { + if (!factory) { + return InvalidArgument("Logger factory for '{}' must not be empty", logger_type); + } + auto& registry = GetRegistry(); + std::unique_lock lock(registry.mtx); + registry.map[std::string(logger_type)] = std::move(factory); + return {}; +} + +Result> Loggers::Load( + const std::unordered_map& properties) { + std::string logger_type = InferLoggerType(properties); + + LoggerFactory factory; + { + auto& registry = GetRegistry(); + std::shared_lock lock(registry.mtx); + auto it = registry.map.find(logger_type); + if (it == registry.map.end()) { + return InvalidArgument( + "Unknown logger type '{}'. Register a factory with Loggers::Register() " + "before using this type.", + logger_type); + } + factory = it->second; + } + + try { + ICEBERG_ASSIGN_OR_RAISE(auto logger, factory(properties)); + if (!logger) { + return InvalidArgument("Logger factory for '{}' returned null", logger_type); + } + ICEBERG_RETURN_UNEXPECTED(logger->Initialize(properties)); + return logger; + } catch (const std::exception& ex) { + return InvalidArgument("Logger factory for '{}' failed: {}", logger_type, ex.what()); + } catch (...) { + return InvalidArgument("Logger factory for '{}' failed with unknown exception", + logger_type); + } +} + +Status Loggers::LoadAndSetDefault( + const std::unordered_map& properties) { + ICEBERG_ASSIGN_OR_RAISE(auto logger, Load(properties)); + SetDefaultLogger(std::shared_ptr(std::move(logger))); + return {}; +} + +} // namespace iceberg diff --git a/src/iceberg/logging/loggers.h b/src/iceberg/logging/loggers.h new file mode 100644 index 000000000..36ccab1d5 --- /dev/null +++ b/src/iceberg/logging/loggers.h @@ -0,0 +1,68 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +#pragma once + +/// \file iceberg/logging/loggers.h +/// \brief Property-driven registry/factory for Logger backends. + +#include +#include +#include +#include +#include + +#include "iceberg/iceberg_export.h" +#include "iceberg/logging/logger.h" +#include "iceberg/result.h" + +namespace iceberg { + +/// \brief Property key selecting the logger implementation. +constexpr std::string_view kLoggerImpl = "logger-impl"; +/// \brief Built-in logger type identifiers. +constexpr std::string_view kLoggerTypeNoop = "noop"; +constexpr std::string_view kLoggerTypeCerr = "cerr"; +constexpr std::string_view kLoggerTypeSpdlog = "spdlog"; + +/// \brief Factory constructing a Logger from catalog-style properties. +using LoggerFactory = std::function>( + const std::unordered_map& properties)>; + +/// \brief Registry of logger factories, mirroring MetricsReporters. +/// +/// Built-in factories: "noop", "cerr", and (only when built with ICEBERG_SPDLOG) +/// "spdlog". When the "logger-impl" property is absent, the default is "spdlog" +/// if compiled in, otherwise "cerr" -- an intentional divergence from the metrics +/// registry's noop default (we want logs by default). +class ICEBERG_EXPORT Loggers { + public: + /// \brief Construct and initialize a logger from properties. + static Result> Load( + const std::unordered_map& properties); + + /// \brief Register a factory for \p logger_type (overwrites any existing). + static Status Register(std::string_view logger_type, LoggerFactory factory); + + /// \brief Load a logger from properties and install it as the default. + static Status LoadAndSetDefault( + const std::unordered_map& properties); +}; + +} // namespace iceberg diff --git a/src/iceberg/logging/meson.build b/src/iceberg/logging/meson.build index e26318368..f62cea55f 100644 --- a/src/iceberg/logging/meson.build +++ b/src/iceberg/logging/meson.build @@ -31,6 +31,7 @@ install_headers( 'log_level.h', 'log_macros.h', 'logger.h', + 'loggers.h', 'short_log_macros.h', ], subdir: 'iceberg/logging', diff --git a/src/iceberg/meson.build b/src/iceberg/meson.build index b247b2942..8bc227830 100644 --- a/src/iceberg/meson.build +++ b/src/iceberg/meson.build @@ -104,6 +104,7 @@ iceberg_sources = files( 'logging/cerr_logger.cc', 'logging/internal/spdlog_logger.cc', 'logging/logger.cc', + 'logging/loggers.cc', 'manifest/manifest_adapter.cc', 'manifest/manifest_entry.cc', 'manifest/manifest_filter_manager.cc', diff --git a/src/iceberg/test/CMakeLists.txt b/src/iceberg/test/CMakeLists.txt index 09872df9e..b0d57913b 100644 --- a/src/iceberg/test/CMakeLists.txt +++ b/src/iceberg/test/CMakeLists.txt @@ -106,6 +106,8 @@ add_iceberg_test(logging_test cerr_logger_test.cc log_level_test.cc logger_test.cc + loggers_test.cc + logging_end_to_end_test.cc macros_active_level_test.cc macros_test.cc spdlog_logger_test.cc) diff --git a/src/iceberg/test/loggers_test.cc b/src/iceberg/test/loggers_test.cc new file mode 100644 index 000000000..956580984 --- /dev/null +++ b/src/iceberg/test/loggers_test.cc @@ -0,0 +1,105 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +#include "iceberg/logging/loggers.h" + +#include +#include +#include + +#include + +#include "iceberg/logging/log_level.h" +#include "iceberg/logging/logger.h" +#include "iceberg/test/logging_test_helpers.h" + +namespace iceberg { + +TEST(LoggersTest, LoadDefaultReturnsNonNullNonNoop) { + auto result = Loggers::Load({}); + ASSERT_TRUE(result.has_value()); + ASSERT_NE(result.value(), nullptr); + // The default backend (spdlog or cerr) is a real sink, never the no-op. + EXPECT_FALSE(result.value()->IsNoop()); +} + +TEST(LoggersTest, LoadNoopByProperty) { + auto result = Loggers::Load({{std::string(kLoggerImpl), std::string(kLoggerTypeNoop)}}); + ASSERT_TRUE(result.has_value()); + EXPECT_TRUE(result.value()->IsNoop()); +} + +TEST(LoggersTest, LoadCerrByProperty) { + auto result = Loggers::Load({{std::string(kLoggerImpl), std::string(kLoggerTypeCerr)}}); + ASSERT_TRUE(result.has_value()); + ASSERT_NE(result.value(), nullptr); + EXPECT_FALSE(result.value()->IsNoop()); +} + +TEST(LoggersTest, UnknownTypeIsAnError) { + auto result = + Loggers::Load({{std::string(kLoggerImpl), std::string("does-not-exist")}}); + ASSERT_FALSE(result.has_value()); + EXPECT_EQ(result.error().kind, ErrorKind::kInvalidArgument); +} + +TEST(LoggersTest, RegisterCustomFactoryThenLoad) { + auto status = Loggers::Register("capturing", + [](const std::unordered_map&) + -> Result> { + return std::make_unique(); + }); + ASSERT_TRUE(status.has_value()); + + auto result = Loggers::Load({{std::string(kLoggerImpl), "capturing"}}); + ASSERT_TRUE(result.has_value()); + EXPECT_NE(dynamic_cast(result.value().get()), nullptr); +} + +TEST(LoggersTest, RegisterRejectsEmptyFactory) { + auto status = Loggers::Register("bad", LoggerFactory{}); + ASSERT_FALSE(status.has_value()); + EXPECT_EQ(status.error().kind, ErrorKind::kInvalidArgument); +} + +TEST(LoggersTest, LoadAndSetDefaultInstallsLogger) { + auto previous = GetDefaultLogger(); + auto status = Loggers::LoadAndSetDefault( + {{std::string(kLoggerImpl), std::string(kLoggerTypeNoop)}}); + ASSERT_TRUE(status.has_value()); + EXPECT_TRUE(GetDefaultLogger()->IsNoop()); + SetDefaultLogger(previous); // restore +} + +TEST(LoggersTest, LoadAppliesLevelProperty) { + auto result = Loggers::Load({{std::string(kLoggerImpl), std::string(kLoggerTypeCerr)}, + {std::string(kLevelProperty), std::string("error")}}); + ASSERT_TRUE(result.has_value()); + EXPECT_EQ(result.value()->level(), LogLevel::kError); +} + +TEST(LoggersTest, LoadRejectsInvalidLevelProperty) { + auto result = + Loggers::Load({{std::string(kLoggerImpl), std::string(kLoggerTypeCerr)}, + {std::string(kLevelProperty), std::string("not-a-level")}}); + ASSERT_FALSE(result.has_value()); + EXPECT_EQ(result.error().kind, ErrorKind::kInvalidArgument); +} + +} // namespace iceberg diff --git a/src/iceberg/test/logging_end_to_end_test.cc b/src/iceberg/test/logging_end_to_end_test.cc new file mode 100644 index 000000000..78f697794 --- /dev/null +++ b/src/iceberg/test/logging_end_to_end_test.cc @@ -0,0 +1,168 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +// End-to-end tests: exercise the public surface the way an application does -- +// configure/install a real backend via the registry, log through the LOG_* +// macros, and observe the actual output. The per-layer unit tests cover each +// piece in isolation against a fake; these cover the seams between them. + +// Internal/build-generated header is acceptable in a test TU (not installed). +#include +#include +#include +#include + +#include + +#include "iceberg/logging/cerr_logger.h" +#include "iceberg/logging/config.h" +#include "iceberg/logging/log_level.h" +#include "iceberg/logging/log_macros.h" +#include "iceberg/logging/logger.h" +#include "iceberg/logging/loggers.h" +#include "iceberg/test/logging_test_helpers.h" + +#ifdef ICEBERG_HAS_SPDLOG +# include +# include + +# include "iceberg/logging/internal/spdlog_logger.h" +#endif + +namespace iceberg { + +namespace { + +/// \brief RAII redirect of std::cerr to a stringstream for the test scope. +class CerrCapture { + public: + CerrCapture() : old_(std::cerr.rdbuf(buffer_.rdbuf())) {} + ~CerrCapture() { std::cerr.rdbuf(old_); } + std::string str() const { return buffer_.str(); } + + private: + std::ostringstream buffer_; + std::streambuf* old_; +}; + +} // namespace + +// Configure CerrLogger through the registry, install it as the process default, +// then log via a macro and observe the formatted line on std::cerr -- the full +// registry -> default-slot -> macro -> Emit -> backend -> output path. +TEST(LoggingEndToEndTest, ConfiguredCerrLoggerEmitsFormattedLineThroughMacro) { + ScopedDefaultLogger guard(GetDefaultLogger()); // save + restore the default + auto status = Loggers::LoadAndSetDefault( + {{std::string(kLoggerImpl), std::string(kLoggerTypeCerr)}}); + ASSERT_TRUE(status.has_value()); + + std::string out; + { + CerrCapture capture; + ICEBERG_LOG_WARN("u={}", 7); + out = capture.str(); + } + EXPECT_NE(out.find("warn"), std::string::npos); + EXPECT_NE(out.find("u=7"), std::string::npos); + EXPECT_NE(out.find("logging_end_to_end_test.cc"), std::string::npos); + EXPECT_EQ(out.back(), '\n'); +} + +// The level set on the installed default logger gates emission decided through +// the whole macro path (not just a direct ShouldLog() call). +TEST(LoggingEndToEndTest, InstalledLevelFiltersThroughFullMacroPath) { + ScopedDefaultLogger guard(GetDefaultLogger()); + auto status = Loggers::LoadAndSetDefault( + {{std::string(kLoggerImpl), std::string(kLoggerTypeCerr)}}); + ASSERT_TRUE(status.has_value()); + SetDefaultLevel(LogLevel::kError); + + { + CerrCapture capture; + ICEBERG_LOG_INFO("dropped {}", 1); + EXPECT_TRUE(capture.str().empty()); + } + { + CerrCapture capture; + ICEBERG_LOG_ERROR("kept {}", 2); + EXPECT_NE(capture.str().find("kept 2"), std::string::npos); + } +} + +// The "level" property set at configuration time gates emission through the full +// registry -> Initialize -> default-slot -> macro path. +TEST(LoggingEndToEndTest, ConfiguredLevelByPropertyFiltersThroughMacro) { + ScopedDefaultLogger guard(GetDefaultLogger()); + auto status = Loggers::LoadAndSetDefault( + {{std::string(kLoggerImpl), std::string(kLoggerTypeCerr)}, + {std::string(kLevelProperty), std::string("error")}}); + ASSERT_TRUE(status.has_value()); + + { + CerrCapture capture; + ICEBERG_LOG_INFO("dropped {}", 1); + EXPECT_TRUE(capture.str().empty()); + } + { + CerrCapture capture; + ICEBERG_LOG_ERROR("kept {}", 2); + EXPECT_NE(capture.str().find("kept 2"), std::string::npos); + } +} + +// The process default with no configuration is a real sink (never the no-op), +// and is the backend the build was compiled with: spdlog when ICEBERG_SPDLOG is +// ON, otherwise the std::cerr logger. +TEST(LoggingEndToEndTest, DefaultLoggerIsTheCompiledBackend) { + auto def = GetDefaultLogger(); + ASSERT_NE(def, nullptr); + EXPECT_FALSE(def->IsNoop()); +#ifdef ICEBERG_HAS_SPDLOG + EXPECT_NE(dynamic_cast(def.get()), nullptr); +#else + EXPECT_NE(dynamic_cast(def.get()), nullptr); +#endif +} + +#ifdef ICEBERG_HAS_SPDLOG +// The "spdlog" registry type resolves to the spdlog-backed sink by name. +TEST(LoggingEndToEndTest, SpdlogFactoryLoadsByName) { + auto result = + Loggers::Load({{std::string(kLoggerImpl), std::string(kLoggerTypeSpdlog)}}); + ASSERT_TRUE(result.has_value()); + ASSERT_NE(result.value(), nullptr); + EXPECT_FALSE(result.value()->IsNoop()); + EXPECT_NE(dynamic_cast(result.value().get()), nullptr); +} + +// A macro statement reaches a real spdlog sink: install a SpdLogger backed by an +// ostream sink as the default, log through the macro, and observe the output. +TEST(LoggingEndToEndTest, MacroLogsThroughRealSpdLogger) { + std::ostringstream out; + auto sink = std::make_shared(out); + auto spd = std::make_shared("e2e", sink); + ScopedDefaultLogger guard(std::make_shared(spd, LogLevel::kTrace)); + + ICEBERG_LOG_INFO("v={}", 9); + GetDefaultLogger()->Flush(); + EXPECT_NE(out.str().find("v=9"), std::string::npos); +} +#endif // ICEBERG_HAS_SPDLOG + +} // namespace iceberg diff --git a/src/iceberg/test/meson.build b/src/iceberg/test/meson.build index a3d1e3c50..867fd1a9b 100644 --- a/src/iceberg/test/meson.build +++ b/src/iceberg/test/meson.build @@ -67,6 +67,8 @@ iceberg_tests = { 'cerr_logger_test.cc', 'log_level_test.cc', 'logger_test.cc', + 'loggers_test.cc', + 'logging_end_to_end_test.cc', 'macros_active_level_test.cc', 'macros_test.cc', 'spdlog_logger_test.cc',