src/logger.cpp
| Line | Branch | Exec | Source |
|---|---|---|---|
| 1 | #include "DetourModKit/logger.hpp" | ||
| 2 | #include "DetourModKit/diagnostics.hpp" | ||
| 3 | #include "DetourModKit/filesystem.hpp" | ||
| 4 | |||
| 5 | #include "internal/async_logger.hpp" | ||
| 6 | #include "internal/utf8_conversion.hpp" | ||
| 7 | #include "internal/win_file_stream.hpp" | ||
| 8 | #include "platform.hpp" | ||
| 9 | |||
| 10 | #include <algorithm> | ||
| 11 | #include <chrono> | ||
| 12 | #include <cstdio> | ||
| 13 | #include <ctime> | ||
| 14 | #include <filesystem> | ||
| 15 | #include <iomanip> | ||
| 16 | #include <iostream> | ||
| 17 | #include <new> | ||
| 18 | #include <stdexcept> | ||
| 19 | #include <string_view> | ||
| 20 | #include <type_traits> | ||
| 21 | |||
| 22 | namespace DetourModKit::detail | ||
| 23 | { | ||
| 24 | #if defined(DMK_ENABLE_TEST_SEAMS) | ||
| 25 | // shutdown_internal() fires this test-only probe inside its dropped-mutex window, after the first writer retirement | ||
| 26 | // and before the final re-check. A fixture drives configure() and enable_async_mode() calls into that window. Tests | ||
| 27 | // install it on one thread. Builds without DMK_ENABLE_TEST_SEAMS omit it. | ||
| 28 | void (*g_logger_shutdown_gap_probe)() noexcept = nullptr; | ||
| 29 | |||
| 30 | // Test-only probe fired inside enable_async_mode()'s arm-then-publish window. When non-null it may throw, which | ||
| 31 | // is the only way to reach the rollback that breaks a retention root whose writer was never published. Set / | ||
| 32 | // cleared on a single thread inside a test fixture; the definition and fire site compile out of shipping builds. | ||
| 33 | void (*g_logger_publication_probe)() = nullptr; | ||
| 34 | |||
| 35 | // Test-only probe at the old success-diagnostic site after enable_async_mode() publishes the writer. | ||
| 36 | // It can throw when non-null. Tests install it on one thread. Shipping builds omit it. | ||
| 37 | void (*g_logger_post_publication_probe)() = nullptr; | ||
| 38 | |||
| 39 | // Test-only probe fired after Logger::log() snapshots an async writer and before it calls enqueue(). A fixture | ||
| 40 | // retires that writer inside the probe to prove a late rejection reaches the facade's cumulative drop counter. | ||
| 41 | void (*g_logger_async_snapshot_probe)() noexcept = nullptr; | ||
| 42 | |||
| 43 | // Test-only probe at entry to each record delivery route. A fixture checks whether a config lock spans that route. | ||
| 44 | void (*g_logger_record_probe)(LogLevel, std::string_view) noexcept = nullptr; | ||
| 45 | |||
| 46 | // Test-only rendezvous after set_log_level() reads the current level and before it attempts the state transition. | ||
| 47 | void (*g_logger_level_transition_probe)() noexcept = nullptr; | ||
| 48 | #endif | ||
| 49 | } // namespace DetourModKit::detail | ||
| 50 | |||
| 51 | namespace DetourModKit | ||
| 52 | { | ||
| 53 | namespace | ||
| 54 | { | ||
| 55 | using StaticConfigAtom = std::atomic<std::shared_ptr<const Logger::StaticConfig>>; | ||
| 56 | |||
| 57 | /** | ||
| 58 | * @brief Returns the never-destroyed process configuration publication slot. | ||
| 59 | * @details The slot matches the process-lifetime Logger storage (`[B-47]`). | ||
| 60 | */ | ||
| 61 | 7927 | StaticConfigAtom &static_config_atom() | |
| 62 | { | ||
| 63 | alignas(StaticConfigAtom) static unsigned char storage[sizeof(StaticConfigAtom)]; | ||
| 64 | static StaticConfigAtom *const atom = | ||
| 65 | 6534 | ::new (static_cast<void *>(storage)) StaticConfigAtom{std::make_shared<const Logger::StaticConfig>( | |
| 66 | 6534 | std::string{DEFAULT_LOG_PREFIX}, | |
| 67 | 6534 | std::string{DEFAULT_LOG_FILE_NAME}, | |
| 68 | 6534 | std::string{DEFAULT_TIMESTAMP_FORMAT} | |
| 69 | 14461 | )}; | |
| 70 | 7927 | return *atom; | |
| 71 | } | ||
| 72 | |||
| 73 | /** | ||
| 74 | * @brief Serializes process-default configuration publication and application. | ||
| 75 | * @details Late static teardown can call configure(). The mutex uses never-destroyed storage (`[B-47]`). | ||
| 76 | */ | ||
| 77 | 2310 | [[nodiscard]] std::mutex &static_config_mutex() noexcept | |
| 78 | { | ||
| 79 | alignas(std::mutex) static unsigned char storage[sizeof(std::mutex)]; | ||
| 80 | 2310 | static std::mutex *const mutex = ::new (static_cast<void *>(storage)) std::mutex(); | |
| 81 | 2310 | return *mutex; | |
| 82 | } | ||
| 83 | |||
| 84 | /** | ||
| 85 | * @brief Writes one INFO banner line from a pre-rendered timestamp. | ||
| 86 | * @details Stream insertion records an error through failbit. This helper does not throw after a state | ||
| 87 | * commit. | ||
| 88 | */ | ||
| 89 | void | ||
| 90 | 4133 | write_banner_line(detail::WinFileStream &sink, std::string_view timestamp, std::string_view message) noexcept | |
| 91 | { | ||
| 92 | 4133 | sink << "[" << timestamp << "] " << "[" << std::setw(7) << std::left << "INFO" << "] :: " << message | |
| 93 | 4133 | << '\n'; | |
| 94 | 4133 | } | |
| 95 | |||
| 96 | /** | ||
| 97 | * @brief Abandons a detached writer's handle to the retention root armed before its publication. | ||
| 98 | * @details Retention costs nothing here: the writer already owns itself, so keeping it alive is simply not | ||
| 99 | * breaking that root. Nothing is allocated, nothing can throw, and there is no finite supply of | ||
| 100 | * fallback storage to exhaust, which is what makes this safe on the loader-lock path that reaches it. | ||
| 101 | * No module reference is taken either: the detached writer thread holds its own counted reference on | ||
| 102 | * this module (taken before thread creation, while the module was fully mapped), and that is what | ||
| 103 | * keeps its code mapped. | ||
| 104 | */ | ||
| 105 | 26 | void abandon_detached_async_logger(std::shared_ptr<AsyncLogger> &logger) noexcept | |
| 106 | { | ||
| 107 | 26 | if (!logger) | |
| 108 | { | ||
| 109 | ✗ | return; | |
| 110 | } | ||
| 111 | 26 | logger.reset(); | |
| 112 | 26 | DetourModKit::diagnostics::record_intentional_leak(DetourModKit::diagnostics::LeakSubsystem::Logger); | |
| 113 | } | ||
| 114 | |||
| 115 | #if defined(DMK_ENABLE_TEST_SEAMS) | ||
| 116 | /** | ||
| 117 | * @brief Fires the post-publication probe of enable_async_mode() and discards any exception it throws. | ||
| 118 | * @details This seam proves that a throw after publication cannot escape or disturb the published writer. | ||
| 119 | */ | ||
| 120 | 1802 | void fire_post_publication_probe() noexcept | |
| 121 | { | ||
| 122 | 1802 | if (auto *post_publication_probe = detail::g_logger_post_publication_probe) | |
| 123 | { | ||
| 124 | try | ||
| 125 | { | ||
| 126 | 2 | post_publication_probe(); | |
| 127 | } | ||
| 128 | 2 | catch (...) | |
| 129 | { | ||
| 130 | 2 | } | |
| 131 | } | ||
| 132 | 1802 | } | |
| 133 | #endif | ||
| 134 | } // anonymous namespace | ||
| 135 | |||
| 136 | 5598 | std::shared_ptr<const Logger::StaticConfig> Logger::get_static_config() | |
| 137 | { | ||
| 138 | 5598 | return static_config_atom().load(std::memory_order_acquire); | |
| 139 | } | ||
| 140 | |||
| 141 | 2329 | void Logger::set_static_config(std::shared_ptr<const StaticConfig> config) | |
| 142 | { | ||
| 143 | 4658 | static_config_atom().store(std::move(config), std::memory_order_release); | |
| 144 | 2329 | } | |
| 145 | |||
| 146 | 750 | LogLevel string_to_log_level(std::string_view level_str) | |
| 147 | { | ||
| 148 | 750 | std::string upper_level_str(level_str); | |
| 149 | 7821 | for (char &c : upper_level_str) | |
| 150 | { | ||
| 151 | // Fold ASCII a-z by hand, as manifest.cpp does for its keywords: std::toupper is locale sensitive, which | ||
| 152 | // [B-37] forbids on a resolution path. LoggerTest.StringToLogLevelUsesAsciiFold pins the rule. | ||
| 153 | 6321 | if (c >= 'a' && c <= 'z') | |
| 154 | { | ||
| 155 | 107 | c = static_cast<char>(c - 'a' + 'A'); | |
| 156 | } | ||
| 157 | } | ||
| 158 | |||
| 159 | 750 | if (upper_level_str == "TRACE") | |
| 160 | 8 | return LogLevel::Trace; | |
| 161 | 742 | if (upper_level_str == "DEBUG") | |
| 162 | 9 | return LogLevel::Debug; | |
| 163 | 733 | if (upper_level_str == "INFO") | |
| 164 | 5 | return LogLevel::Info; | |
| 165 | 728 | if (upper_level_str == "WARNING") | |
| 166 | 8 | return LogLevel::Warning; | |
| 167 | 720 | if (upper_level_str == "ERROR") | |
| 168 | 8 | return LogLevel::Error; | |
| 169 | |||
| 170 | std::cerr << "[" << DEFAULT_LOG_PREFIX << " Logger WARNING] Unrecognized log level string '" << level_str | ||
| 171 | 712 | << "'. Defaulting to INFO." << '\n'; | |
| 172 | 712 | return LogLevel::Info; | |
| 173 | 750 | } | |
| 174 | |||
| 175 | 2310 | void Logger::configure( | |
| 176 | std::string_view prefix, | ||
| 177 | std::string_view file_name, | ||
| 178 | std::string_view timestamp_fmt, | ||
| 179 | LogOpenMode open_mode, | ||
| 180 | LogSourceStampMode source_stamp_mode | ||
| 181 | ) | ||
| 182 | { | ||
| 183 | 2310 | std::lock_guard<std::mutex> config_lock(static_config_mutex()); | |
| 184 | |||
| 185 | // The staged snapshot precedes first use because the process-default constructor reads it. The prior snapshot | ||
| 186 | // restores the last accepted defaults after a failed apply. | ||
| 187 | auto staged_config = std::make_shared<const StaticConfig>( | ||
| 188 | 4615 | std::string(prefix), | |
| 189 | 4618 | std::string(file_name), | |
| 190 | 4623 | std::string(timestamp_fmt), | |
| 191 | open_mode, | ||
| 192 | source_stamp_mode | ||
| 193 | 2306 | ); | |
| 194 | 2305 | auto previous_config = get_static_config(); | |
| 195 | 2305 | set_static_config(std::move(staged_config)); | |
| 196 | |||
| 197 | // The qualified free accessor avoids the member log() overload set, which hides the process-default accessor. | ||
| 198 | try | ||
| 199 | { | ||
| 200 | 2305 | Logger &instance = DetourModKit::log(); | |
| 201 | |||
| 202 | // An inert first-use logger owns no sink or mutex and cannot apply the staged defaults. Restore the prior | ||
| 203 | // snapshot before it returns to its process-lifetime inert state. | ||
| 204 | 2305 | if (instance.is_inert()) | |
| 205 | { | ||
| 206 | ✗ | set_static_config(std::move(previous_config)); | |
| 207 | ✗ | return; | |
| 208 | } | ||
| 209 | |||
| 210 | // The sink locks serialize configuration with shutdown. Neither operation can split the other's sink | ||
| 211 | // transition. | ||
| 212 | 2305 | std::scoped_lock lock(instance.m_async_mutex, *instance.m_log_mutex_ptr); | |
| 213 | 2305 | if (instance.m_async_writer_abandoned.load(std::memory_order_acquire)) | |
| 214 | { | ||
| 215 | // A detached writer retains final sink ownership. Restore the snapshot to avoid a second sink owner. | ||
| 216 | ✗ | set_static_config(std::move(previous_config)); | |
| 217 | ✗ | return; | |
| 218 | } | ||
| 219 | // configure() is the authoritative reset path: it re-enables the process default even after a shutdown, | ||
| 220 | // so a test fixture or a re-attach can reuse the sink. The latch is deliberately outside the sink | ||
| 221 | // transaction. A live facade over an unopenable sink still routes an Error record to stderr. | ||
| 222 | 2305 | instance.m_shutdown_called.store(false, std::memory_order_release); | |
| 223 | 2305 | if (!instance.reconfigure_locked(prefix, file_name, timestamp_fmt)) | |
| 224 | { | ||
| 225 | 8 | set_static_config(std::move(previous_config)); | |
| 226 | } | ||
| 227 | else | ||
| 228 | { | ||
| 229 | 2281 | instance.set_source_stamp_mode(source_stamp_mode); | |
| 230 | } | ||
| 231 | 2305 | } | |
| 232 | 16 | catch (...) | |
| 233 | { | ||
| 234 | // A post-publication allocation can throw. Rollback pairs the immutable defaults with the last accepted | ||
| 235 | // configuration and preserves configure()'s exception contract. | ||
| 236 | 16 | set_static_config(std::move(previous_config)); | |
| 237 | 16 | throw; | |
| 238 | 16 | } | |
| 239 | 2342 | } | |
| 240 | |||
| 241 | 24 | void Logger::reconfigure(std::string_view prefix, std::string_view file_name, std::string_view timestamp_fmt) | |
| 242 | { | ||
| 243 | 24 | if (is_inert() || m_async_writer_abandoned.load(std::memory_order_acquire)) | |
| 244 | { | ||
| 245 | 2 | return; | |
| 246 | } | ||
| 247 | |||
| 248 | 23 | if (m_shutdown_called.load(std::memory_order_acquire)) | |
| 249 | { | ||
| 250 | 1 | return; | |
| 251 | } | ||
| 252 | |||
| 253 | // Acquire both m_async_mutex and *m_log_mutex_ptr to prevent concurrent log() calls from reading | ||
| 254 | // partially-updated string members during reconfiguration. | ||
| 255 | 22 | std::scoped_lock lock(m_async_mutex, *m_log_mutex_ptr); | |
| 256 | 44 | if (m_shutdown_called.load(std::memory_order_acquire) || | |
| 257 | 22 | m_async_writer_abandoned.load(std::memory_order_acquire)) | |
| 258 | { | ||
| 259 | ✗ | return; | |
| 260 | } | ||
| 261 | // The public form reports nothing: a caller that needs the outcome reads the log file it named. | ||
| 262 | 22 | (void)reconfigure_locked(prefix, file_name, timestamp_fmt); | |
| 263 | 22 | } | |
| 264 | |||
| 265 | 2327 | bool Logger::reconfigure_locked(std::string_view prefix, std::string_view file_name, std::string_view timestamp_fmt) | |
| 266 | { | ||
| 267 | // Precondition: the caller holds m_async_mutex and *m_log_mutex_ptr. | ||
| 268 | |||
| 269 | // Skip only when all parameters match AND the stream is usable. After shutdown or a prior open failure the | ||
| 270 | // stream may be closed, so fall through to reopen even if the strings are identical. | ||
| 271 | 2327 | const bool sink_usable = m_log_file_stream_ptr->is_open() && m_log_file_stream_ptr->good(); | |
| 272 | 4075 | if (sink_usable && m_log_prefix == prefix && m_log_file_name == file_name && | |
| 273 | 1748 | m_timestamp_format == timestamp_fmt) | |
| 274 | { | ||
| 275 | 1745 | return true; | |
| 276 | } | ||
| 277 | |||
| 278 | // The prefix and timestamp format apply per line, not baked into the open file, so a change that keeps the | ||
| 279 | // same file needs no reopen. A different target file, or an unusable stream, needs a replacement sink. Only | ||
| 280 | // the process-start constructor truncates, so the replacement opens in append mode and the target file keeps | ||
| 281 | // its existing records. | ||
| 282 | 582 | const bool needs_new_sink = (m_log_file_name != file_name) || !sink_usable; | |
| 283 | |||
| 284 | // All transaction allocation precedes file creation. A failed candidate leaves the current configuration and | ||
| 285 | // sink intact. A failed retirement can leave an empty candidate file, but it retains the current handle and | ||
| 286 | // tail. | ||
| 287 | // LoggerTest.Reconfigure_InvalidPath_KeepsOldFile and LoggerTest.Reconfigure_AllocationFailure_KeepsOldSink | ||
| 288 | // pin both halves. | ||
| 289 | 1164 | std::string staged_prefix(prefix); | |
| 290 | 1162 | std::string staged_file_name(file_name); | |
| 291 | 580 | std::string staged_timestamp_format(timestamp_fmt); | |
| 292 | 578 | std::string staged_async_format = staged_timestamp_format; | |
| 293 | 577 | const bool retires_prior_sink = needs_new_sink && m_log_file_stream_ptr->is_open(); | |
| 294 | 577 | const std::string retire_timestamp = retires_prior_sink ? get_timestamp(m_timestamp_format) : std::string{}; | |
| 295 | 575 | std::string retire_notice; | |
| 296 | 575 | if (retires_prior_sink) | |
| 297 | { | ||
| 298 | 312 | retire_notice = "Logger reconfiguring. New file: "; | |
| 299 | 310 | retire_notice += file_name; | |
| 300 | } | ||
| 301 | 571 | const std::string adopt_notice = needs_new_sink ? ("Logger reconfigured. Now logging to: " + staged_file_name) | |
| 302 | 627 | : std::string("Logger reconfigured (same file retained)."); | |
| 303 | 569 | const std::string adopt_timestamp = get_timestamp(staged_timestamp_format); | |
| 304 | |||
| 305 | 568 | std::shared_ptr<detail::WinFileStream> staged_sink; | |
| 306 | 568 | if (needs_new_sink) | |
| 307 | { | ||
| 308 | 514 | staged_sink = open_sink(staged_file_name, /*truncate=*/false); | |
| 309 | 500 | if (!staged_sink) | |
| 310 | { | ||
| 311 | 11 | return false; | |
| 312 | } | ||
| 313 | } | ||
| 314 | |||
| 315 | // The current sink closes before the state commit. A close failure retains the handle and buffered tail. | ||
| 316 | // Cleared stream flags permit a later retry. The candidate stays uncommitted while recoverable state exists. | ||
| 317 | 543 | if (staged_sink && retires_prior_sink) | |
| 318 | { | ||
| 319 | 285 | if (sink_usable) | |
| 320 | { | ||
| 321 | 285 | write_banner_line(*m_log_file_stream_ptr, retire_timestamp, retire_notice); | |
| 322 | 285 | m_log_file_stream_ptr->flush(); | |
| 323 | } | ||
| 324 | 285 | m_log_file_stream_ptr->close(); | |
| 325 | 285 | if (m_log_file_stream_ptr->is_open()) | |
| 326 | { | ||
| 327 | 1 | m_log_file_stream_ptr->clear(); | |
| 328 | 1 | return false; | |
| 329 | } | ||
| 330 | } | ||
| 331 | |||
| 332 | // Member moves, banner writes, and both async setters are no-throw. The configuration cannot become | ||
| 333 | // half-applied. | ||
| 334 | 542 | m_log_prefix = std::move(staged_prefix); | |
| 335 | 542 | m_log_file_name = std::move(staged_file_name); | |
| 336 | 542 | m_timestamp_format = std::move(staged_timestamp_format); | |
| 337 | |||
| 338 | 542 | if (staged_sink) | |
| 339 | { | ||
| 340 | 488 | m_log_file_stream_ptr = std::move(staged_sink); | |
| 341 | 488 | write_banner_line(*m_log_file_stream_ptr, adopt_timestamp, adopt_notice); | |
| 342 | } | ||
| 343 | else | ||
| 344 | { | ||
| 345 | // The same file stays open with its records intact. The in-line banner records the change without | ||
| 346 | // truncation. | ||
| 347 | 54 | write_banner_line(*m_log_file_stream_ptr, adopt_timestamp, adopt_notice); | |
| 348 | 54 | m_log_file_stream_ptr->flush(); | |
| 349 | } | ||
| 350 | |||
| 351 | // A live async writer receives the committed sink and timestamp format. enable_async_mode captures both at | ||
| 352 | // construction. Without this update, the writer keeps the old format and writes to the retired stream. Each | ||
| 353 | // setter assigns under the scoped lock, and the writer reads both only under *m_log_mutex_ptr. | ||
| 354 | 542 | if (m_async_mode_enabled.load(std::memory_order_acquire)) | |
| 355 | { | ||
| 356 | 2 | if (auto async_logger = m_async_logger.load(std::memory_order_acquire)) | |
| 357 | { | ||
| 358 | 2 | async_logger->set_file_stream(m_log_file_stream_ptr); | |
| 359 | 4 | async_logger->set_timestamp_format(std::move(staged_async_format)); | |
| 360 | 2 | } | |
| 361 | } | ||
| 362 | 542 | return true; | |
| 363 | 738 | } | |
| 364 | |||
| 365 | 3267 | Logger::Logger() : m_log_mutex_ptr(std::make_shared<std::mutex>()) | |
| 366 | { | ||
| 367 | 3267 | const auto config = get_static_config(); | |
| 368 | 3267 | m_log_prefix = config->log_prefix; | |
| 369 | 3267 | m_log_file_name = config->log_file_name; | |
| 370 | 3267 | m_timestamp_format = config->timestamp_format; | |
| 371 | 3267 | m_source_stamp_mode.store(config->source_stamp_mode, std::memory_order_relaxed); | |
| 372 | |||
| 373 | // A default construction starts a fresh log unless the published configuration selected Append. | ||
| 374 | // Reconfiguration never truncates. | ||
| 375 | 3267 | adopt_first_sink(/*truncate=*/config->open_mode == LogOpenMode::Truncate); | |
| 376 | 3267 | } | |
| 377 | |||
| 378 | 2 | Logger::Logger(InertTag) noexcept | |
| 379 | { | ||
| 380 | // Inert first-use logger. No sink, shared sink mutex, or writer is allocated, so is_inert() (a null | ||
| 381 | // m_log_mutex_ptr) is true and every enabled log request fails closed by dropping and counting. Constructing | ||
| 382 | // the empty string and atomic members allocates nothing, so this stays no-throw under the OOM that forced the | ||
| 383 | // fallback. | ||
| 384 | 2 | } | |
| 385 | |||
| 386 | 44 | Logger::Logger( | |
| 387 | std::string_view prefix, | ||
| 388 | std::string_view file_name, | ||
| 389 | std::string_view timestamp_fmt, | ||
| 390 | LogOpenMode open_mode, | ||
| 391 | LogSourceStampMode source_stamp_mode | ||
| 392 | 44 | ) | |
| 393 | 264 | : m_log_prefix(prefix), m_log_file_name(file_name), m_timestamp_format(timestamp_fmt), | |
| 394 | 44 | m_log_mutex_ptr(std::make_shared<std::mutex>()), m_source_stamp_mode(source_stamp_mode) | |
| 395 | { | ||
| 396 | // Construction starts a fresh log unless the caller selected Append. Reconfiguration never truncates. | ||
| 397 | 44 | adopt_first_sink(/*truncate=*/open_mode == LogOpenMode::Truncate); | |
| 398 | 44 | } | |
| 399 | |||
| 400 | 3825 | std::shared_ptr<detail::WinFileStream> Logger::open_sink(const std::string &file_name, bool truncate) const | |
| 401 | { | ||
| 402 | // Opens a candidate sink and never touches this Logger, so reconfigure_locked() can prove the replacement | ||
| 403 | // file before it retires the live one. Truncate starts a fresh file. Append preserves prior records. | ||
| 404 | 3825 | const std::wstring log_file_full_path = generate_log_file_path(file_name); | |
| 405 | 3813 | if (log_file_full_path.empty() && !file_name.empty()) | |
| 406 | { | ||
| 407 | // generate_log_file_path() already reported the name that did not widen. An empty path names no file. | ||
| 408 | 3 | return nullptr; | |
| 409 | } | ||
| 410 | 3810 | const auto mode = truncate ? (std::ios::out | std::ios::trunc) : (std::ios::out | std::ios::app); | |
| 411 | 3810 | auto sink = std::make_shared<detail::WinFileStream>(); | |
| 412 | 3808 | sink->open(log_file_full_path, mode); | |
| 413 | |||
| 414 | 3808 | if (!sink->is_open()) | |
| 415 | { | ||
| 416 | 13 | std::cerr << "[" << m_log_prefix << " Logger CRITICAL ERROR] " | |
| 417 | 26 | << "Failed to open log file: " << detail::utf8_from_wide(log_file_full_path) | |
| 418 | 26 | << ". Subsequent logs to file will fail." << '\n'; | |
| 419 | 13 | return nullptr; | |
| 420 | } | ||
| 421 | 3795 | return sink; | |
| 422 | 3813 | } | |
| 423 | |||
| 424 | 3311 | void Logger::adopt_first_sink(bool truncate) | |
| 425 | { | ||
| 426 | // Construction only: a failed open still leaves a stream object, because every later log() dereferences | ||
| 427 | // m_log_file_stream_ptr and fails closed on the closed stream rather than on a null pointer. | ||
| 428 | 3311 | auto sink = open_sink(m_log_file_name, truncate); | |
| 429 | 3311 | if (!sink) | |
| 430 | { | ||
| 431 | 5 | m_log_file_stream_ptr = std::make_shared<detail::WinFileStream>(); | |
| 432 | 5 | return; | |
| 433 | } | ||
| 434 | 3306 | m_log_file_stream_ptr = std::move(sink); | |
| 435 | 9918 | write_banner_line( | |
| 436 | 3306 | *m_log_file_stream_ptr, | |
| 437 | 6612 | get_timestamp(m_timestamp_format), | |
| 438 | 6612 | "Logger initialized. Logging to: " + m_log_file_name | |
| 439 | ); | ||
| 440 | 3311 | } | |
| 441 | |||
| 442 | 59 | Logger::~Logger() noexcept | |
| 443 | { | ||
| 444 | 44 | bool expected = false; | |
| 445 | 44 | if (!m_shutdown_called.compare_exchange_strong(expected, true, std::memory_order_acq_rel)) | |
| 446 | { | ||
| 447 | 29 | return; | |
| 448 | } | ||
| 449 | 15 | shutdown_internal(); | |
| 450 | 218 | } | |
| 451 | |||
| 452 | 1853 | void Logger::shutdown() noexcept | |
| 453 | { | ||
| 454 | 1853 | bool expected = false; | |
| 455 | 1853 | if (!m_shutdown_called.compare_exchange_strong(expected, true, std::memory_order_acq_rel)) | |
| 456 | { | ||
| 457 | 29 | return; | |
| 458 | } | ||
| 459 | 1824 | shutdown_internal(); | |
| 460 | } | ||
| 461 | |||
| 462 | 1839 | void Logger::shutdown_internal() noexcept | |
| 463 | { | ||
| 464 | // An inert first-use logger owns no async writer, sink, or shared sink mutex, so there is nothing to drain or | ||
| 465 | // close. | ||
| 466 | 1839 | if (is_inert()) | |
| 467 | { | ||
| 468 | 16 | return; | |
| 469 | } | ||
| 470 | |||
| 471 | // Retires the published writer. The caller holds m_async_mutex but not *m_log_mutex_ptr, which the writer | ||
| 472 | // takes to drain before its join returns. Returns true when the writer detached and keeps final sink access. | ||
| 473 | 3660 | const auto retire_published_writer = [this](std::shared_ptr<AsyncLogger> &owner) noexcept -> bool | |
| 474 | { | ||
| 475 | 3660 | if (!m_async_mode_enabled.load(std::memory_order_acquire)) | |
| 476 | { | ||
| 477 | 1904 | return false; | |
| 478 | } | ||
| 479 | 1756 | owner = m_async_logger.exchange(nullptr, std::memory_order_acq_rel); | |
| 480 | 1756 | m_async_mode_enabled.store(false, std::memory_order_release); | |
| 481 | 1756 | if (!owner) | |
| 482 | { | ||
| 483 | ✗ | return false; | |
| 484 | } | ||
| 485 | 1756 | owner->shutdown(); | |
| 486 | 1756 | m_dropped_messages.fetch_add(owner->dropped_count(), std::memory_order_relaxed); | |
| 487 | 1756 | if (owner->writer_was_detached()) | |
| 488 | { | ||
| 489 | // The latch precedes the release of m_async_mutex, so configure cannot reopen behind the writer. | ||
| 490 | 14 | m_async_writer_abandoned.store(true, std::memory_order_release); | |
| 491 | 14 | return true; | |
| 492 | } | ||
| 493 | // The joined writer reads no state. The owner reference keeps it alive, so the root release cannot destroy | ||
| 494 | // the writer inside its own call. | ||
| 495 | 1742 | owner->release_retention_root(); | |
| 496 | 1742 | return false; | |
| 497 | 1837 | }; | |
| 498 | |||
| 499 | 1837 | std::shared_ptr<AsyncLogger> local_logger; | |
| 500 | 1837 | bool writer_detached = false; | |
| 501 | { | ||
| 502 | 1837 | std::lock_guard<std::mutex> lock(m_async_mutex); | |
| 503 | 1837 | writer_detached = retire_published_writer(local_logger); | |
| 504 | 1837 | } | |
| 505 | |||
| 506 | #if defined(DMK_ENABLE_TEST_SEAMS) | ||
| 507 | 1837 | if (auto *gap_probe = detail::g_logger_shutdown_gap_probe) | |
| 508 | { | ||
| 509 | 3 | gap_probe(); | |
| 510 | } | ||
| 511 | #endif | ||
| 512 | |||
| 513 | // A configure call that ran inside the gap above must not leave the facade live after this shutdown continues. | ||
| 514 | 1837 | m_shutdown_called.store(true, std::memory_order_release); | |
| 515 | |||
| 516 | // A detached writer still owns the AsyncLogger state and final sink access. Drop this frame's handle without | ||
| 517 | // breaking the writer's retention root and return without sink I/O. Keying on the recorded detach outcome | ||
| 518 | // avoids a loader-lock re-query race. | ||
| 519 | 1837 | if (writer_detached) | |
| 520 | { | ||
| 521 | 14 | abandon_detached_async_logger(local_logger); | |
| 522 | 14 | return; | |
| 523 | } | ||
| 524 | |||
| 525 | // A configure() and enable_async_mode() pair in the gap can publish a writer. m_async_mutex stays held from | ||
| 526 | // this re-check through the close, so no pair publishes between them. A writer that any path detached keeps | ||
| 527 | // final sink access (`[B-48]`), so the close runs only while the abandoned latch is clear. Every write of that | ||
| 528 | // latch runs under m_async_mutex. gap_logger drops after both mutexes release. | ||
| 529 | 1823 | std::shared_ptr<AsyncLogger> gap_logger; | |
| 530 | 1823 | bool gap_writer_detached = false; | |
| 531 | { | ||
| 532 | 1823 | std::lock_guard<std::mutex> async_lock(m_async_mutex); | |
| 533 | 1823 | m_shutdown_called.store(true, std::memory_order_release); | |
| 534 | 1823 | gap_writer_detached = retire_published_writer(gap_logger); | |
| 535 | 1823 | if (!m_async_writer_abandoned.load(std::memory_order_acquire)) | |
| 536 | { | ||
| 537 | 1823 | std::lock_guard<std::mutex> sink_lock(*m_log_mutex_ptr); | |
| 538 | 1823 | if (m_log_file_stream_ptr && m_log_file_stream_ptr->is_open()) | |
| 539 | { | ||
| 540 | 1819 | m_log_file_stream_ptr->flush(); | |
| 541 | 1819 | m_log_file_stream_ptr->close(); | |
| 542 | } | ||
| 543 | 1823 | } | |
| 544 | 1823 | } | |
| 545 | 1823 | if (gap_writer_detached) | |
| 546 | { | ||
| 547 | ✗ | abandon_detached_async_logger(gap_logger); | |
| 548 | } | ||
| 549 | 1837 | } | |
| 550 | |||
| 551 | 258 | void Logger::set_log_level(LogLevel level) | |
| 552 | { | ||
| 553 | // LogLevel's fixed unsigned base makes a negative value unrepresentable, so the upper bound is the whole | ||
| 554 | // domain check: an out-of-range cast arrives as a value above Error. LoggerTest.SetLogLevel_InvalidLevel pins | ||
| 555 | // the rejection at 5, 99, and the top of the base. | ||
| 556 | 258 | auto level_int = static_cast<std::underlying_type_t<LogLevel>>(level); | |
| 557 | 258 | if (level_int > static_cast<std::underlying_type_t<LogLevel>>(LogLevel::Error)) | |
| 558 | { | ||
| 559 | 3 | log(LogLevel::Warning, | |
| 560 | "Attempted to set an invalid log level value ({}). Keeping current level.", | ||
| 561 | level_int); | ||
| 562 | 83 | return; | |
| 563 | } | ||
| 564 | |||
| 565 | 255 | auto old_level = m_current_log_level.load(std::memory_order_acquire); | |
| 566 | #if defined(DMK_ENABLE_TEST_SEAMS) | ||
| 567 | 255 | if (const auto transition_probe = detail::g_logger_level_transition_probe) | |
| 568 | { | ||
| 569 | 4 | transition_probe(); | |
| 570 | } | ||
| 571 | #endif | ||
| 572 | |||
| 573 | for (;;) | ||
| 574 | { | ||
| 575 | 257 | if (old_level == level) | |
| 576 | { | ||
| 577 | 80 | return; | |
| 578 | } | ||
| 579 | 177 | if (m_current_log_level | |
| 580 | 177 | .compare_exchange_weak(old_level, level, std::memory_order_acq_rel, std::memory_order_acquire)) | |
| 581 | { | ||
| 582 | 175 | break; | |
| 583 | } | ||
| 584 | } | ||
| 585 | |||
| 586 | // The new threshold precedes this record. The ordinary predicate discards the record after an upward change. | ||
| 587 | ✗ | (void)format_located( | |
| 588 | 349 | [this](std::string_view rendered) { return this->emit_record(LogLevel::Info, rendered); }, | |
| 589 | 175 | source_stamp_enabled(LogLevel::Info), | |
| 590 | 175 | std::source_location::current(), | |
| 591 | "Log level changed from {} to {}", | ||
| 592 | 175 | to_string(old_level), | |
| 593 | 350 | to_string(level) | |
| 594 | ); | ||
| 595 | } | ||
| 596 | |||
| 597 | 33876 | bool Logger::log(LogLevel level, std::string_view message) | |
| 598 | { | ||
| 599 | 33876 | if (level < m_current_log_level.load(std::memory_order_acquire)) | |
| 600 | { | ||
| 601 | 6 | return false; | |
| 602 | } | ||
| 603 | |||
| 604 | 33872 | return emit_record(level, message); | |
| 605 | } | ||
| 606 | |||
| 607 | 34043 | bool Logger::emit_record(LogLevel level, std::string_view message) | |
| 608 | { | ||
| 609 | #if defined(DMK_ENABLE_TEST_SEAMS) | ||
| 610 | 34043 | if (const auto record_probe = detail::g_logger_record_probe) | |
| 611 | { | ||
| 612 | 670 | record_probe(level, message); | |
| 613 | } | ||
| 614 | #endif | ||
| 615 | 67950 | if (m_shutdown_called.load(std::memory_order_acquire) || | |
| 616 | 33905 | m_async_writer_abandoned.load(std::memory_order_acquire)) | |
| 617 | { | ||
| 618 | 134 | m_dropped_messages.fetch_add(1, std::memory_order_relaxed); | |
| 619 | 134 | return false; | |
| 620 | } | ||
| 621 | |||
| 622 | // An inert first-use logger (construction failed under OOM) owns no sink or shared sink mutex. Drop and count | ||
| 623 | // the record instead of dereferencing a null pointer; it stays inert for the process lifetime. | ||
| 624 | 33910 | if (is_inert()) | |
| 625 | { | ||
| 626 | 6 | m_dropped_messages.fetch_add(1, std::memory_order_relaxed); | |
| 627 | 6 | return false; | |
| 628 | } | ||
| 629 | |||
| 630 | // Fast path: an atomic<bool> gate (a genuine lock-free read) selects async mode. The atomic<shared_ptr> | ||
| 631 | // snapshot that follows is correct and callback-safe but takes a bounded internal STL lock, not a lock-free | ||
| 632 | // read (see the m_async_logger member comment in logger.hpp), so it is not described as lock-free here. | ||
| 633 | 33908 | if (m_async_mode_enabled.load(std::memory_order_acquire)) | |
| 634 | { | ||
| 635 | 7988 | auto local_logger = m_async_logger.load(std::memory_order_acquire); | |
| 636 | 8016 | if (local_logger) | |
| 637 | { | ||
| 638 | #if defined(DMK_ENABLE_TEST_SEAMS) | ||
| 639 | 8016 | if (auto *snapshot_probe = detail::g_logger_async_snapshot_probe) | |
| 640 | { | ||
| 641 | 1 | snapshot_probe(); | |
| 642 | } | ||
| 643 | #endif | ||
| 644 | // The queue result exposes the true delivery status instead of unconditional success. | ||
| 645 | 8016 | return local_logger->enqueue_from_facade(level, message, m_dropped_messages); | |
| 646 | } | ||
| 647 | 8011 | } | |
| 648 | |||
| 649 | 25923 | const auto level_str = to_string(level); | |
| 650 | 25924 | std::lock_guard<std::mutex> lock(*m_log_mutex_ptr); | |
| 651 | |||
| 652 | // Close the race where shutdown exchanges the async handle after the first check but before this thread reaches | ||
| 653 | // the synchronous sink. An admitted synchronous write finishes before shutdown can acquire this same mutex. | ||
| 654 | 51850 | if (m_shutdown_called.load(std::memory_order_acquire) || | |
| 655 | 25925 | m_async_writer_abandoned.load(std::memory_order_acquire)) | |
| 656 | { | ||
| 657 | ✗ | m_dropped_messages.fetch_add(1, std::memory_order_relaxed); | |
| 658 | ✗ | return false; | |
| 659 | } | ||
| 660 | |||
| 661 | 25925 | if (m_log_file_stream_ptr->is_open() && m_log_file_stream_ptr->good()) | |
| 662 | { | ||
| 663 | 51834 | *m_log_file_stream_ptr << "[" << get_timestamp(m_timestamp_format) << "] " | |
| 664 | 25917 | << "[" << std::setw(7) << std::left << level_str << "] :: " << message << '\n'; | |
| 665 | |||
| 666 | // Flush on warnings/errors to ensure critical messages survive crashes | ||
| 667 | 25849 | if (level >= LogLevel::Warning) | |
| 668 | { | ||
| 669 | 6858 | m_log_file_stream_ptr->flush(); | |
| 670 | } | ||
| 671 | |||
| 672 | // Report whether the write (and any flush) left the stream healthy, so log_noexcept()/try_log() reflect | ||
| 673 | // actual delivery rather than just a no-throw call. | ||
| 674 | 25849 | const bool delivered = m_log_file_stream_ptr->good(); | |
| 675 | 25849 | if (!delivered) | |
| 676 | { | ||
| 677 | ✗ | m_dropped_messages.fetch_add(1, std::memory_order_relaxed); | |
| 678 | } | ||
| 679 | 25849 | return delivered; | |
| 680 | } | ||
| 681 | |||
| 682 | 8 | if (level >= LogLevel::Error) | |
| 683 | { | ||
| 684 | // std::cerr is shared with the host, so the level field pads by hand and leaves its format flags unchanged. | ||
| 685 | 5 | constexpr std::string_view level_padding{" "}; | |
| 686 | 5 | std::cerr << "[" << m_log_prefix << " LOG_FILE_WRITE_ERROR] [" << get_timestamp(m_timestamp_format) << "] [" | |
| 687 | 10 | << level_str << level_padding.substr(std::min(level_str.size(), level_padding.size())) | |
| 688 | 10 | << "] :: " << message << '\n'; | |
| 689 | } | ||
| 690 | |||
| 691 | // The file sink was closed or unhealthy; the message was not delivered to it (an error-level message reached | ||
| 692 | // stderr only as a last resort). Count it so dropped_count() reflects the loss. | ||
| 693 | 8 | m_dropped_messages.fetch_add(1, std::memory_order_relaxed); | |
| 694 | 8 | return false; | |
| 695 | 25925 | } | |
| 696 | |||
| 697 | 19368 | bool Logger::log_noexcept(LogLevel level, std::string_view message) noexcept | |
| 698 | { | ||
| 699 | // The synchronous sink allocates as it formats a timestamp, and a custom stream can raise. | ||
| 700 | // This wrapper keeps the no-throw contract for noexcept-boundary callers. The bool is log()'s delivery status. | ||
| 701 | try | ||
| 702 | { | ||
| 703 | 19368 | return log(level, message); | |
| 704 | } | ||
| 705 | 67 | catch (...) | |
| 706 | { | ||
| 707 | // log() counts every record it refuses and never throws after counting one, so this catch owns the | ||
| 708 | // records that were lost mid-write, which otherwise leave dropped_count() below the real loss. | ||
| 709 | 67 | m_dropped_messages.fetch_add(1, std::memory_order_relaxed); | |
| 710 | 67 | return false; | |
| 711 | 67 | } | |
| 712 | } | ||
| 713 | |||
| 714 | 30111 | std::string Logger::get_timestamp(const std::string &format) const | |
| 715 | { | ||
| 716 | try | ||
| 717 | { | ||
| 718 | 30111 | const auto now = std::chrono::system_clock::now(); | |
| 719 | 30111 | const auto in_time_t = std::chrono::system_clock::to_time_t(now); | |
| 720 | 30111 | std::tm timeinfo_struct = {}; | |
| 721 | |||
| 722 | #if defined(_MSC_VER) || defined(__MINGW32__) || defined(__MINGW64__) | ||
| 723 | // MinGW's localtime_s takes the same (struct tm *, const time_t *) argument order as MSVC, not the ISO C11 | ||
| 724 | // Annex K order, so the call is identical. | ||
| 725 | 30111 | if (localtime_s(&timeinfo_struct, &in_time_t) != 0) | |
| 726 | { | ||
| 727 | ✗ | throw std::runtime_error("localtime_s failed to convert time."); | |
| 728 | } | ||
| 729 | #else | ||
| 730 | if (localtime_r(&in_time_t, &timeinfo_struct) == nullptr) | ||
| 731 | { | ||
| 732 | throw std::runtime_error("localtime_r failed to convert time."); | ||
| 733 | } | ||
| 734 | #endif | ||
| 735 | // Single stack buffer for timestamp + milliseconds, no heap allocation | ||
| 736 | char buf[134]; | ||
| 737 | 30111 | const size_t len = std::strftime(buf, sizeof(buf) - 5, format.c_str(), &timeinfo_struct); | |
| 738 | 30111 | if (len == 0) | |
| 739 | { | ||
| 740 | ✗ | return "TIMESTAMP_FORMAT_ERROR"; | |
| 741 | } | ||
| 742 | |||
| 743 | 30111 | const auto ms = std::chrono::duration_cast<std::chrono::milliseconds>(now.time_since_epoch()) % 1000; | |
| 744 | 30111 | const int ms_len = std::snprintf(buf + len, 5, ".%03d", static_cast<int>(ms.count())); | |
| 745 | 60222 | return std::string(buf, len + static_cast<size_t>(ms_len)); | |
| 746 | } | ||
| 747 | 71 | catch (const std::exception &e) | |
| 748 | { | ||
| 749 | 142 | std::cerr << "[" << m_log_prefix << " Logger TIMESTAMP_ERROR] Failed to generate timestamp: " << e.what() | |
| 750 | 71 | << '\n'; | |
| 751 | 142 | return "TIMESTAMP_GENERATION_ERROR"; | |
| 752 | 71 | } | |
| 753 | ✗ | catch (...) | |
| 754 | { | ||
| 755 | ✗ | std::cerr << "[" << m_log_prefix | |
| 756 | ✗ | << " Logger TIMESTAMP_ERROR] Unknown exception during timestamp generation." << '\n'; | |
| 757 | ✗ | return "TIMESTAMP_GENERATION_ERROR"; | |
| 758 | ✗ | } | |
| 759 | } | ||
| 760 | |||
| 761 | 3825 | std::wstring Logger::generate_log_file_path(const std::string &file_name) const | |
| 762 | { | ||
| 763 | 3825 | const std::wstring wide_name = detail::widen_utf8(file_name); | |
| 764 | 3823 | if (!file_name.empty() && wide_name.empty()) | |
| 765 | { | ||
| 766 | 3 | std::cerr << "[" << m_log_prefix << " Logger PATH_WARNING] Log file name is not well-formed UTF-8, holds a " | |
| 767 | 3 | << "NUL, or exceeds INT_MAX bytes." << '\n'; | |
| 768 | 3 | return {}; | |
| 769 | } | ||
| 770 | |||
| 771 | 3820 | const std::filesystem::path log_file_path_obj(wide_name); | |
| 772 | 3812 | if (log_file_path_obj.is_absolute()) | |
| 773 | { | ||
| 774 | 651 | return log_file_path_obj.wstring(); | |
| 775 | } | ||
| 776 | |||
| 777 | try | ||
| 778 | { | ||
| 779 | 3161 | std::wstring module_dir = filesystem::get_runtime_directory(); | |
| 780 | 3161 | if (module_dir.empty() || module_dir == L".") | |
| 781 | { | ||
| 782 | ✗ | std::cerr << "[" << m_log_prefix << " Logger PATH_WARNING] " | |
| 783 | ✗ | << "Could not determine module directory. Using relative path: " << file_name << '\n'; | |
| 784 | ✗ | return log_file_path_obj.wstring(); | |
| 785 | } | ||
| 786 | |||
| 787 | 3161 | const std::filesystem::path final_log_path = std::filesystem::path(module_dir) / log_file_path_obj; | |
| 788 | 3161 | return final_log_path.lexically_normal().wstring(); | |
| 789 | 3161 | } | |
| 790 | ✗ | catch (const std::exception &e) | |
| 791 | { | ||
| 792 | ✗ | std::cerr << "[" << m_log_prefix | |
| 793 | ✗ | << " Logger PATH_WARNING] Failed to determine module directory for log file: " << e.what() | |
| 794 | ✗ | << ". Using relative path for log file: " << file_name << '\n'; | |
| 795 | ✗ | return log_file_path_obj.wstring(); | |
| 796 | ✗ | } | |
| 797 | ✗ | catch (...) | |
| 798 | { | ||
| 799 | ✗ | std::cerr << "[" << m_log_prefix | |
| 800 | << " Logger PATH_WARNING] Unknown exception while determining module directory for log file." | ||
| 801 | ✗ | << " Using relative path: " << file_name << '\n'; | |
| 802 | ✗ | return log_file_path_obj.wstring(); | |
| 803 | ✗ | } | |
| 804 | 3825 | } | |
| 805 | |||
| 806 | 5810 | void Logger::enable_async_mode(const AsyncLoggerConfig &config) noexcept | |
| 807 | { | ||
| 808 | // An inert first-use logger has no sink to feed a writer thread; async mode stays unavailable for its | ||
| 809 | // process-lifetime inert state. | ||
| 810 | 5810 | if (is_inert()) | |
| 811 | { | ||
| 812 | 4002 | return; | |
| 813 | } | ||
| 814 | |||
| 815 | 5810 | bool sink_closed = false; | |
| 816 | 5810 | bool activation_failed = false; | |
| 817 | 5810 | bool activated = false; | |
| 818 | 5810 | std::size_t queue_cap = 0; | |
| 819 | 5810 | std::size_t batch_sz = 0; | |
| 820 | |||
| 821 | { | ||
| 822 | 5810 | std::lock_guard<std::mutex> lock(m_async_mutex); | |
| 823 | |||
| 824 | // Refuse to resurrect async logging after shutdown. The check runs under m_async_mutex because | ||
| 825 | // shutdown_internal() drops that mutex before it closes the sink. A configure() inside that window clears | ||
| 826 | // the latch, and shutdown_internal() then retires any writer published there (`[B-48]`). | ||
| 827 | 5810 | if (m_shutdown_called.load(std::memory_order_acquire)) | |
| 828 | { | ||
| 829 | 4001 | return; | |
| 830 | } | ||
| 831 | |||
| 832 | 1809 | if (m_async_writer_abandoned.load(std::memory_order_acquire)) | |
| 833 | { | ||
| 834 | ✗ | return; | |
| 835 | } | ||
| 836 | |||
| 837 | 1809 | if (m_async_mode_enabled.load(std::memory_order_acquire)) | |
| 838 | { | ||
| 839 | 1 | return; | |
| 840 | } | ||
| 841 | |||
| 842 | 1808 | if (!m_log_file_stream_ptr->is_open()) | |
| 843 | { | ||
| 844 | 1 | sink_closed = true; | |
| 845 | } | ||
| 846 | else | ||
| 847 | { | ||
| 848 | try | ||
| 849 | { | ||
| 850 | // Override the config's timestamp format with the Logger's own so the async sink emits the same | ||
| 851 | // timestamps as the synchronous path; callers configure the format through the Logger, not the | ||
| 852 | // async config. | ||
| 853 | 1807 | AsyncLoggerConfig effective_config = config; | |
| 854 | 1807 | effective_config.timestamp_format = m_timestamp_format; | |
| 855 | auto writer = | ||
| 856 | 1807 | std::make_shared<AsyncLogger>(effective_config, m_log_file_stream_ptr, m_log_mutex_ptr); | |
| 857 | |||
| 858 | // Arm the writer's retention root here: after make_shared has established shared ownership (so the | ||
| 859 | // stored copy is a reference into an existing control block, not a new allocation) and before | ||
| 860 | // publication (so the storage a loader-lock detach would need already exists the instant a detach | ||
| 861 | // becomes possible). Break it again on any path that does not publish. An unpublished writer has | ||
| 862 | // no owner left to break it later, so an unbroken root outlives the process for nothing. | ||
| 863 | 1805 | writer->arm_retention_root(writer); | |
| 864 | try | ||
| 865 | { | ||
| 866 | #if defined(DMK_ENABLE_TEST_SEAMS) | ||
| 867 | 1805 | if (auto *publication_probe = detail::g_logger_publication_probe) | |
| 868 | { | ||
| 869 | 3 | publication_probe(); | |
| 870 | } | ||
| 871 | #endif | ||
| 872 | 1802 | m_async_logger.store(writer, std::memory_order_release); | |
| 873 | 1802 | m_async_mode_enabled.store(true, std::memory_order_release); | |
| 874 | } | ||
| 875 | 3 | catch (...) | |
| 876 | { | ||
| 877 | 3 | writer->release_retention_root(); | |
| 878 | 3 | throw; | |
| 879 | 3 | } | |
| 880 | 1802 | activated = true; | |
| 881 | 1802 | queue_cap = config.queue_capacity; | |
| 882 | 1802 | batch_sz = config.batch_size; | |
| 883 | 1810 | } | |
| 884 | 5 | catch (...) | |
| 885 | { | ||
| 886 | // Every throw here occurs before publication. The writer never existed or released its retention | ||
| 887 | // root, so async mode stays off and synchronous delivery remains available. | ||
| 888 | 5 | activation_failed = true; | |
| 889 | 5 | } | |
| 890 | } | ||
| 891 | 5810 | } | |
| 892 | |||
| 893 | #if defined(DMK_ENABLE_TEST_SEAMS) | ||
| 894 | 1808 | if (activated) | |
| 895 | { | ||
| 896 | 1802 | fire_post_publication_probe(); | |
| 897 | } | ||
| 898 | #endif | ||
| 899 | |||
| 900 | // Diagnostics stay outside the mutex. Fixed text through try_log keeps the published path no-throw. | ||
| 901 | 1808 | if (sink_closed) | |
| 902 | { | ||
| 903 | 1 | (void)try_log(LogLevel::Error, "Cannot enable async mode: log file is not open."); | |
| 904 | } | ||
| 905 | 1807 | else if (activation_failed) | |
| 906 | { | ||
| 907 | 5 | (void)try_log(LogLevel::Error, "Failed to enable async mode."); | |
| 908 | } | ||
| 909 | 1802 | else if (activated) | |
| 910 | { | ||
| 911 | 1802 | (void)try_log( | |
| 912 | LogLevel::Info, | ||
| 913 | "Async logging mode enabled. Queue capacity: {}, Batch size: {}", | ||
| 914 | queue_cap, | ||
| 915 | batch_sz | ||
| 916 | ); | ||
| 917 | } | ||
| 918 | } | ||
| 919 | |||
| 920 | 4133 | void Logger::enable_async_mode() noexcept | |
| 921 | { | ||
| 922 | 4133 | enable_async_mode(AsyncLoggerConfig{}); | |
| 923 | 4133 | } | |
| 924 | |||
| 925 | 43 | void Logger::disable_async_mode() noexcept | |
| 926 | { | ||
| 927 | 43 | std::shared_ptr<AsyncLogger> local_async; | |
| 928 | 43 | bool writer_detached = false; | |
| 929 | 43 | bool should_log = false; | |
| 930 | |||
| 931 | { | ||
| 932 | 43 | std::lock_guard<std::mutex> lock(m_async_mutex); | |
| 933 | |||
| 934 | 43 | if (!m_async_mode_enabled.load(std::memory_order_acquire)) | |
| 935 | { | ||
| 936 | 4 | return; | |
| 937 | } | ||
| 938 | |||
| 939 | 39 | local_async = m_async_logger.exchange(nullptr, std::memory_order_acq_rel); | |
| 940 | 39 | if (local_async) | |
| 941 | { | ||
| 942 | 39 | local_async->shutdown(); | |
| 943 | 39 | m_dropped_messages.fetch_add(local_async->dropped_count(), std::memory_order_relaxed); | |
| 944 | 39 | writer_detached = local_async->writer_was_detached(); | |
| 945 | 39 | if (writer_detached) | |
| 946 | { | ||
| 947 | // A detached writer retains final sink ownership. Make every facade operation fail closed rather | ||
| 948 | // than switching to a second synchronous writer on the same sink. | ||
| 949 | 12 | m_async_writer_abandoned.store(true, std::memory_order_release); | |
| 950 | 12 | m_shutdown_called.store(true, std::memory_order_release); | |
| 951 | } | ||
| 952 | else | ||
| 953 | { | ||
| 954 | // Joined: local_async is the external strong owner that makes breaking the root safe. | ||
| 955 | 27 | local_async->release_retention_root(); | |
| 956 | } | ||
| 957 | } | ||
| 958 | |||
| 959 | 39 | m_async_mode_enabled.store(false, std::memory_order_release); | |
| 960 | 39 | should_log = true; | |
| 961 | 43 | } | |
| 962 | |||
| 963 | // Mirror shutdown_internal's ownership rule: a detached writer keeps exclusive access to live AsyncLogger | ||
| 964 | // state, so leave every detached writer standing on the retention root it was published with. The outcome is | ||
| 965 | // recorded under the lifecycle mutex beside the decision it drove, so this teardown and the latches above | ||
| 966 | // cannot disagree about which writer they are describing. | ||
| 967 | 39 | if (writer_detached) | |
| 968 | { | ||
| 969 | 12 | abandon_detached_async_logger(local_async); | |
| 970 | } | ||
| 971 | |||
| 972 | 39 | if (should_log && !writer_detached) | |
| 973 | { | ||
| 974 | // disable_async_mode() is noexcept; the synchronous sink can allocate and throw while formatting this | ||
| 975 | // line. Fail closed: drop the diagnostic rather than letting an exception escape the mode switch. | ||
| 976 | try | ||
| 977 | { | ||
| 978 | 27 | log(LogLevel::Info, "Async logging mode disabled. Switched to synchronous mode."); | |
| 979 | } | ||
| 980 | ✗ | catch (...) | |
| 981 | { | ||
| 982 | ✗ | } | |
| 983 | } | ||
| 984 | 43 | } | |
| 985 | |||
| 986 | 268 | bool Logger::is_async_mode_enabled() const noexcept | |
| 987 | { | ||
| 988 | 268 | return m_async_mode_enabled.load(std::memory_order_acquire); | |
| 989 | } | ||
| 990 | |||
| 991 | 18 | std::size_t Logger::dropped_count() const noexcept | |
| 992 | { | ||
| 993 | 18 | std::size_t total = m_dropped_messages.load(std::memory_order_relaxed); | |
| 994 | 18 | if (m_async_mode_enabled.load(std::memory_order_acquire)) | |
| 995 | { | ||
| 996 | 3 | if (auto async_logger = m_async_logger.load(std::memory_order_acquire)) | |
| 997 | { | ||
| 998 | 3 | total += async_logger->dropped_count(); | |
| 999 | 3 | } | |
| 1000 | } | ||
| 1001 | 18 | return total; | |
| 1002 | } | ||
| 1003 | |||
| 1004 | 216 | void Logger::flush() noexcept | |
| 1005 | { | ||
| 1006 | 216 | if (is_inert() || m_async_writer_abandoned.load(std::memory_order_acquire)) | |
| 1007 | { | ||
| 1008 | 10 | return; | |
| 1009 | } | ||
| 1010 | |||
| 1011 | 215 | if (m_async_mode_enabled.load(std::memory_order_acquire)) | |
| 1012 | { | ||
| 1013 | 9 | auto local_logger = m_async_logger.load(std::memory_order_acquire); | |
| 1014 | 9 | if (local_logger) | |
| 1015 | { | ||
| 1016 | 9 | local_logger->flush(); | |
| 1017 | 9 | return; | |
| 1018 | } | ||
| 1019 | 9 | } | |
| 1020 | |||
| 1021 | 206 | std::lock_guard<std::mutex> lock(*m_log_mutex_ptr); | |
| 1022 | 206 | if (m_log_file_stream_ptr->is_open()) | |
| 1023 | { | ||
| 1024 | 206 | m_log_file_stream_ptr->flush(); | |
| 1025 | } | ||
| 1026 | 206 | } | |
| 1027 | |||
| 1028 | 48779 | Logger &log() noexcept | |
| 1029 | { | ||
| 1030 | // The process-default logger, created once and INTENTIONALLY never destroyed. A plain function-local static | ||
| 1031 | // Logger would be reclaimed during CRT atexit teardown, so a later static destructor or a detached thread that | ||
| 1032 | // logs after that point would touch freed storage. Holding the object behind a leaked pointer keeps it alive | ||
| 1033 | // for the whole process; the pointer itself is a reachable static, so a leak sanitizer sees the allocation as | ||
| 1034 | // still-reachable rather than leaked. shutdown() (invoked by the Session teardown) flushes and closes the sink | ||
| 1035 | // explicitly, so the deliberate leak costs only the object's storage, never a lost flush. First-use | ||
| 1036 | // construction can allocate: create_process_default() catches an out-of-memory failure and publishes an inert | ||
| 1037 | // drop/count logger instead of letting the throw terminate this noexcept accessor. | ||
| 1038 | 48779 | static Logger *const instance = Logger::create_process_default(); | |
| 1039 | 48779 | return *instance; | |
| 1040 | } | ||
| 1041 | |||
| 1042 | 3269 | Logger *Logger::create_process_default() noexcept | |
| 1043 | { | ||
| 1044 | // Prefer the full logger. If its construction throws (first-use OOM allocating the logger object, its sink, | ||
| 1045 | // or its mutex), publish a process-lifetime inert logger rather than letting the throw escape the noexcept | ||
| 1046 | // free log() and terminate the host. The inert logger allocates nothing, so this fallback is safe even while | ||
| 1047 | // allocation is still failing, and it latches for the process generation because this static runs once. | ||
| 1048 | try | ||
| 1049 | { | ||
| 1050 | 3269 | return new Logger(); | |
| 1051 | } | ||
| 1052 | 2 | catch (...) | |
| 1053 | { | ||
| 1054 | alignas(Logger) static unsigned char inert_storage[sizeof(Logger)]; | ||
| 1055 | 2 | return ::new (static_cast<void *>(inert_storage)) Logger(InertTag{}); | |
| 1056 | 2 | } | |
| 1057 | } | ||
| 1058 | |||
| 1059 | } // namespace DetourModKit | ||
| 1060 |