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..0d5c93e 100644 --- a/include/cucascade/log/logging.hpp +++ b/include/cucascade/log/logging.hpp @@ -18,26 +18,434 @@ #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. +// Logging with a host-installable sink. +// +// cuCascade has no logging backend of its own and does not want one: an +// embedding host (sirius, a benchmark harness, a test) already has a logger, +// and a library that opens its own file or grabs stderr fights with it. So the +// CUCASCADE_LOG_* macros format their message and hand a @ref record to a sink +// the host installs via @ref set_sink. +// +// **Silent by default.** With no sink installed — which is every standalone +// cuCascade build, including its own tests — a call site costs one relaxed +// atomic load and a predictable, never-taken branch. Nothing is formatted and +// nothing is allocated, so this is opt-in for the host rather than a behaviour +// change for anyone else. @ref use_stderr_sink is there for the case where you +// are debugging cuCascade itself and do not want to write an adapter first. +// +// **The sink boundary is C-shaped on purpose.** cuCascade is linked into hosts +// that were built separately, and @ref record is the one thing that crosses +// that line: it is a POD of pointers and integers, so it does not depend on the +// standard library's layout choices the way an std::string or an +// std::source_location object would. @ref record::struct_size lets a sink +// compiled against an older header stay callable, and the `inline namespace v1` +// keeps a future incompatible record from silently binding to a v1 sink. +// std::source_location is still used at the *call site*, where both sides are +// the same TU; it is decomposed into `const char*` / integers before it crosses. +// +// **Never throws, never aborts.** A log statement is not an error path. It is +// used inside destructors and noexcept functions, where an escaping exception +// is std::terminate, so formatting failures and a throwing host sink are both +// caught and the record is dropped (see @ref detail::emit). Likewise +// @ref level::fatal is a severity, not an action: cuCascade does not abort, and +// a sink that wants to should say so explicitly on the host side. +// +// Message formatting is deliberately minimal: successive `{}` in the format +// string are replaced by the corresponding argument streamed through +// `operator<<`. That covers every call site here without pulling into +// the public headers (this codebase targets toolchains where it is not +// dependable) and without taking a dependency on fmt or spdlog. +// +// A host adapter is the whole integration surface: +// +// @code +// void to_host_logger(void* user_data, cucascade::log::record const& rec) noexcept +// { +// auto* logger = static_cast(user_data); +// logger->write(map_level(rec.lvl), rec.file, rec.line, +// std::string_view{rec.message, rec.message_len}); +// } +// +// cucascade::log::set_sink(&to_host_logger, &my_logger_instance, +// cucascade::log::level::debug); +// @endcode -namespace cucascade::log::detail { +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include -/// Declared only — used strictly inside an unevaluated context. +#if defined(__linux__) +#include +#include +#endif + +// The sink and the level threshold are process-wide state reached through +// inline accessors, so every translation unit and every shared object that +// includes this header must resolve to the *same* object — otherwise the host +// installs a sink into its own copy and cuCascade's internal call sites keep +// reading a null one, and logging silently does nothing. +// +// On ELF that unification is the dynamic linker's job, and it only happens for +// symbols with default visibility. cuCascade does not currently build with +// -fvisibility=hidden, so this is redundant today; it is spelled out anyway so +// that turning hidden visibility on later (or a host compiling these headers +// with it) breaks nothing. +#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 { + +enum class level : int { + trace = 0, + debug, + info, + warn, + error, + /// A severity only — cuCascade never aborts on its own behalf. + fatal, + /// Not a message level — assign to @ref set_min_level to mute everything. + off, +}; + +/// Human-readable name for @p lvl, e.g. for a sink that renders its own prefix. +[[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 "?"; +} + +/// One formatted log record, as handed to a host sink. +/// +/// Deliberately a POD of pointers and integers: this is the only type that +/// crosses into separately-compiled host code, so it must not depend on the +/// standard library's layout choices. +/// +/// Every pointer is borrowed for the duration of the sink call only. @ref file +/// and @ref function come from `std::source_location` and have static storage +/// duration, so they may be retained; @ref message points into a buffer that +/// dies when the call returns, so a queuing sink must copy it. +/// +/// New fields are only ever appended, and @ref struct_size reports the size the +/// *producer* was compiled with. A sink built against an older header can read +/// the prefix it knows about; one that wants a newer field must check that +/// `struct_size` is large enough to cover it before reading. +struct record { + /// `sizeof(record)` as seen by the caller — see the note above. + std::size_t struct_size; + level lvl; + std::uint_least32_t line; + std::uint_least32_t column; + /// Formatted message. Borrowed, and *not* guaranteed NUL-terminated: pair it + /// with @ref message_len. + char const* message; + std::size_t message_len; + /// Originating call site — the CUCASCADE_LOG_* expansion, not the sink. + char const* file; + char const* function; + /// Linux thread id (`gettid`), so it matches `top`/`gdb`. 0 where unavailable. + std::uint64_t thread_id; + /// Wall-clock time the record was formatted, nanoseconds since the epoch. + /// Stamped at the call site rather than at delivery, which is what makes an + /// asynchronous sink able to report when the event actually happened. + std::int64_t unix_time_ns; +}; + +/// Host-installed destination for a formatted log record. +/// +/// A plain function pointer plus an opaque @p user_data rather than +/// std::function: it is read on every enabled call site from arbitrary threads, +/// and this pair is cheap to publish atomically. @p user_data is whatever was +/// passed to @ref set_sink and must outlive the last log call — including any +/// logging that happens during the host's own static destruction. +/// +/// May throw — the caller catches and drops the record — but a sink that throws +/// per record is paying to format a message nobody sees, so prefer not to. +using sink_fn = void (*)(void* user_data, record const&); + +namespace detail { + +/// Immutable once published, so that a reader always sees a matched +/// callback/user_data pair rather than one from either side of a swap. +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; +} + +/// Declared only — used strictly inside an unevaluated context to keep the +/// arguments of a compiled-out call site type-checked and "used". template int ignore(Args&&...) noexcept; -} // namespace cucascade::log::detail +/// Publish a new sink pair, returning null to mean "no sink". +/// +/// The result is never freed. A concurrent @ref emit may be holding the +/// previous pointer with no way to announce that it is done, so there is no +/// safe moment to reclaim it; the alternative — two independent atomics — can +/// hand a sink the *previous* installation's user_data mid-swap, which is a +/// dangling pointer rather than a leak. The first installation is served from a +/// static because that is what essentially every process does exactly once, so +/// the normal path neither allocates nor shows up under LeakSanitizer. +inline 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 — publication happens in set_sink. + first = sink_state{fn, user_data}; + return &first; + } + // Out of memory while installing a logger is not worth a throw from a + // noexcept function; the caller stores null and logging stays silent. + return new (std::nothrow) sink_state{fn, user_data}; +} + +[[nodiscard]] inline std::uint64_t current_thread_id() noexcept +{ +#if defined(__linux__) + // Cached: gettid is a syscall, and the id is fixed for the thread's lifetime. + static thread_local std::uint64_t const tid{static_cast(::syscall(SYS_gettid))}; + return tid; +#else + return 0; +#endif +} + +[[nodiscard]] inline std::int64_t current_unix_time_ns() noexcept +{ + return std::chrono::duration_cast( + std::chrono::system_clock::now().time_since_epoch()) + .count(); +} + +/// Terminal case: no arguments left, so the rest of the format string is +/// literal. A surplus `{}` is emitted as-is rather than treated as an error — +/// a malformed log line must never take down the caller. +inline void format_into(std::ostringstream& out, std::string_view fmt) { out << fmt; } + +template +void format_into(std::ostringstream& out, std::string_view fmt, Arg&& arg, Rest&&... rest) +{ + auto const pos = fmt.find("{}"); + if (pos == std::string_view::npos) { + // More arguments than placeholders; drop the extras rather than throw. + out << fmt; + return; + } + out << fmt.substr(0, pos) << std::forward(arg); + format_into(out, fmt.substr(pos + 2), std::forward(rest)...); +} + +template +std::string format(std::string_view fmt, Args&&... args) +{ + std::ostringstream out; + // Diagnostics are for machines and grep, not for a user's locale: without + // this a host that installed a global locale turns every byte count into + // "1,048,576", and the reads of the global locale race with a host that + // swaps it while cuCascade threads are logging. + out.imbue(std::locale::classic()); + format_into(out, fmt, std::forward(args)...); + return std::move(out).str(); +} + +/// Format and deliver one record. Called only behind @ref enabled. +template +void emit(level lvl, + std::source_location const& location, + std::string_view fmt, + Args&&... args) noexcept +{ + // Re-read rather than trusting the enabled() check: set_sink may have raced + // in between. A null here just drops the record — and 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 = format(fmt, std::forward(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 (...) { + // Both halves of that block can throw: formatting allocates and may call a + // user-supplied operator<<, and the sink is host code. Neither is allowed + // to escape, because these macros are used in destructors and noexcept + // paths where that is std::terminate. Dropping the record is the only + // answer available; reporting the failure would need the very sink that + // just failed. + } +} + +} // namespace detail + +/// Install the process-wide sink and set the severity threshold. +/// +/// Intended to be called once during host start-up, before the threads that +/// log are running. Safe to call concurrently with logging — the worst case is +/// that a record straddling the call goes to the old sink or is dropped — but +/// @p fn and whatever @p user_data points at must stay valid for as long as any +/// cuCascade thread can log, including during static destruction. Use +/// @ref clear_sink to close that window explicitly at teardown. +/// +/// @note This always writes the threshold, so it undoes an earlier +/// @ref set_min_level. Install the sink first, then adjust the 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); +} + +/// Remove the installed sink, returning cuCascade to silence. +/// +/// Call this before destroying whatever `user_data` pointed at. +inline void clear_sink() noexcept { detail::sink_slot().store(nullptr, std::memory_order_release); } + +/// Change the severity threshold without touching the installed sink. +/// +/// Hosts whose own logger has a runtime-adjustable level (glog's `--v`, +/// spdlog's `set_level`) mirror it here so filtering happens once, in +/// @ref enabled, instead of formatting a record the backend will discard. +inline void set_min_level(level min_level) noexcept +{ + detail::min_level_slot().store(min_level, std::memory_order_relaxed); +} + +[[nodiscard]] inline sink_fn sink() noexcept +{ + auto const* const state = detail::sink_slot().load(std::memory_order_acquire); + return state != nullptr ? state->fn : nullptr; +} + +[[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; +} + +[[nodiscard]] inline level min_level() noexcept +{ + return detail::min_level_slot().load(std::memory_order_relaxed); +} + +/// Whether a record at @p lvl would reach a sink. The guard on every call site, +/// so it must stay cheap: 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 its @p user_data. +/// +/// Not installed by default — see @ref use_stderr_sink. Exposed by name so a +/// host can chain to it (e.g. as the fallback of its own sink). +/// +/// @note Unlike the rest of this header, this one is defined in the library +/// (src/log/stderr_sink.cpp) rather than inline, so that , +/// and stay out of every translation unit that merely +/// logs. Using it therefore requires linking cuCascade, and it is +/// unavailable in a CUCASCADE_TOPOLOGY_ONLY build. +void stderr_sink(void* user_data, record const& rec) noexcept; + +/// Route cuCascade's log records to stderr. +/// +/// For debugging cuCascade standalone (tests, benchmarks, a reproducer) where +/// wiring a real adapter is not worth it. An embedding host should install its +/// own sink instead so cuCascade's output lands in the same place as its own. +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 floor on the severity of call sites that survive preprocessing, +// as the underlying value of a cucascade::log::level (0 = trace ... 6 = off). +// The default keeps every call site, matching the runtime-only behaviour. +// +// Safe to define differently in the library and in a consumer: it is read only +// inside the macros below, which expand at the call site, and never inside an +// inline function body or a type — so differing values cannot produce an ODR +// violation, only differently-pruned call sites. +#ifndef CUCASCADE_MIN_LOG_LEVEL +#define CUCASCADE_MIN_LOG_LEVEL 0 +#endif + +// Discard the arguments in an unevaluated context: they stay type-checked and +// count as used (no -Wunused fallout), but are never evaluated. Kept as a +// public spelling because the compiled-out branch below uses it directly to +// swallow a diagnostic on purpose. #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 { \ + /* Below the compile-time floor: keep the arguments type-checked and used. */ \ + 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..9c53f5c --- /dev/null +++ b/src/log/CMakeLists.txt @@ -0,0 +1,26 @@ +# ============================================================================= +# 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. +# ============================================================================= + +# Only the built-in stderr sink lives here. The logging machinery itself (level +# check, sink slot, formatting) stays header-only in +# include/cucascade/log/logging.hpp so that logging never imposes a link +# dependency -- including on the topology-only build, which does not produce +# cucascade_objects and therefore has no stderr sink available. +if(TARGET cucascade_objects) + target_sources(cucascade_objects + PRIVATE ${CMAKE_CURRENT_SOURCE_DIR}/stderr_sink.cpp) +endif() 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..234ba96 --- /dev/null +++ b/test/log/test_logging.cpp @@ -0,0 +1,354 @@ +/* + * 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("placeholder and argument counts may disagree without throwing", "[log]") +{ + sink_guard const guard; + capture captured; + cucascade::log::set_sink(&capture_sink, &captured, level::trace); + + SECTION("surplus arguments are dropped") + { + CUCASCADE_LOG_INFO("only {}", 1, 2); + REQUIRE(captured.messages.size() == 1); + CHECK(captured.messages.front() == "only 1"); + } + + SECTION("unfilled placeholders stay literal") + { + CUCASCADE_LOG_INFO("{} and {}", 1); + REQUIRE(captured.messages.size() == 1); + CHECK(captured.messages.front() == "1 and {}"); + } + + 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"); + } +} + +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); +}