diff --git a/docs/TaskExecutor.md b/docs/TaskExecutor.md index 5074cdc..6d0e046 100644 --- a/docs/TaskExecutor.md +++ b/docs/TaskExecutor.md @@ -75,19 +75,23 @@ end users through `LOGIT_GET_DROPPED_TASKS()`. application. 1. `m_resizing` is set to `true` with release semantics. -2. `wait()` drains the queue and ensures `m_active_tasks == 0`. -3. The worker is stopped by setting `m_stop_flag`, notifying sleepers, and +2. Producers that already entered `add_task()` are allowed to finish or the + resize is abandoned after the bounded resize deadline. +3. `wait()` drains the queue and ensures `m_active_tasks == 0`. +4. The worker is stopped by setting `m_stop_flag`, notifying sleepers, and joining the thread so it no longer touches `m_mpsc_queue`. -4. In a single thread the ring is rebuilt with the new capacity. The resize +5. In a single thread the ring is rebuilt with the new capacity. The resize keeps `m_dropped_tasks` intact but resets `m_active_tasks` to 0 because the queue is empty. -5. The worker thread is restarted and the stop flag cleared. -6. `m_resizing` flips back to `false` and `m_resize_cv.notify_all()` wakes +6. The worker thread is restarted and the stop flag cleared. +7. `m_resizing` flips back to `false` and `m_resize_cv.notify_all()` wakes producers that parked at the start of `add_task()`. -While the resize is in progress, producers briefly wait on `m_resize_cv`. No -accepted tasks are lost, and the consumer thread never observes partially -initialised ring buffers. +While the resize is in progress, new producers briefly wait on `m_resize_cv`. +No accepted tasks are lost, and the consumer thread never observes partially +initialised ring buffers. Calling `set_max_queue_size()` or +`set_queue_policy()` after shutdown is a no-op; these calls must not restart or +mutate the stopped singleton worker. ## 4. Ordering and completion guarantees @@ -96,7 +100,9 @@ initialised ring buffers. * When the ring build is enabled, `DropNewest` and `DropOldest` both drop the incoming task; accepted tasks keep their order. * `wait()` returns once the queue is empty and `m_active_tasks == 0`, or when a - shutdown is requested. + shutdown is requested. In MPSC builds the worker marks a pop attempt active + before removing a task, so `wait()` cannot return in the narrow window between + a dequeued cell becoming free and the task body starting. * `shutdown()` blocks until the worker thread terminates. It is safe to call multiple times. @@ -198,15 +204,16 @@ const auto lost = LOGIT_GET_DROPPED_TASKS(); * All public methods on non-Emscripten builds are thread-safe. Producers may call `add_task()` concurrently with `set_max_queue_size()` and `set_queue_policy()`. -* The hot-resize barrier uses `m_resizing` and `m_resize_cv` so producers never - touch a ring buffer that is being rebuilt. This eliminates the data races that - TSAN previously reported on `try_pop()` vs. buffer assignment. The barrier - only drops once the worker thread fully stops and the queue drains; if a sink - blocks the worker or `QueuePolicy::Block` keeps `m_active_tasks` above the - limit for more than one second, `set_max_queue_size()` abandons the hot - resize, clears `m_resizing`, and leaves the existing ring untouched so - producers cannot wait indefinitely. Non-MPSC builds perform the resize as an - atomic update of `m_max_queue_size`, so they are not subject to this stall. +* The hot-resize barrier uses `m_resizing`, `m_resize_cv`, and an active-producer + counter so producers never touch a ring buffer that is being rebuilt. This + eliminates the data races that TSAN previously reported on `try_pop()` vs. + buffer assignment. The barrier only proceeds once producers have paused, the + worker thread fully stops, and the queue drains; if a sink blocks the worker + or `QueuePolicy::Block` prevents producers from reaching the pause point for + more than one second, `set_max_queue_size()` abandons the hot resize, clears + `m_resizing`, and leaves the existing ring untouched so producers cannot wait + indefinitely. Non-MPSC builds perform the resize as an atomic update of + `m_max_queue_size`, so they are not subject to this stall. * Non-MPSC builds rely solely on mutexes and had no known data races. * The Emscripten path is single-threaded and should not be used concurrently. diff --git a/include/logit_cpp/logit/Logger.hpp b/include/logit_cpp/logit/Logger.hpp index 21d0c4c..dcd3a66 100644 --- a/include/logit_cpp/logit/Logger.hpp +++ b/include/logit_cpp/logit/Logger.hpp @@ -59,7 +59,7 @@ namespace logit { std::unique_ptr logger, std::unique_ptr formatter, bool single_mode = false) { - if (m_shutdown) return; + if (m_shutdown.load(std::memory_order_acquire)) return; auto strategy = std::make_shared(); strategy->logger = std::move(logger); strategy->formatter = std::move(formatter); @@ -67,6 +67,7 @@ namespace logit { strategy->enabled = true; LoggerWriteLock lock(m_loggers_mx); + if (m_shutdown.load(std::memory_order_acquire)) return; m_loggers.push_back(std::move(strategy)); } @@ -157,7 +158,7 @@ namespace logit { /// the formatted message to the logger. /// \param record Log record to be logged. void log(const LogRecord& record) { - if (m_shutdown) return; + if (m_shutdown.load(std::memory_order_acquire)) return; const bool targeted = record.logger_index >= 0; @@ -178,6 +179,7 @@ namespace logit { auto& strategy = snapshot[0]; std::lock_guard exec_lock(strategy->exec_mx); + if (m_shutdown.load(std::memory_order_acquire)) return; if (!strategy->enabled) return; if (!record.raw_mode && static_cast(record.log_level) < static_cast(strategy->logger->get_log_level())) return; @@ -189,6 +191,7 @@ namespace logit { if (!strategy) continue; std::lock_guard exec_lock(strategy->exec_mx); + if (m_shutdown.load(std::memory_order_acquire)) return; if (strategy->single_mode) continue; if (!strategy->enabled) continue; if (!record.raw_mode && @@ -400,7 +403,7 @@ namespace logit { /// Disables further logging, waits for asynchronous tasks to complete, /// and shuts down TaskExecutor. void shutdown() { - if (m_shutdown.exchange(true)) return; + if (m_shutdown.exchange(true, std::memory_order_acq_rel)) return; const auto snapshot = get_all_strategy_snapshots(); for (const auto& strategy : snapshot) { diff --git a/include/logit_cpp/logit/detail/TaskExecutor.hpp b/include/logit_cpp/logit/detail/TaskExecutor.hpp index 6893cbd..dcdce2b 100644 --- a/include/logit_cpp/logit/detail/TaskExecutor.hpp +++ b/include/logit_cpp/logit/detail/TaskExecutor.hpp @@ -211,21 +211,14 @@ namespace logit { namespace detail { lock.unlock(); m_queue_condition.notify_one(); # else - // Hot-resize barrier: wait until the ring rebuild is finished. - if (m_resizing.load(std::memory_order_acquire)) { - std::unique_lock lk(m_cv_mutex); - m_resize_cv.wait(lk, [this]{ return !m_resizing.load(std::memory_order_acquire); }); - } - - if (m_stop_flag.load(std::memory_order_acquire)) { - return; - } + enter_producer_(); std::function local_task = std::move(task); + bool done = false; - for (;;) { + while (!done) { if (m_stop_flag.load(std::memory_order_acquire)) { - return; + break; } const auto policy = m_overflow_policy.load(std::memory_order_relaxed); @@ -243,20 +236,22 @@ namespace logit { namespace detail { // Try to push into the ring buffer. if (m_mpsc_queue.try_push(local_task)) { m_cv.notify_one(); // wake the worker - return; + break; } // Apply the configured overflow policy when the ring is full. switch (policy) { case QueuePolicy::DropNewest: m_dropped_tasks.fetch_add(1, std::memory_order_relaxed); - return; + done = true; + break; case QueuePolicy::DropOldest: // Safe MPSC behaviour: drop the incoming task. // Preserves ordering and avoids producer/consumer deadlocks. m_dropped_tasks.fetch_add(1, std::memory_order_relaxed); - return; + done = true; + break; case QueuePolicy::Block: { std::unique_lock lk(m_cv_mutex); @@ -265,6 +260,7 @@ namespace logit { namespace detail { } } } + leave_producer_(); # endif } @@ -289,6 +285,7 @@ namespace logit { namespace detail { /// \brief Stop the worker thread and drain outstanding tasks. void shutdown() { + std::lock_guard lifecycle_lock(m_lifecycle_mutex); # ifndef LOGIT_USE_MPSC_RING std::unique_lock lock(m_queue_mutex); m_stop_flag.store(true, std::memory_order_release); @@ -314,17 +311,26 @@ namespace logit { namespace detail { /// \details On MPSC builds this performs the "hot" resize described in /// docs/TaskExecutor.md. void set_max_queue_size(std::size_t size) { + std::lock_guard lifecycle_lock(m_lifecycle_mutex); + if (m_stop_flag.load(std::memory_order_acquire)) return; # ifdef LOGIT_USE_MPSC_RING // Tell producers to pause before any wait()/stop conditions run. m_resizing.store(true, std::memory_order_release); + const auto deadline = std::chrono::steady_clock::now() + + std::chrono::seconds(1); + // Existing producers may be blocked by backpressure, so do not + // wait forever for the resize barrier. + if (!wait_until_producers_paused_(deadline)) { + m_resizing.store(false, std::memory_order_release); + m_resize_cv.notify_all(); + return; + } // Drain the queue completely, but do not wait forever if the worker // is stalled (e.g., blocked sink or backpressure keeping // m_active_tasks > 0). If we fail to drain before the deadline, // abort the resize and re-open the barrier so producers can // continue. - const auto deadline = std::chrono::steady_clock::now() + - std::chrono::seconds(1); if (!wait_until_idle_(deadline)) { m_resizing.store(false, std::memory_order_release); m_resize_cv.notify_all(); @@ -334,7 +340,7 @@ namespace logit { namespace detail { // Stop the worker so it cannot touch m_mpsc_queue during the resize. std::unique_lock lk(m_queue_mutex); m_stop_flag.store(true, std::memory_order_relaxed); - lk.unlock(); + lk.unlock(); m_cv.notify_all(); m_queue_condition.notify_all(); @@ -343,15 +349,15 @@ namespace logit { namespace detail { } // Reinitialise the parameters and the ring on a single thread. - lk.lock(); - m_max_queue_size = size; - const std::size_t cap = - (m_max_queue_size == 0 ? m_default_ring_cap : m_max_queue_size); - m_mpsc_queue = MpscRingAny>(cap); - // Reset counters (except drops) because the queue is empty. - m_active_tasks.store(0, std::memory_order_relaxed); - // Keep m_dropped_tasks untouched — tests manage it via macros. - lk.unlock(); + lk.lock(); + m_max_queue_size = size; + const std::size_t cap = + (m_max_queue_size == 0 ? m_default_ring_cap : m_max_queue_size); + m_mpsc_queue = MpscRingAny>(cap); + // Reset counters (except drops) because the queue is empty. + m_active_tasks.store(0, std::memory_order_relaxed); + // Keep m_dropped_tasks untouched; tests manage it via macros. + lk.unlock(); // Clear the stop flag and restart the worker thread. m_stop_flag.store(false, std::memory_order_relaxed); @@ -368,6 +374,8 @@ namespace logit { namespace detail { /// \brief Change the overflow policy for newly submitted tasks. void set_queue_policy(QueuePolicy policy) { + std::lock_guard lifecycle_lock(m_lifecycle_mutex); + if (m_stop_flag.load(std::memory_order_acquire)) return; std::lock_guard lock(m_queue_mutex); m_overflow_policy.store(policy, std::memory_order_relaxed); } @@ -382,6 +390,7 @@ namespace logit { namespace detail { } private: + mutable std::mutex m_lifecycle_mutex; ///< Serializes shutdown with lifecycle-changing operations. #ifndef LOGIT_USE_MPSC_RING std::deque> m_tasks_queue; mutable std::mutex m_queue_mutex; @@ -401,6 +410,7 @@ namespace logit { namespace detail { std::atomic m_resizing; ///< true while a hot resize is in flight. std::condition_variable m_resize_cv; ///< Producers wait here during a resize. + std::atomic m_active_producers; ///< Producers currently touching the ring. std::thread m_worker_thread; std::atomic m_stop_flag; @@ -445,9 +455,17 @@ namespace logit { namespace detail { std::function task; int budget = LOGIT_TASK_EXECUTOR_DRAIN_BUDGET; - while (budget-- && m_mpsc_queue.try_pop(task)) { - drained_any = true; + while (budget--) { + // Count the pop attempt as active so wait() cannot observe + // an empty ring between try_pop() freeing a cell and the + // dequeued task starting execution. m_active_tasks.fetch_add(1, std::memory_order_relaxed); + if (!m_mpsc_queue.try_pop(task)) { + m_active_tasks.fetch_sub(1, std::memory_order_relaxed); + break; + } + + drained_any = true; task(); @@ -488,6 +506,38 @@ namespace logit { namespace detail { m_stop_flag.load(std::memory_order_acquire)); }); } + + void enter_producer_() { + for (;;) { + if (m_resizing.load(std::memory_order_acquire)) { + std::unique_lock lk(m_cv_mutex); + m_resize_cv.wait(lk, [this]() { + return !m_resizing.load(std::memory_order_acquire); + }); + continue; + } + + m_active_producers.fetch_add(1, std::memory_order_acq_rel); + if (!m_resizing.load(std::memory_order_acquire)) { + return; + } + leave_producer_(); + } + } + + void leave_producer_() { + if (m_active_producers.fetch_sub(1, std::memory_order_acq_rel) == 1 && + m_resizing.load(std::memory_order_acquire)) { + m_resize_cv.notify_all(); + } + } + + bool wait_until_producers_paused_(std::chrono::steady_clock::time_point deadline) { + std::unique_lock lk(m_cv_mutex); + return m_resize_cv.wait_until(lk, deadline, [this]() { + return m_active_producers.load(std::memory_order_acquire) == 0; + }); + } #endif TaskExecutor() @@ -499,6 +549,7 @@ namespace logit { namespace detail { m_active_tasks(0) #else : m_resizing(false), + m_active_producers(0), m_worker_thread(), m_stop_flag(false), m_max_queue_size(0), diff --git a/include/logit_cpp/logit/loggers/ConsoleLogger.hpp b/include/logit_cpp/logit/loggers/ConsoleLogger.hpp index 350b028..0693988 100644 --- a/include/logit_cpp/logit/loggers/ConsoleLogger.hpp +++ b/include/logit_cpp/logit/loggers/ConsoleLogger.hpp @@ -121,6 +121,7 @@ namespace logit { std::shared_ptr old_executor; { std::unique_lock lock(m_mutex); + if (m_shutdown.load(std::memory_order_acquire)) return; wait_for_pending_enqueues(lock); m_config = config; if (m_config.async && m_config.use_dedicated_executor) { @@ -154,9 +155,11 @@ namespace logit { /// \param record The log record containing log information. /// \param message The formatted log message. void log(const LogRecord& record, const std::string& message) override { - m_last_log_ts = record.timestamp_ms; + if (m_shutdown.load(std::memory_order_acquire)) return; #ifdef __EMSCRIPTEN__ std::unique_lock lock(m_mutex); + if (m_shutdown.load(std::memory_order_acquire)) return; + m_last_log_ts = record.timestamp_ms; const int lvl = static_cast(record.log_level); std::shared_ptr executor = m_executor; if (!m_config.async) { @@ -194,6 +197,8 @@ namespace logit { return; #else std::unique_lock lock(m_mutex); + if (m_shutdown.load(std::memory_order_acquire)) return; + m_last_log_ts = record.timestamp_ms; std::shared_ptr executor = m_executor; if (!m_config.async) { # if defined(_WIN32) @@ -306,6 +311,7 @@ namespace logit { /// \brief Stops the dedicated executor after draining pending messages. void shutdown() override { + if (m_shutdown.exchange(true, std::memory_order_acq_rel)) return; std::shared_ptr executor; bool async = false; { @@ -327,6 +333,7 @@ namespace logit { Config m_config; ///< Configuration for the console logger. std::atomic m_last_log_ts = ATOMIC_VAR_INIT(0); std::atomic m_log_level = ATOMIC_VAR_INIT(static_cast(LogLevel::LOG_LVL_TRACE)); + std::atomic m_shutdown = ATOMIC_VAR_INIT(false); std::shared_ptr m_executor; std::condition_variable m_enqueue_cv; std::size_t m_pending_enqueues = 0; diff --git a/include/logit_cpp/logit/loggers/EventLogLogger.hpp b/include/logit_cpp/logit/loggers/EventLogLogger.hpp index 8ae75d6..a7f0583 100644 --- a/include/logit_cpp/logit/loggers/EventLogLogger.hpp +++ b/include/logit_cpp/logit/loggers/EventLogLogger.hpp @@ -6,6 +6,7 @@ #include #include #include +#include /// \file EventLogLogger.hpp /// \brief Logger writing to Windows Event Log. @@ -80,6 +81,8 @@ namespace logit { /// \param rec Log metadata. /// \param msg UTF-8 message text. void log(const LogRecord& rec, const std::string& msg) override { + std::lock_guard lifecycle_lock(m_lifecycle_mutex); + if (m_shutdown.load(std::memory_order_acquire)) return; LogLevel lvl = rec.raw_mode ? LogLevel::LOG_LVL_INFO : rec.log_level; bool raw_mode = rec.raw_mode; std::string s = msg; @@ -125,7 +128,17 @@ namespace logit { void wait() override { if (m_cfg.async) { if (m_executor) { m_executor->wait(); } else { detail::TaskExecutor::get_instance().wait(); } } } /// \brief Stops logger-owned asynchronous resources after draining pending messages. - void shutdown() override { if (m_executor) { m_executor->shutdown(); } else if (m_cfg.async) { detail::TaskExecutor::get_instance().wait(); } } + void shutdown() override { + { + std::lock_guard lifecycle_lock(m_lifecycle_mutex); + if (m_shutdown.exchange(true, std::memory_order_acq_rel)) return; + } + if (m_executor) { + m_executor->shutdown(); + } else if (m_cfg.async) { + detail::TaskExecutor::get_instance().wait(); + } + } private: static WORD m_map(LogLevel l) { @@ -139,9 +152,11 @@ namespace logit { } return EVENTLOG_INFORMATION_TYPE; } Config m_cfg{}; + std::mutex m_lifecycle_mutex; HANDLE m_hsrc = nullptr; std::atomic m_level{static_cast(LogLevel::LOG_LVL_TRACE)}; std::atomic m_last_ts{0}; + std::atomic m_shutdown{false}; std::unique_ptr m_executor; static Config make_config( @@ -227,4 +242,3 @@ namespace logit { } // namespace logit #endif - diff --git a/include/logit_cpp/logit/loggers/FileLogger.hpp b/include/logit_cpp/logit/loggers/FileLogger.hpp index 1e7629f..f0470a1 100644 --- a/include/logit_cpp/logit/loggers/FileLogger.hpp +++ b/include/logit_cpp/logit/loggers/FileLogger.hpp @@ -207,6 +207,8 @@ namespace logit { /// \param record The log record containing log information. /// \param message The formatted log message. void log(const LogRecord& record, const std::string& message) override { + std::lock_guard lifecycle_lock(m_lifecycle_mutex); + if (m_shutdown.load(std::memory_order_acquire)) return; m_last_log_ts = record.timestamp_ms; m_last_log_mono_ts = LOGIT_MONOTONIC_MS(); if (!m_config.async) { @@ -400,6 +402,10 @@ namespace logit { /// \brief Stops logger-owned asynchronous resources after draining pending writes. void shutdown() override { + { + std::lock_guard lifecycle_lock(m_lifecycle_mutex); + if (m_shutdown.exchange(true, std::memory_order_acq_rel)) return; + } if (m_executor) { m_executor->shutdown(); std::lock_guard lock(m_mutex); @@ -411,6 +417,7 @@ namespace logit { private: mutable std::mutex m_mutex; ///< Mutex to protect file operations. + std::mutex m_lifecycle_mutex; ///< Serializes direct log() calls with shutdown(). Config m_config; ///< Configuration for the file logger. mutable std::ofstream m_file; ///< Output file stream for logging. mutable std::mutex m_file_path_mutex; ///< Mutex to protect file path operations. @@ -423,6 +430,7 @@ namespace logit { std::atomic m_last_log_ts = ATOMIC_VAR_INIT(0); ///< Timestamp of the last log. std::atomic m_last_log_mono_ts = ATOMIC_VAR_INIT(0); ///< Timestamp of the last log. std::atomic m_log_level = ATOMIC_VAR_INIT(static_cast(LogLevel::LOG_LVL_TRACE)); + std::atomic m_shutdown = ATOMIC_VAR_INIT(false); static Config make_config( const std::string& directory, diff --git a/include/logit_cpp/logit/loggers/OtlpHttpLogger.hpp b/include/logit_cpp/logit/loggers/OtlpHttpLogger.hpp index 2d8fe2f..a1f2ff2 100644 --- a/include/logit_cpp/logit/loggers/OtlpHttpLogger.hpp +++ b/include/logit_cpp/logit/loggers/OtlpHttpLogger.hpp @@ -72,6 +72,12 @@ namespace logit { /// \param record Structured log record. /// \param message Formatted log message used as OTLP body. void log(const LogRecord& record, const std::string& message) override { + std::unique_lock lifecycle_lock(m_lifecycle_mutex); + + if (m_stopping) { + ++m_dropped; + return; + } m_last_log_ts = record.timestamp_ms; OtlpLogItem item; @@ -85,27 +91,39 @@ namespace logit { return; } - std::unique_lock lock(m_mutex); - - if (m_queue.size() >= m_config.max_queue_size) { - if (m_config.drop_on_overflow) { + for (;;) { + std::unique_lock lock(m_mutex); + if (m_stopping) { ++m_dropped; return; } - m_cv_space.wait(lock, [this]() { - return m_stopping || m_queue.size() < m_config.max_queue_size; - }); + if (m_queue.size() >= m_config.max_queue_size) { + if (m_config.drop_on_overflow) { + ++m_dropped; + return; + } - if (m_stopping) { - ++m_dropped; - return; + lifecycle_lock.unlock(); + m_cv_space.wait(lock, [this]() { + return m_stopping || m_queue.size() < m_config.max_queue_size; + }); + lock.unlock(); + lifecycle_lock.lock(); + + if (m_stopping) { + ++m_dropped; + return; + } + + continue; } - } - m_queue.push_back(item); - lock.unlock(); - m_cv.notify_one(); + m_queue.push_back(item); + lock.unlock(); + m_cv.notify_one(); + return; + } } /// \brief Waits until queued and in-flight exports finish. @@ -120,6 +138,11 @@ namespace logit { }); } + /// \brief Stops the OTLP worker after draining queued exports. + void shutdown() override { + stop(); + } + /// \brief Retrieves a string parameter from the logger. /// \param param Parameter to retrieve. /// \return Parameter value, or empty string when unsupported. @@ -197,6 +220,7 @@ namespace logit { OtlpHttpLoggerConfig m_config; ///< Export configuration. kurlyk::HttpClient m_client; ///< HTTP client used for OTLP export. + mutable std::mutex m_lifecycle_mutex;///< Serializes log() with shutdown. mutable std::mutex m_mutex; ///< Protects queue and worker state. std::condition_variable m_cv; ///< Signals queued records. std::condition_variable m_cv_space; ///< Signals available queue space. @@ -204,7 +228,7 @@ namespace logit { std::deque m_queue; ///< Pending records. std::thread m_worker; ///< Export worker thread. - bool m_stopping = false; ///< Stop flag protected by m_mutex. + bool m_stopping = false; ///< Stop flag protected by lifecycle/mutex locks. std::size_t m_in_flight = 0; ///< Number of batches currently being exported. std::atomic m_log_level = ATOMIC_VAR_INIT(static_cast(LogLevel::LOG_LVL_TRACE)); @@ -289,6 +313,7 @@ namespace logit { /// \brief Stops worker and cancels pending requests. void stop() { + std::lock_guard lifecycle_lock(m_lifecycle_mutex); { std::lock_guard lock(m_mutex); if (m_stopping) { diff --git a/include/logit_cpp/logit/loggers/SyslogLogger.hpp b/include/logit_cpp/logit/loggers/SyslogLogger.hpp index ae9f58e..25fbb5f 100644 --- a/include/logit_cpp/logit/loggers/SyslogLogger.hpp +++ b/include/logit_cpp/logit/loggers/SyslogLogger.hpp @@ -6,6 +6,7 @@ #include #include #include +#include /// \file SyslogLogger.hpp /// \brief Logger writing to system syslog. @@ -86,6 +87,8 @@ namespace logit { /// \param rec Log metadata. /// \param msg Formatted message. void log(const LogRecord& rec, const std::string& msg) override { + std::lock_guard lifecycle_lock(m_lifecycle_mutex); + if (m_shutdown.load(std::memory_order_acquire)) return; LogLevel lvl = rec.raw_mode ? LogLevel::LOG_LVL_INFO : rec.log_level; bool raw_mode = rec.raw_mode; std::string s = msg; @@ -124,7 +127,17 @@ namespace logit { void wait() override { if (m_cfg.async) { if (m_executor) { m_executor->wait(); } else { detail::TaskExecutor::get_instance().wait(); } } } /// \brief Stops logger-owned asynchronous resources after draining pending messages. - void shutdown() override { if (m_executor) { m_executor->shutdown(); } else if (m_cfg.async) { detail::TaskExecutor::get_instance().wait(); } } + void shutdown() override { + { + std::lock_guard lifecycle_lock(m_lifecycle_mutex); + if (m_shutdown.exchange(true, std::memory_order_acq_rel)) return; + } + if (m_executor) { + m_executor->shutdown(); + } else if (m_cfg.async) { + detail::TaskExecutor::get_instance().wait(); + } + } private: static int m_map(LogLevel l) { @@ -138,8 +151,10 @@ namespace logit { } return LOG_INFO; } Config m_cfg{}; + std::mutex m_lifecycle_mutex; std::atomic m_level{static_cast(LogLevel::LOG_LVL_TRACE)}; std::atomic m_last_ts{0}; + std::atomic m_shutdown{false}; std::unique_ptr m_executor; static Config make_config( @@ -228,4 +243,3 @@ namespace logit { } // namespace logit #endif - diff --git a/include/logit_cpp/logit/loggers/UniqueFileLogger.hpp b/include/logit_cpp/logit/loggers/UniqueFileLogger.hpp index ffeb38e..450f833 100644 --- a/include/logit_cpp/logit/loggers/UniqueFileLogger.hpp +++ b/include/logit_cpp/logit/loggers/UniqueFileLogger.hpp @@ -155,6 +155,8 @@ namespace logit { /// \param record The log record containing log information. /// \param message The log message to write. void log(const LogRecord& record, const std::string& message) override { + std::lock_guard lifecycle_lock(m_lifecycle_mutex); + if (m_shutdown.load(std::memory_order_acquire)) return; auto thread_id = record.thread_id; m_last_log_ts = record.timestamp_ms; m_last_log_mono_ts = LOGIT_MONOTONIC_MS(); @@ -309,6 +311,10 @@ namespace logit { /// \brief Stops logger-owned asynchronous resources after draining pending writes. void shutdown() override { + { + std::lock_guard lifecycle_lock(m_lifecycle_mutex); + if (m_shutdown.exchange(true, std::memory_order_acq_rel)) return; + } if (m_executor) { m_executor->shutdown(); } else if (m_config.async) { @@ -318,6 +324,7 @@ namespace logit { private: mutable std::mutex m_mutex; ///< Mutex to protect file operations. + std::mutex m_lifecycle_mutex; ///< Serializes direct log() calls with shutdown(). Config m_config; ///< Configuration for the unique file logger. std::unique_ptr m_executor; ///< Dedicated executor (null = use global). @@ -345,6 +352,7 @@ namespace logit { std::atomic m_last_log_ts = ATOMIC_VAR_INIT(0); ///< Timestamp of the last log. std::atomic m_last_log_mono_ts = ATOMIC_VAR_INIT(0); ///< Timestamp of the last log. std::atomic m_log_level = ATOMIC_VAR_INIT(static_cast(LogLevel::LOG_LVL_TRACE)); + std::atomic m_shutdown = ATOMIC_VAR_INIT(false); static Config make_config( const std::string& directory, diff --git a/include/logit_cpp/logit/loggers/WindowsDebugLogger.hpp b/include/logit_cpp/logit/loggers/WindowsDebugLogger.hpp index 55207e0..b23d595 100644 --- a/include/logit_cpp/logit/loggers/WindowsDebugLogger.hpp +++ b/include/logit_cpp/logit/loggers/WindowsDebugLogger.hpp @@ -10,6 +10,7 @@ #include #include #include +#include #if defined(_WIN32) #include @@ -86,6 +87,8 @@ namespace logit { /// \param record The log record containing log information. /// \param message The formatted log message. void log(const LogRecord& record, const std::string& message) override { + std::lock_guard lifecycle_lock(m_lifecycle_mutex); + if (m_shutdown.load(std::memory_order_acquire)) return; if (m_config.async) { if (m_executor) { m_executor->add_task([message]() { @@ -163,6 +166,10 @@ namespace logit { /// \brief Stops logger-owned asynchronous resources after draining pending messages. void shutdown() override { + { + std::lock_guard lifecycle_lock(m_lifecycle_mutex); + if (m_shutdown.exchange(true, std::memory_order_acq_rel)) return; + } if (m_executor) { m_executor->shutdown(); } else if (m_config.async) { @@ -172,8 +179,10 @@ namespace logit { private: Config m_config; + std::mutex m_lifecycle_mutex; std::atomic m_log_level{static_cast(LogLevel::LOG_LVL_TRACE)}; std::atomic m_last_log_ts{0}; + std::atomic m_shutdown{false}; std::unique_ptr m_executor; static Config make_config( diff --git a/include/logit_cpp/logit/loggers/otlp/OtlpJsonSerializer.hpp b/include/logit_cpp/logit/loggers/otlp/OtlpJsonSerializer.hpp index 82a98dd..09d91c5 100644 --- a/include/logit_cpp/logit/loggers/otlp/OtlpJsonSerializer.hpp +++ b/include/logit_cpp/logit/loggers/otlp/OtlpJsonSerializer.hpp @@ -7,7 +7,6 @@ #include "OtlpHttpLoggerConfig.hpp" #include "OtlpRecordSnapshot.hpp" -#include "../../enums.hpp" #include #include #include diff --git a/include/logit_cpp/logit/loggers/otlp/OtlpRecordSnapshot.hpp b/include/logit_cpp/logit/loggers/otlp/OtlpRecordSnapshot.hpp index fc1ede6..b2c6e83 100644 --- a/include/logit_cpp/logit/loggers/otlp/OtlpRecordSnapshot.hpp +++ b/include/logit_cpp/logit/loggers/otlp/OtlpRecordSnapshot.hpp @@ -5,7 +5,7 @@ /// \file OtlpRecordSnapshot.hpp /// \brief Defines a stable snapshot of LogRecord data for asynchronous OTLP export. -#include "../../utils.hpp" +#include #include #include #include diff --git a/tests/backend_shutdown_terminal_test.cpp b/tests/backend_shutdown_terminal_test.cpp new file mode 100644 index 0000000..8debce5 --- /dev/null +++ b/tests/backend_shutdown_terminal_test.cpp @@ -0,0 +1,118 @@ +#include + +#include +#include +#include +#include + +namespace { + +logit::LogRecord make_record() { + return logit::LogRecord( + logit::LogLevel::LOG_LVL_INFO, + LOGIT_CURRENT_TIMESTAMP_MS(), + __FILE__, + __LINE__, + __func__, + "", + "", + -1, + false); +} + +bool file_logger_ignores_log_after_shutdown(bool dedicated) { + logit::FileLogger::Config cfg; + cfg.directory = std::string("backend_shutdown_file_") + + (dedicated ? "dedicated_" : "global_") + + std::to_string(LOGIT_CURRENT_TIMESTAMP_MS()); + cfg.async = true; + cfg.auto_delete_days = 1; + cfg.use_dedicated_executor = dedicated; + cfg.queue_capacity = 4; + cfg.queue_policy = logit::detail::QueuePolicy::Block; + + logit::FileLogger logger(cfg); + const logit::LogRecord rec = make_record(); + logger.log(rec, "before shutdown"); + logger.shutdown(); + logger.log(rec, "after shutdown"); + logger.wait(); + + const std::vector files = logger.list_log_files(); + if (files.empty()) { + return false; + } + + std::string content; + for (std::size_t i = 0; i < files.size(); ++i) { + const logit::LogFileReadResult result = logger.read_log_file(files[i].path); + if (result.ok) { + content += result.content; + } + } + + return content.find("before shutdown") != std::string::npos && + content.find("after shutdown") == std::string::npos; +} + +bool unique_file_logger_ignores_log_after_shutdown() { + logit::UniqueFileLogger::Config cfg; + cfg.directory = std::string("backend_shutdown_unique_") + + std::to_string(LOGIT_CURRENT_TIMESTAMP_MS()); + cfg.async = true; + cfg.auto_delete_days = 1; + cfg.hash_length = 8; + cfg.use_dedicated_executor = true; + cfg.queue_capacity = 4; + cfg.queue_policy = logit::detail::QueuePolicy::Block; + + logit::UniqueFileLogger logger(cfg); + const logit::LogRecord rec = make_record(); + logger.log(rec, "before shutdown"); + logger.shutdown(); + const std::vector before = logger.list_log_files(); + logger.log(rec, "after shutdown"); + logger.wait(); + const std::vector after = logger.list_log_files(); + + return !before.empty() && after.size() == before.size(); +} + +bool simple_async_backends_ignore_log_after_shutdown() { + const logit::LogRecord rec = make_record(); + + logit::ConsoleLogger::Config console_cfg; + console_cfg.async = true; + console_cfg.use_dedicated_executor = true; + console_cfg.queue_capacity = 4; + console_cfg.queue_policy = logit::detail::QueuePolicy::Block; + logit::ConsoleLogger console(console_cfg); + console.log(rec, "console before shutdown"); + console.shutdown(); + console.log(rec, "console after shutdown"); + console.wait(); + + logit::WindowsDebugLogger::Config debug_cfg(true); + debug_cfg.use_dedicated_executor = true; + debug_cfg.queue_capacity = 4; + debug_cfg.queue_policy = logit::detail::QueuePolicy::Block; + logit::WindowsDebugLogger debug(debug_cfg); + debug.log(rec, "debug before shutdown"); + debug.shutdown(); + debug.log(rec, "debug after shutdown"); + debug.wait(); + + return true; +} + +} // namespace + +int main() { + const bool ok = file_logger_ignores_log_after_shutdown(false) && + file_logger_ignores_log_after_shutdown(true) && + unique_file_logger_ignores_log_after_shutdown() && + simple_async_backends_ignore_log_after_shutdown(); + + std::cout << (ok ? "PASS" : "FAIL") << ": backend_shutdown_terminal" << std::endl; + return ok ? 0 : 1; +} diff --git a/tests/ems/single_thread_executor.cpp b/tests/ems/single_thread_executor.cpp index e788c06..d50a322 100644 --- a/tests/ems/single_thread_executor.cpp +++ b/tests/ems/single_thread_executor.cpp @@ -1,15 +1,83 @@ #include #include +#include int main() { - logit::detail::SingleThreadExecutor executor; - std::atomic counter{0}; + { + logit::detail::SingleThreadExecutor executor; + std::atomic counter{0}; - executor.add_task([&counter]() { - counter.fetch_add(1, std::memory_order_relaxed); - }); - executor.wait(); + executor.add_task([&counter]() { + counter.fetch_add(1, std::memory_order_relaxed); + }); + executor.wait(); - return counter.load(std::memory_order_relaxed) == 1 ? 0 : 1; + if (counter.load(std::memory_order_relaxed) != 1) { + return 1; + } + } + + { + logit::detail::SingleThreadExecutor executor; + executor.set_max_queue_size(2); + executor.set_queue_policy(logit::detail::QueuePolicy::DropNewest); + std::atomic counter{0}; + + executor.add_task([&counter]() { counter.fetch_add(1, std::memory_order_relaxed); }); + executor.add_task([&counter]() { counter.fetch_add(1, std::memory_order_relaxed); }); + executor.add_task([&counter]() { counter.fetch_add(1, std::memory_order_relaxed); }); + executor.wait(); + + if (counter.load(std::memory_order_relaxed) != 2 || executor.dropped_tasks() != 1) { + return 2; + } + } + + { + logit::detail::SingleThreadExecutor executor; + executor.set_max_queue_size(2); + executor.set_queue_policy(logit::detail::QueuePolicy::DropOldest); + std::vector order; + + executor.add_task([&order]() { order.push_back(1); }); + executor.add_task([&order]() { order.push_back(2); }); + executor.add_task([&order]() { order.push_back(3); }); + executor.wait(); + + if (order.size() != 2 || order[0] != 2 || order[1] != 3 || + executor.dropped_tasks() != 1) { + return 3; + } + } + + { + logit::detail::SingleThreadExecutor executor; + executor.set_max_queue_size(1); + executor.set_queue_policy(logit::detail::QueuePolicy::Block); + std::atomic counter{0}; + + executor.add_task([&counter]() { counter.fetch_add(1, std::memory_order_relaxed); }); + executor.add_task([&counter]() { counter.fetch_add(1, std::memory_order_relaxed); }); + executor.wait(); + + if (counter.load(std::memory_order_relaxed) != 2 || executor.dropped_tasks() != 0) { + return 4; + } + } + + { + logit::detail::SingleThreadExecutor executor; + std::atomic counter{0}; + + executor.add_task([&counter]() { counter.fetch_add(1, std::memory_order_relaxed); }); + executor.shutdown(); + executor.add_task([&counter]() { counter.fetch_add(1, std::memory_order_relaxed); }); + + if (counter.load(std::memory_order_relaxed) != 1) { + return 5; + } + } + + return 0; } diff --git a/tests/logger_shutdown_race_test.cpp b/tests/logger_shutdown_race_test.cpp new file mode 100644 index 0000000..533663d --- /dev/null +++ b/tests/logger_shutdown_race_test.cpp @@ -0,0 +1,103 @@ +#include + +#include +#include +#include +#include +#include +#include +#include +#include + +namespace { + +class ShutdownRaceLogger final : public logit::ILogger { +public: + void log(const logit::LogRecord&, const std::string&) override { + if (m_shutdown_started.load(std::memory_order_acquire)) { + m_logs_after_shutdown.fetch_add(1, std::memory_order_relaxed); + } + m_logs.fetch_add(1, std::memory_order_relaxed); + } + + std::string get_string_param(const logit::LoggerParam&) const override { + return std::string(); + } + + int64_t get_int_param(const logit::LoggerParam&) const override { + return 0; + } + + double get_float_param(const logit::LoggerParam&) const override { + return 0.0; + } + + void set_log_level(logit::LogLevel level) override { + m_level.store(static_cast(level), std::memory_order_relaxed); + } + + logit::LogLevel get_log_level() const override { + return static_cast(m_level.load(std::memory_order_relaxed)); + } + + void wait() override {} + + void shutdown() override { + m_shutdown_started.store(true, std::memory_order_release); + std::this_thread::sleep_for(std::chrono::milliseconds(10)); + } + + std::size_t logs_after_shutdown() const { + return m_logs_after_shutdown.load(std::memory_order_relaxed); + } + + bool shutdown_started() const { + return m_shutdown_started.load(std::memory_order_acquire); + } + +private: + std::atomic m_level{static_cast(logit::LogLevel::LOG_LVL_TRACE)}; + std::atomic m_logs{0}; + std::atomic m_logs_after_shutdown{0}; + std::atomic m_shutdown_started{false}; +}; + +} // namespace + +int main() { + ShutdownRaceLogger* raw_logger = new ShutdownRaceLogger(); + logit::Logger::get_instance().add_logger( + std::unique_ptr(raw_logger), + std::unique_ptr( + new logit::SimpleLogFormatter("%v"))); + + std::atomic start(false); + std::atomic stop(false); + std::vector producers; + for (int i = 0; i < 4; ++i) { + producers.emplace_back([&start, &stop]() { + while (!start.load(std::memory_order_acquire)) { + std::this_thread::yield(); + } + while (!stop.load(std::memory_order_acquire)) { + LOGIT_INFO("shutdown race"); + } + }); + } + + start.store(true, std::memory_order_release); + std::this_thread::sleep_for(std::chrono::milliseconds(5)); + LOGIT_SHUTDOWN(); + stop.store(true, std::memory_order_release); + + for (std::size_t i = 0; i < producers.size(); ++i) { + producers[i].join(); + } + + LOGIT_INFO("after shutdown"); + + const bool ok = raw_logger->shutdown_started() && + raw_logger->logs_after_shutdown() == 0; + std::cout << (ok ? "PASS" : "FAIL") << ": logger_shutdown_race" << std::endl; + return ok ? 0 : 1; +} diff --git a/tests/otlp_http_logger_integration_test.cpp b/tests/otlp_http_logger_integration_test.cpp index 234fb50..3806515 100644 --- a/tests/otlp_http_logger_integration_test.cpp +++ b/tests/otlp_http_logger_integration_test.cpp @@ -111,6 +111,8 @@ int main() { assert(captured.body.find("\"severityNumber\":13") != std::string::npos); assert(captured.body.find("OTLP integration test message") != std::string::npos); + LOGIT_SHUTDOWN(); + return 0; } diff --git a/tests/per_logger_mixed_mode_test.cpp b/tests/per_logger_mixed_mode_test.cpp index 818ab56..40d612c 100644 --- a/tests/per_logger_mixed_mode_test.cpp +++ b/tests/per_logger_mixed_mode_test.cpp @@ -28,7 +28,7 @@ class CountingLogger : public logit::ILogger { } ~CountingLogger() override { - if (m_executor) m_executor->shutdown(); + shutdown(); } void log(const LogRecord& record, const std::string& message) override { @@ -56,6 +56,11 @@ class CountingLogger : public logit::ILogger { else logit::detail::TaskExecutor::get_instance().wait(); } + void shutdown() override { + wait(); + if (m_executor) m_executor->shutdown(); + } + std::size_t count() const { return m_count.load(std::memory_order_relaxed); } private: diff --git a/tests/task_executor_resize_race_test.cpp b/tests/task_executor_resize_race_test.cpp new file mode 100644 index 0000000..fdcf017 --- /dev/null +++ b/tests/task_executor_resize_race_test.cpp @@ -0,0 +1,64 @@ +#include + +#include +#include +#include +#include +#include + +int main() { + auto& executor = logit::detail::TaskExecutor::get_instance(); + executor.wait(); + + LOGIT_SET_QUEUE_POLICY(logit::detail::QueuePolicy::Block); + LOGIT_SET_MAX_QUEUE(32); + LOGIT_RESET_DROPPED_TASKS(); + + std::atomic start(false); + std::atomic submitted(0); + std::atomic processed(0); + + std::vector producers; + for (int t = 0; t < 4; ++t) { + producers.emplace_back([&]() { + while (!start.load(std::memory_order_acquire)) { + std::this_thread::yield(); + } + for (int i = 0; i < 250; ++i) { + submitted.fetch_add(1, std::memory_order_relaxed); + executor.add_task([&processed]() { + processed.fetch_add(1, std::memory_order_relaxed); + }); + } + }); + } + + std::thread resizer([&]() { + while (!start.load(std::memory_order_acquire)) { + std::this_thread::yield(); + } + for (int i = 0; i < 100; ++i) { + LOGIT_SET_MAX_QUEUE(8 + static_cast((i % 8) * 8)); + std::this_thread::yield(); + } + }); + + start.store(true, std::memory_order_release); + + for (std::size_t i = 0; i < producers.size(); ++i) { + producers[i].join(); + } + resizer.join(); + + executor.wait(); + + const bool ok = processed.load(std::memory_order_relaxed) == + submitted.load(std::memory_order_relaxed) && + LOGIT_GET_DROPPED_TASKS() == 0; + + LOGIT_SET_MAX_QUEUE(0); + LOGIT_RESET_DROPPED_TASKS(); + + std::cout << (ok ? "PASS" : "FAIL") << ": task_executor_resize_race" << std::endl; + return ok ? 0 : 1; +}