diff --git a/meson.build b/meson.build index 46446cd8d..46d7ab6ae 100644 --- a/meson.build +++ b/meson.build @@ -31,7 +31,9 @@ project( ) cpp = meson.get_compiler('cpp') -args = cpp.get_supported_arguments(['/bigobj']) +# /Zc:preprocessor: MSVC's conforming preprocessor, required for the __VA_OPT__ +# used by the logging macros. get_supported_arguments drops it on non-MSVC. +args = cpp.get_supported_arguments(['/bigobj', '/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..6af862f00 100644 --- a/src/iceberg/logging/logger.h +++ b/src/iceberg/logging/logger.h @@ -371,3 +371,179 @@ 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 (...) { \ + ::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 default logger ONCE and uses the 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::GetDefaultLogger(); \ + 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/test/CMakeLists.txt b/src/iceberg/test/CMakeLists.txt index fcbc22126..32aac4dbd 100644 --- a/src/iceberg/test/CMakeLists.txt +++ b/src/iceberg/test/CMakeLists.txt @@ -64,7 +64,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}) @@ -106,7 +108,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 ba0f6230d..793dfef5d 100644 --- a/src/iceberg/test/meson.build +++ b/src/iceberg/test/meson.build @@ -66,6 +66,8 @@ iceberg_tests = { 'cerr_logger_test.cc', 'log_level_test.cc', 'logger_test.cc', + 'macros_active_level_test.cc', + 'macros_test.cc', ), }, 'expression_test': {