diff --git a/CMakeLists.txt b/CMakeLists.txt index 41b3772..d2e7385 100644 --- a/CMakeLists.txt +++ b/CMakeLists.txt @@ -46,6 +46,22 @@ option( "Build the S3 parquet benchmark (requires aws-sdk-cpp; NOT a cuCascade dependency)" OFF) +# Compile-time floor for the CUCASCADE_LOG_* macros, as the underlying value of +# a cucascade::log::level (0 = trace ... 6 = off). The default keeps every call +# site and leaves filtering to the runtime threshold; raising it strips the +# cheaper levels from the binary entirely. +# +# Propagated PUBLIC because consumers expand the same macros. That is safe even +# if a consumer overrides it: the definition is read only inside the macros, not +# inside any inline function body or type, so a mismatch prunes call sites +# differently rather than violating the ODR. +set(CUCASCADE_MIN_LOG_LEVEL + "0" + CACHE + STRING + "Compile out CUCASCADE_LOG_* call sites below this level (0=trace, 1=debug, 2=info, 3=warn, 4=error, 5=fatal, 6=off)" +) + # Swappable third-party backends for the io layer. The io code was ported from a # codebase with its own vendored dependencies. These knobs let an embedding host # (e.g. sirius) reuse the copies it already links instead of the @@ -340,6 +356,7 @@ if(NOT CUCASCADE_TOPOLOGY_ONLY) add_subdirectory(src/cuda) endif() add_subdirectory(src/memory) +add_subdirectory(src/log) if(NOT CUCASCADE_TOPOLOGY_ONLY) add_subdirectory(src/data) endif() @@ -356,6 +373,13 @@ set(CUCASCADE_PUBLIC_INCLUDE_DIRS $ $) +# Carried by every target that exposes include/cucascade/log/logging.hpp. The +# object libraries need it for cuCascade's own call sites; the installable +# static/shared targets are assembled from $ rather than by +# linking, so PUBLIC usage requirements do not flow across and must be repeated. +set(CUCASCADE_PUBLIC_COMPILE_DEFS + CUCASCADE_MIN_LOG_LEVEL=${CUCASCADE_MIN_LOG_LEVEL}) + if(NOT CUCASCADE_TOPOLOGY_ONLY) set(CUCASCADE_PUBLIC_LINK_LIBS rmm::rmm CUDA::cudart_static Threads::Threads Numa::Numa) @@ -363,6 +387,8 @@ if(NOT CUCASCADE_TOPOLOGY_ONLY) # Set include directories for the object library target_include_directories(cucascade_objects PUBLIC ${CUCASCADE_PUBLIC_INCLUDE_DIRS}) + target_compile_definitions(cucascade_objects + PUBLIC ${CUCASCADE_PUBLIC_COMPILE_DEFS}) # Link dependencies to object library target_link_libraries(cucascade_objects PUBLIC ${CUCASCADE_PUBLIC_LINK_LIBS}) @@ -424,6 +450,8 @@ endif() target_include_directories(cucascade_topology_discovery_objects PUBLIC ${CUCASCADE_PUBLIC_INCLUDE_DIRS}) +target_compile_definitions(cucascade_topology_discovery_objects + PUBLIC ${CUCASCADE_PUBLIC_COMPILE_DEFS}) target_link_libraries(cucascade_topology_discovery_objects PUBLIC CUDA::nvml_static rmm::rmm) target_compile_features(cucascade_topology_discovery_objects PUBLIC cxx_std_20) @@ -446,6 +474,8 @@ if(CUCASCADE_BUILD_STATIC_LIBS) PRIVATE CUDA::nvml_static rmm::rmm) target_include_directories(cucascade_topology_discovery_static PUBLIC ${CUCASCADE_PUBLIC_INCLUDE_DIRS}) + target_compile_definitions(cucascade_topology_discovery_static + PUBLIC ${CUCASCADE_PUBLIC_COMPILE_DEFS}) target_compile_features(cucascade_topology_discovery_static PUBLIC cxx_std_20) # Work around a bug in libnvidia-ml.so - it attempts to call back into the # stub library (https://nvbugspro.nvidia.com/bug/6174166) @@ -463,6 +493,8 @@ if(CUCASCADE_BUILD_STATIC_LIBS) target_include_directories(cucascade_static PUBLIC ${CUCASCADE_PUBLIC_INCLUDE_DIRS}) + target_compile_definitions(cucascade_static + PUBLIC ${CUCASCADE_PUBLIC_COMPILE_DEFS}) target_link_libraries( cucascade_static PUBLIC ${CUCASCADE_PUBLIC_LINK_LIBS} cucascade_topology_discovery_static) @@ -524,6 +556,8 @@ if(CUCASCADE_BUILD_SHARED_LIBS) PRIVATE CUDA::nvml_static rmm::rmm) target_include_directories(cucascade_topology_discovery_shared PUBLIC ${CUCASCADE_PUBLIC_INCLUDE_DIRS}) + target_compile_definitions(cucascade_topology_discovery_shared + PUBLIC ${CUCASCADE_PUBLIC_COMPILE_DEFS}) target_compile_features(cucascade_topology_discovery_shared PUBLIC cxx_std_20) # Work around a bug in libnvidia-ml.so - it attempts to call back into the # stub library (https://nvbugspro.nvidia.com/bug/6174166) @@ -539,6 +573,8 @@ if(CUCASCADE_BUILD_SHARED_LIBS) target_include_directories(cucascade_shared PUBLIC ${CUCASCADE_PUBLIC_INCLUDE_DIRS}) + target_compile_definitions(cucascade_shared + PUBLIC ${CUCASCADE_PUBLIC_COMPILE_DEFS}) target_link_libraries( cucascade_shared PUBLIC ${CUCASCADE_PUBLIC_LINK_LIBS} cucascade_topology_discovery_shared) diff --git a/include/cucascade/log/logging.hpp b/include/cucascade/log/logging.hpp index 5a9f6d9..4779437 100644 --- a/include/cucascade/log/logging.hpp +++ b/include/cucascade/log/logging.hpp @@ -18,26 +18,244 @@ #pragma once -// Logging is compiled out: the CUCASCADE_LOG_* macros are no-ops. The -// argument expressions are placed in an unevaluated (sizeof) context so they -// are type-checked and their operands count as used (no -Wunused-variable -// fallout at call sites), but they are never evaluated at runtime. +/** + * @file + * @brief std::format-based logging delivered to a host-installed sink. + * + * cuCascade ships no logging backend; an embedding host installs a @ref cucascade::log::sink_fn + * via @ref cucascade::log::set_sink. With no sink installed a call site costs one relaxed atomic + * load and a never-taken branch, so logging is silent and free by default. + * + * @code + * void to_host_logger(void* user_data, cucascade::log::record const& rec) noexcept + * { + * static_cast(user_data)->write(rec.file, rec.line, + * std::string_view{rec.message, rec.message_len}); + * } + * cucascade::log::set_sink(&to_host_logger, &my_logger, cucascade::log::level::debug); + * @endcode + */ + +#include +#include +#include +#include +#include +#include + +/// Forces default visibility on the process-wide sink state. Without it a `-fvisibility=hidden` +/// build gives each shared object its own sink slot, so a host's @ref cucascade::log::set_sink +/// would be invisible to cuCascade's own call sites. +#if defined(__GNUC__) || defined(__clang__) +#define CUCASCADE_LOG_SHARED_STATE __attribute__((visibility("default"))) +#else +#define CUCASCADE_LOG_SHARED_STATE +#endif + +namespace cucascade::log { +inline namespace v1 { + +/// Record severity, ordered ascending. +enum class level : int { + trace = 0, + debug, + info, + warn, + error, + fatal, ///< Severity only; cuCascade never aborts on its own behalf. + off, ///< Not a message level; pass to @ref set_min_level to mute everything. +}; + +/// @return Static, human-readable name of @p lvl, e.g. `"WARN"`. +[[nodiscard]] inline char const* to_string(level lvl) noexcept +{ + switch (lvl) { + case level::trace: return "TRACE"; + case level::debug: return "DEBUG"; + case level::info: return "INFO"; + case level::warn: return "WARN"; + case level::error: return "ERROR"; + case level::fatal: return "FATAL"; + case level::off: return "OFF"; + } + return "?"; +} + +/// A formatted log record as passed to a sink. +/// +/// A POD of pointers and integers, so it can cross into separately-compiled host code without +/// depending on standard library layout choices. All pointers are borrowed for the duration of +/// the sink call; @ref file and @ref function have static storage duration, @ref message does not. +/// +/// @note Fields are only ever appended. @ref struct_size is the producer's `sizeof(record)`; a +/// sink must check that it covers a field before reading one it was not compiled against. +struct record { + std::size_t struct_size; ///< `sizeof(record)` as seen by the producer. + level lvl; + std::uint_least32_t line; + std::uint_least32_t column; + char const* message; ///< Not NUL-terminated; pair with @ref message_len. + std::size_t message_len; + char const* file; ///< Originating call site, not the sink. + char const* function; + std::uint64_t thread_id; ///< Linux `gettid()`; 0 where unavailable. + std::int64_t unix_time_ns; ///< Stamped when formatted, not when delivered. +}; + +/// Host-installed destination for a log record. +/// +/// @param user_data Whatever was passed to @ref set_sink; must outlive the last log call. +/// @note May throw — the caller catches and drops the record — but a throwing sink formats +/// messages nobody sees. +using sink_fn = void (*)(void* user_data, record const&); + +namespace detail { + +/// Immutable once published, so a reader never sees a mismatched fn/user_data pair. +struct sink_state { + sink_fn fn; + void* user_data; +}; + +CUCASCADE_LOG_SHARED_STATE inline std::atomic& sink_slot() noexcept +{ + static std::atomic slot{nullptr}; + return slot; +} + +CUCASCADE_LOG_SHARED_STATE inline std::atomic& min_level_slot() noexcept +{ + static std::atomic slot{level::info}; + return slot; +} + +/// Publishes a sink pair, or null for a null @p fn. +/// +/// @note The result is never freed: a concurrent @ref vemit may still hold the previous pointer. +/// The first install is served from a static, so the usual single-install case neither +/// allocates nor reports a leak. +sink_state const* publish_sink(sink_fn fn, void* user_data) noexcept; -namespace cucascade::log::detail { +/// Formats and delivers one record. Never throws: these macros run in destructors and noexcept +/// paths, where an escaping exception is `std::terminate`. +void vemit(level lvl, + std::source_location const& location, + std::string_view fmt, + std::format_args args) noexcept; -/// Declared only — used strictly inside an unevaluated context. +/// Type-erases the arguments, so a call site expands to one `make_format_args` and one +/// non-template call rather than a fresh instantiation per argument pack. +template +void emit(level lvl, + std::source_location const& location, + std::format_string fmt, + Args&&... args) noexcept +{ + vemit(lvl, location, fmt.get(), std::make_format_args(args...)); +} + +/// Declared only; used in an unevaluated context to keep compiled-out arguments type-checked. template int ignore(Args&&...) noexcept; -} // namespace cucascade::log::detail +} // namespace detail + +/// Installs the process-wide sink and sets the severity threshold. +/// +/// Intended to be called once during host start-up. @p fn and whatever @p user_data points at +/// must stay valid while any cuCascade thread can log; see @ref clear_sink for teardown. +/// +/// @note Always writes the threshold, so it overrides an earlier @ref set_min_level. +inline void set_sink(sink_fn fn, void* user_data = nullptr, level min_level = level::info) noexcept +{ + auto const* const state = detail::publish_sink(fn, user_data); + detail::min_level_slot().store(min_level, std::memory_order_relaxed); + detail::sink_slot().store(state, std::memory_order_release); +} + +/// Removes the installed sink. Call before destroying whatever `user_data` pointed at. +inline void clear_sink() noexcept { detail::sink_slot().store(nullptr, std::memory_order_release); } + +/// Sets the severity threshold without touching the installed sink. +/// +/// Mirror the host logger's own level here so filtering happens once, in @ref enabled, rather +/// than formatting records the backend will discard. +inline void set_min_level(level min_level) noexcept +{ + detail::min_level_slot().store(min_level, std::memory_order_relaxed); +} + +/// @return The installed sink, or null if none. +[[nodiscard]] inline sink_fn sink() noexcept +{ + auto const* const state = detail::sink_slot().load(std::memory_order_acquire); + return state != nullptr ? state->fn : nullptr; +} + +/// @return The `user_data` passed to @ref set_sink, or null if no sink is installed. +[[nodiscard]] inline void* sink_user_data() noexcept +{ + auto const* const state = detail::sink_slot().load(std::memory_order_acquire); + return state != nullptr ? state->user_data : nullptr; +} + +/// @return The current severity threshold. +[[nodiscard]] inline level min_level() noexcept +{ + return detail::min_level_slot().load(std::memory_order_relaxed); +} + +/// @return Whether a record at @p lvl would reach a sink. +/// @note The guard on every call site, so it stays one relaxed load and two integer compares. +[[nodiscard]] inline bool enabled(level lvl) noexcept +{ + return detail::sink_slot().load(std::memory_order_relaxed) != nullptr && lvl >= min_level(); +} + +/// Built-in sink writing ` [LEVEL] file:line: message` to stderr. Ignores +/// @p user_data. Not installed by default; see @ref use_stderr_sink. +void stderr_sink(void* user_data, record const& rec) noexcept; + +/// Routes records to @ref stderr_sink, for debugging cuCascade standalone. An embedding host +/// should install its own sink instead. +inline void use_stderr_sink(level min_level = level::info) noexcept +{ + set_sink(&stderr_sink, nullptr, min_level); +} + +} // namespace v1 +} // namespace cucascade::log // clang-format off + +/// Compile-time severity floor, as the underlying value of a cucascade::log::level (0 = trace +/// ... 6 = off). Call sites below it are removed by the preprocessor, arguments included. +/// +/// @note Read only inside the macros below, never in an inline function body or a type, so the +/// library and a consumer may define it differently without an ODR violation. +#ifndef CUCASCADE_MIN_LOG_LEVEL +#define CUCASCADE_MIN_LOG_LEVEL 0 +#endif + +/// Discards the arguments in an unevaluated context: still type-checked and "used", never run. #define CUCASCADE_LOG_NOOP(...) static_cast(sizeof(::cucascade::log::detail::ignore(__VA_ARGS__))) -#define CUCASCADE_LOG_TRACE(...) CUCASCADE_LOG_NOOP(__VA_ARGS__) -#define CUCASCADE_LOG_DEBUG(...) CUCASCADE_LOG_NOOP(__VA_ARGS__) -#define CUCASCADE_LOG_INFO(...) CUCASCADE_LOG_NOOP(__VA_ARGS__) -#define CUCASCADE_LOG_WARN(...) CUCASCADE_LOG_NOOP(__VA_ARGS__) -#define CUCASCADE_LOG_ERROR(...) CUCASCADE_LOG_NOOP(__VA_ARGS__) -#define CUCASCADE_LOG_FATAL(...) CUCASCADE_LOG_NOOP(__VA_ARGS__) +#define CUCASCADE_LOG_IMPL(lvl, ...) \ + do { \ + if constexpr (static_cast(lvl) >= (CUCASCADE_MIN_LOG_LEVEL)) { \ + if (::cucascade::log::enabled(lvl)) { \ + ::cucascade::log::detail::emit( \ + (lvl), std::source_location::current(), __VA_ARGS__); \ + } \ + } else { \ + CUCASCADE_LOG_NOOP(__VA_ARGS__); \ + } \ + } while (false) + +#define CUCASCADE_LOG_TRACE(...) CUCASCADE_LOG_IMPL(::cucascade::log::level::trace, __VA_ARGS__) +#define CUCASCADE_LOG_DEBUG(...) CUCASCADE_LOG_IMPL(::cucascade::log::level::debug, __VA_ARGS__) +#define CUCASCADE_LOG_INFO(...) CUCASCADE_LOG_IMPL(::cucascade::log::level::info, __VA_ARGS__) +#define CUCASCADE_LOG_WARN(...) CUCASCADE_LOG_IMPL(::cucascade::log::level::warn, __VA_ARGS__) +#define CUCASCADE_LOG_ERROR(...) CUCASCADE_LOG_IMPL(::cucascade::log::level::error, __VA_ARGS__) +#define CUCASCADE_LOG_FATAL(...) CUCASCADE_LOG_IMPL(::cucascade::log::level::fatal, __VA_ARGS__) // clang-format on diff --git a/src/log/CMakeLists.txt b/src/log/CMakeLists.txt new file mode 100644 index 0000000..9ecb33d --- /dev/null +++ b/src/log/CMakeLists.txt @@ -0,0 +1,28 @@ +# ============================================================================= +# SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. +# All rights reserved. SPDX-License-Identifier: Apache-2.0 +# +# Licensed 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. +# ============================================================================= + +# Record delivery (vemit), sink publication and the built-in stderr sink. Only +# the level check and the sink slot stay inline in +# include/cucascade/log/logging.hpp, so the hot path remains header-only while +# , and stay out of every translation unit that logs. +# +# Logging therefore requires linking cuCascade, and is unavailable in a +# topology-only build, which does not produce cucascade_objects. +if(TARGET cucascade_objects) + target_sources(cucascade_objects + PRIVATE ${CMAKE_CURRENT_SOURCE_DIR}/logging.cpp) +endif() diff --git a/src/log/logging.cpp b/src/log/logging.cpp new file mode 100644 index 0000000..401c1a8 --- /dev/null +++ b/src/log/logging.cpp @@ -0,0 +1,142 @@ +/* + * SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. + * SPDX-License-Identifier: Apache-2.0 + * + * + * Licensed 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 + +#include +#include +#include +#include +#include +#include +#include +#include + +namespace cucascade::log { +inline namespace v1 { + +namespace { + +/// Cached: `gettid` is a syscall and the id is fixed for the thread's lifetime. +[[nodiscard]] std::uint64_t current_thread_id() noexcept +{ + static thread_local std::uint64_t const tid{static_cast(::syscall(SYS_gettid))}; + return tid; +} + +[[nodiscard]] std::int64_t current_unix_time_ns() noexcept +{ + return std::chrono::duration_cast( + std::chrono::system_clock::now().time_since_epoch()) + .count(); +} + +} // namespace + +namespace detail { + +sink_state const* publish_sink(sink_fn fn, void* user_data) noexcept +{ + if (fn == nullptr) { return nullptr; } + + static sink_state first{}; + static std::atomic first_taken{false}; + + bool expected = false; + if (first_taken.compare_exchange_strong(expected, true, std::memory_order_relaxed)) { + // Not yet reachable by any reader: set_sink publishes the pointer afterwards. + first = sink_state{fn, user_data}; + return &first; + } + // Failing to allocate a logger is not worth throwing from a noexcept path; the caller stores + // null and logging stays silent. + return new (std::nothrow) sink_state{fn, user_data}; +} + +void vemit(level lvl, + std::source_location const& location, + std::string_view fmt, + std::format_args args) noexcept +{ + // Re-read rather than trusting enabled(): set_sink may have raced in between. Formatting + // happens after the check, so losing that race costs nothing. + auto const* const state = sink_slot().load(std::memory_order_acquire); + if (state == nullptr) { return; } + + try { + auto const message = std::vformat(fmt, args); + + record const rec{ + .struct_size = sizeof(record), + .lvl = lvl, + .line = location.line(), + .column = location.column(), + .message = message.data(), + .message_len = message.size(), + .file = location.file_name(), + .function = location.function_name(), + .thread_id = current_thread_id(), + .unix_time_ns = current_unix_time_ns(), + }; + + state->fn(state->user_data, rec); + } catch (...) { + // std::vformat allocates and the sink is host code; neither may escape into a destructor or + // noexcept caller. Reporting the failure would need the sink that just failed, so the record + // is dropped. + } +} + +} // namespace detail + +void stderr_sink(void*, record const& rec) noexcept +{ + try { + auto const secs = static_cast(rec.unix_time_ns / 1'000'000'000); + auto const usecs = static_cast((rec.unix_time_ns % 1'000'000'000) / 1'000); + + std::array stamp{}; + std::tm utc{}; + bool formatted = false; + if (::gmtime_r(&secs, &utc) != nullptr) { + formatted = std::strftime(stamp.data(), stamp.size(), "%Y-%m-%dT%H:%M:%S", &utc) != 0; + } + // Keep the line shape stable when the clock is unrepresentable, so a parser sees a bogus + // timestamp rather than a missing column. + char const* const stamp_text = formatted ? stamp.data() : "0000-00-00T00:00:00"; + + auto const line = std::format("{}.{:06}Z [{:<5}] {} {}:{}: {}\n", + stamp_text, + usecs, + to_string(rec.lvl), + rec.thread_id, + rec.file, + rec.line, + std::string_view{rec.message, rec.message_len}); + + // One fwrite so concurrent loggers interleave by line rather than mid-line. + [[maybe_unused]] auto const written = std::fwrite(line.data(), 1, line.size(), stderr); + } catch (...) { // A sink that throws is worse than a lost line. + } +} + +} // namespace v1 +} // namespace cucascade::log diff --git a/src/log/stderr_sink.cpp b/src/log/stderr_sink.cpp new file mode 100644 index 0000000..e56f9be --- /dev/null +++ b/src/log/stderr_sink.cpp @@ -0,0 +1,67 @@ +/* + * SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. + * SPDX-License-Identifier: Apache-2.0 + * + * + * Licensed 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. + */ + +// The built-in stderr sink, kept out of the header so that , +// and are not pulled into every translation unit that merely logs. + +#include + +#include +#include +#include +#include +#include +#include +#include + +namespace cucascade::log { +inline namespace v1 { + +void stderr_sink(void*, record const& rec) noexcept +{ + try { + auto const secs = static_cast(rec.unix_time_ns / 1'000'000'000); + auto const usecs = static_cast((rec.unix_time_ns % 1'000'000'000) / 1'000); + + std::array stamp{}; + std::tm utc{}; + bool formatted = false; + if (::gmtime_r(&secs, &utc) != nullptr) { + formatted = std::strftime(stamp.data(), stamp.size(), "%Y-%m-%dT%H:%M:%S", &utc) != 0; + } + // Keep the line shape stable when the clock is unrepresentable, so a log + // parser sees a bogus timestamp rather than a missing column. + char const* const stamp_text = formatted ? stamp.data() : "0000-00-00T00:00:00"; + + std::ostringstream line; + line.imbue(std::locale::classic()); + line << stamp_text << '.' << std::setfill('0') << std::setw(6) << usecs << "Z [" + << std::setfill(' ') << std::setw(5) << to_string(rec.lvl) << "] " << rec.thread_id << ' ' + << rec.file << ':' << rec.line << ": " << std::string_view{rec.message, rec.message_len} + << '\n'; + auto const text = std::move(line).str(); + + // One fwrite so concurrent loggers interleave by line rather than mid-line; + // stderr is unbuffered, so this is a single write(). + [[maybe_unused]] auto const written = std::fwrite(text.data(), 1, text.size(), stderr); + } catch (...) { // A sink that throws is worse than a lost line. + } +} + +} // namespace v1 +} // namespace cucascade::log diff --git a/test/CMakeLists.txt b/test/CMakeLists.txt index 03de372..69cb20a 100644 --- a/test/CMakeLists.txt +++ b/test/CMakeLists.txt @@ -38,6 +38,8 @@ if(NOT CUCASCADE_TOPOLOGY_ONLY) data/test_data_repository_manager.cpp data/test_disk_io_backend.cpp data/test_io_worker.cpp + # Logging tests + log/test_logging.cpp # Main test runner unittest.cpp) set_target_properties(cucascade_tests PROPERTIES CUDA_STANDARD 20 diff --git a/test/log/test_logging.cpp b/test/log/test_logging.cpp new file mode 100644 index 0000000..e1df056 --- /dev/null +++ b/test/log/test_logging.cpp @@ -0,0 +1,364 @@ +/* + * SPDX-FileCopyrightText: Copyright (c) 2026 NVIDIA CORPORATION & AFFILIATES. All rights reserved. + * SPDX-License-Identifier: Apache-2.0 + * + * + * Licensed 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. + */ + +// These cover the behaviours of the logging layer that fail *silently* when +// they regress -- a dropped record, a sink that never gets installed, an +// argument evaluated when the call site was supposed to be free. A broken +// logger does not fail a build or throw; it just goes quiet, so the cost of not +// pinning this down is discovering months later that nothing was ever logged. + +#include + +#include + +#include +#include +#include +#include +#include +#include +#include +#include + +namespace { + +using cucascade::log::level; +using cucascade::log::record; + +/// Everything a sink saw, so a test can assert on it after the fact. +struct capture { + std::vector messages; + level last_level{level::off}; + std::string last_file; + std::string last_function; + std::uint_least32_t last_line{0}; + std::size_t last_struct_size{0}; + std::uint64_t last_thread_id{0}; + std::int64_t last_unix_time_ns{0}; + void* observed_user_data{nullptr}; +}; + +void capture_sink(void* user_data, record const& rec) +{ + auto* const captured = static_cast(user_data); + captured->observed_user_data = user_data; + captured->last_level = rec.lvl; + captured->last_file = rec.file; + captured->last_function = rec.function; + captured->last_line = rec.line; + captured->last_struct_size = rec.struct_size; + captured->last_thread_id = rec.thread_id; + captured->last_unix_time_ns = rec.unix_time_ns; + captured->messages.emplace_back(rec.message, rec.message_len); +} + +void throwing_sink(void*, record const&) { throw std::runtime_error{"sink failure"}; } + +/// Counts records under a lock, for the concurrency check. +struct counting_capture { + std::mutex mutex; + std::size_t count{0}; +}; + +void counting_sink(void* user_data, record const&) +{ + auto* const counter = static_cast(user_data); + std::lock_guard const lock{counter->mutex}; + ++counter->count; +} + +/// The sink slot is process-wide state, so every test here has to put it back +/// or it leaks into whatever Catch2 runs next. +struct sink_guard { + sink_guard() = default; + sink_guard(sink_guard const&) = delete; + sink_guard& operator=(sink_guard const&) = delete; + ~sink_guard() + { + cucascade::log::clear_sink(); + cucascade::log::set_min_level(level::info); + } +}; + +} // namespace + +TEST_CASE("logging is silent until a sink is installed", "[log]") +{ + sink_guard const guard; + cucascade::log::clear_sink(); + + CHECK(cucascade::log::sink() == nullptr); + CHECK(cucascade::log::sink_user_data() == nullptr); + // Even the most severe level is disabled: "no sink" is the gate, not the level. + CHECK_FALSE(cucascade::log::enabled(level::fatal)); + // The macros are statements, not expressions, so they need a lambda here. + CHECK_NOTHROW([] { CUCASCADE_LOG_FATAL("dropped {}", 1); }()); +} + +TEST_CASE("an installed sink receives the formatted record and its call site", "[log]") +{ + sink_guard const guard; + capture captured; + cucascade::log::set_sink(&capture_sink, &captured, level::trace); + + auto const expected_line = static_cast(__LINE__) + 1; + CUCASCADE_LOG_WARN("value {} and {}", 42, "text"); + + REQUIRE(captured.messages.size() == 1); + CHECK(captured.messages.front() == "value 42 and text"); + CHECK(captured.last_level == level::warn); + CHECK(captured.last_line == expected_line); + CHECK(std::string_view{captured.last_file}.find("test_logging.cpp") != std::string_view::npos); + CHECK_FALSE(captured.last_function.empty()); + // struct_size is the forward-compat handshake: it must be this build's size. + CHECK(captured.last_struct_size == sizeof(record)); + CHECK(captured.last_thread_id != 0); + CHECK(captured.last_unix_time_ns > 0); +} + +TEST_CASE("user_data is handed back to the sink unchanged", "[log]") +{ + sink_guard const guard; + capture first; + capture second; + + cucascade::log::set_sink(&capture_sink, &first, level::trace); + CHECK(cucascade::log::sink_user_data() == &first); + CUCASCADE_LOG_INFO("to first"); + CHECK(first.observed_user_data == &first); + + // Swapping must move the callback and its context together. + cucascade::log::set_sink(&capture_sink, &second, level::trace); + CHECK(cucascade::log::sink_user_data() == &second); + CUCASCADE_LOG_INFO("to second"); + + CHECK(first.messages.size() == 1); + CHECK(second.messages.size() == 1); + CHECK(second.observed_user_data == &second); +} + +TEST_CASE("records below the threshold are dropped", "[log]") +{ + sink_guard const guard; + capture captured; + cucascade::log::set_sink(&capture_sink, &captured, level::warn); + + CHECK_FALSE(cucascade::log::enabled(level::info)); + CHECK(cucascade::log::enabled(level::warn)); + + CUCASCADE_LOG_DEBUG("hidden"); + CUCASCADE_LOG_INFO("hidden"); + CUCASCADE_LOG_WARN("shown"); + CUCASCADE_LOG_ERROR("shown too"); + + CHECK(captured.messages == std::vector{"shown", "shown too"}); +} + +TEST_CASE("set_min_level retunes the threshold without disturbing the sink", "[log]") +{ + sink_guard const guard; + capture captured; + cucascade::log::set_sink(&capture_sink, &captured, level::trace); + + cucascade::log::set_min_level(level::error); + CHECK(cucascade::log::min_level() == level::error); + CHECK(cucascade::log::sink() == &capture_sink); + CHECK(cucascade::log::sink_user_data() == &captured); + + CUCASCADE_LOG_WARN("hidden"); + CUCASCADE_LOG_ERROR("shown"); + CHECK(captured.messages == std::vector{"shown"}); +} + +TEST_CASE("level::off mutes every severity", "[log]") +{ + sink_guard const guard; + capture captured; + cucascade::log::set_sink(&capture_sink, &captured, level::off); + + CUCASCADE_LOG_TRACE("hidden"); + CUCASCADE_LOG_FATAL("hidden"); + + CHECK_FALSE(cucascade::log::enabled(level::fatal)); + CHECK(captured.messages.empty()); +} + +TEST_CASE("arguments are not evaluated for a filtered record", "[log]") +{ + sink_guard const guard; + capture captured; + cucascade::log::set_sink(&capture_sink, &captured, level::error); + + int evaluations = 0; + auto const counted = [&evaluations]() { + ++evaluations; + return 1; + }; + + // The level check guards the whole expression, so a costly argument -- a + // stringify, a device query -- must not run when the record is dropped. + CUCASCADE_LOG_INFO("{}", counted()); + CHECK(evaluations == 0); + + CUCASCADE_LOG_ERROR("{}", counted()); + CHECK(evaluations == 1); +} + +TEST_CASE("format strings behave like std::format", "[log]") +{ + sink_guard const guard; + capture captured; + cucascade::log::set_sink(&capture_sink, &captured, level::trace); + + // Too few arguments or a bad format spec are compile errors, so they cannot be + // exercised here -- that is the point of using std::format_string. + + SECTION("surplus arguments are ignored, as std::format allows") + { + CUCASCADE_LOG_INFO("only {}", 1, 2); + REQUIRE(captured.messages.size() == 1); + CHECK(captured.messages.front() == "only 1"); + } + + SECTION("a message with no placeholders passes through") + { + CUCASCADE_LOG_INFO("nothing to substitute"); + REQUIRE(captured.messages.size() == 1); + CHECK(captured.messages.front() == "nothing to substitute"); + } + + SECTION("format specs are honoured") + { + CUCASCADE_LOG_INFO("{:.2f} {:#x} {:>4}", 3.14159, 255, "ab"); + REQUIRE(captured.messages.size() == 1); + CHECK(captured.messages.front() == "3.14 0xff ab"); + } + + SECTION("formatting is locale-independent") + { + CUCASCADE_LOG_INFO("{}", 1048576); + REQUIRE(captured.messages.size() == 1); + CHECK(captured.messages.front() == "1048576"); + } +} + +TEST_CASE("a throwing sink never propagates into the call site", "[log]") +{ + sink_guard const guard; + cucascade::log::set_sink(&throwing_sink, nullptr, level::trace); + + CHECK_NOTHROW([] { CUCASCADE_LOG_ERROR("boom {}", 1); }()); + + // The case that actually matters: these macros are used in destructors and + // noexcept functions, where an escaping exception is std::terminate. + auto const from_noexcept = []() noexcept { CUCASCADE_LOG_ERROR("from a noexcept context"); }; + CHECK_NOTHROW(from_noexcept()); +} + +TEST_CASE("clear_sink stops delivery", "[log]") +{ + sink_guard const guard; + capture captured; + cucascade::log::set_sink(&capture_sink, &captured, level::trace); + CUCASCADE_LOG_INFO("delivered"); + + cucascade::log::clear_sink(); + CUCASCADE_LOG_INFO("after clear"); + + CHECK(cucascade::log::sink() == nullptr); + CHECK(captured.messages == std::vector{"delivered"}); +} + +TEST_CASE("use_stderr_sink installs the built-in sink", "[log]") +{ + sink_guard const guard; + cucascade::log::use_stderr_sink(level::error); + + // Only the wiring is checked -- emitting here would pollute the test output. + CHECK(cucascade::log::sink() == &cucascade::log::stderr_sink); + CHECK(cucascade::log::min_level() == level::error); +} + +TEST_CASE("to_string names every level", "[log]") +{ + CHECK(std::string_view{cucascade::log::to_string(level::trace)} == "TRACE"); + CHECK(std::string_view{cucascade::log::to_string(level::debug)} == "DEBUG"); + CHECK(std::string_view{cucascade::log::to_string(level::info)} == "INFO"); + CHECK(std::string_view{cucascade::log::to_string(level::warn)} == "WARN"); + CHECK(std::string_view{cucascade::log::to_string(level::error)} == "ERROR"); + CHECK(std::string_view{cucascade::log::to_string(level::fatal)} == "FATAL"); + CHECK(std::string_view{cucascade::log::to_string(level::off)} == "OFF"); +} + +TEST_CASE("concurrent logging delivers every record", "[log]") +{ + sink_guard const guard; + counting_capture counter; + cucascade::log::set_sink(&counting_sink, &counter, level::trace); + + constexpr std::size_t thread_count = 8; + constexpr std::size_t records_per_thread = 128; + + std::vector workers; + workers.reserve(thread_count); + for (std::size_t t = 0; t < thread_count; ++t) { + workers.emplace_back([t]() { + for (std::size_t i = 0; i < records_per_thread; ++i) { + CUCASCADE_LOG_INFO("thread {} record {}", t, i); + } + }); + } + for (auto& worker : workers) { + worker.join(); + } + + std::lock_guard const lock{counter.mutex}; + CHECK(counter.count == thread_count * records_per_thread); +} + +// --------------------------------------------------------------------------- +// Compile-time pruning. CUCASCADE_MIN_LOG_LEVEL is read where the macro +// expands, so redefining it here changes only the call sites below. +// --------------------------------------------------------------------------- + +#undef CUCASCADE_MIN_LOG_LEVEL +#define CUCASCADE_MIN_LOG_LEVEL 4 // level::error + +TEST_CASE("CUCASCADE_MIN_LOG_LEVEL removes call sites at compile time", "[log]") +{ + sink_guard const guard; + capture captured; + cucascade::log::set_sink(&capture_sink, &captured, level::trace); + + int evaluations = 0; + auto const counted = [&evaluations]() { + ++evaluations; + return 7; + }; + + // Below the floor: gone from the binary, and its arguments never run even + // though the runtime threshold would have admitted them. + CUCASCADE_LOG_WARN("compiled out {}", counted()); + CHECK(captured.messages.empty()); + CHECK(evaluations == 0); + + CUCASCADE_LOG_ERROR("kept {}", counted()); + REQUIRE(captured.messages.size() == 1); + CHECK(captured.messages.front() == "kept 7"); + CHECK(evaluations == 1); +}