Skip to main content

nautilus_common/logging/
logger.rs

1// -------------------------------------------------------------------------------------------------
2//  Copyright (C) 2015-2026 Nautech Systems Pty Ltd. All rights reserved.
3//  https://nautechsystems.io
4//
5//  Licensed under the GNU Lesser General Public License Version 3.0 (the "License");
6//  You may not use this file except in compliance with the License.
7//  You may obtain a copy of the License at https://www.gnu.org/licenses/lgpl-3.0.en.html
8//
9//  Unless required by applicable law or agreed to in writing, software
10//  distributed under the License is distributed on an "AS IS" BASIS,
11//  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12//  See the License for the specific language governing permissions and
13//  limitations under the License.
14// -------------------------------------------------------------------------------------------------
15
16//! Core logger lifecycle, filtering, event formatting, and dispatch.
17
18use std::{
19    cell::RefCell,
20    fmt::{Display, Write as _},
21    io::{self, Write as _},
22    sync::{
23        OnceLock,
24        atomic::{AtomicBool, Ordering},
25        mpsc::SendError,
26    },
27};
28#[cfg(not(all(feature = "simulation", madsim)))]
29use std::{
30    sync::mpsc::{RecvTimeoutError, TryRecvError},
31    time::{Duration, Instant},
32};
33
34use ahash::AHashMap;
35use indexmap::IndexMap;
36use log::{
37    Level, LevelFilter, Log, STATIC_MAX_LEVEL,
38    kv::{ToValue, Value},
39    set_boxed_logger, set_max_level,
40};
41use nautilus_core::{
42    UUID4, UnixNanos,
43    datetime::unix_nanos_to_iso8601,
44    time::{get_atomic_clock_realtime, get_atomic_clock_static},
45};
46use nautilus_model::identifiers::TraderId;
47use parking_lot::Mutex;
48use serde::{Deserialize, Serialize, Serializer, ser::SerializeMap};
49use smallvec::SmallVec;
50use ustr::Ustr;
51
52pub use super::config::LoggerConfig;
53use super::{LOGGING_BYPASSED, LOGGING_GUARDS_ACTIVE, LOGGING_INITIALIZED, LOGGING_REALTIME};
54#[cfg(not(all(feature = "simulation", madsim)))]
55use crate::logging::writer::{FileWriter, LogWriter, StderrWriter, StdoutWriter};
56use crate::{
57    enums::{LogColor, LogLevel},
58    logging::writer::FileWriterConfig,
59};
60
61#[cfg(not(all(feature = "simulation", madsim)))]
62const LOGGING: &str = "logging";
63
64// Bounds how long lines sit in the file buffer before reaching the OS (flush only, no fsync)
65#[cfg(not(all(feature = "simulation", madsim)))]
66const FILE_FLUSH_INTERVAL: Duration = Duration::from_millis(100);
67
68// Queued events between flush deadline checks, amortizing the clock read under a backlog
69#[cfg(not(all(feature = "simulation", madsim)))]
70const FILE_FLUSH_CHECK_EVENTS: u32 = 256;
71
72const KV_COLOR: &str = "color";
73const KV_COMPONENT: &str = "component";
74const LOG_FIELDS_INLINE_CAP: usize = 0;
75const MAX_LEVEL_DISPLAY_LEN: usize = "ERROR".len();
76const ANSI_BOLD_LEN: usize = "\x1b[1m".len();
77const ANSI_RESET_LEN: usize = "\x1b[0m".len();
78const PLAIN_FORMAT_OVERHEAD: usize = " [".len() + "] ".len() + ".".len() + ": ".len() + "\n".len();
79const COLORED_FORMAT_OVERHEAD: usize = ANSI_BOLD_LEN
80    + ANSI_RESET_LEN
81    + " ".len()
82    + "[".len()
83    + "] ".len()
84    + ".".len()
85    + ": ".len()
86    + ANSI_RESET_LEN
87    + "\n".len();
88const REPEATED_USTR_CACHE_CAP: usize = 8;
89
90thread_local! {
91    static REPEATED_USTR_CACHE: RefCell<RepeatedUstrCache> =
92        const { RefCell::new(RepeatedUstrCache::new()) };
93}
94
95/// Storage for structured log fields.
96/// Inline capacity is intentionally zero to keep the producer-side `LogLine` payload small.
97pub type LogFields = SmallVec<[(Ustr, String); LOG_FIELDS_INLINE_CAP]>;
98
99/// Global log sender which allows multiple log guards per process.
100static LOGGER_TX: OnceLock<std::sync::mpsc::Sender<LogEvent>> = OnceLock::new();
101
102/// Global handle to the logging thread - only one thread exists per process.
103static LOGGER_HANDLE: Mutex<Option<std::thread::JoinHandle<()>>> = Mutex::new(None);
104
105#[derive(Debug, Clone, Copy, PartialEq, Eq)]
106enum LoggerLifecycle {
107    Uninitialized,
108    Running,
109    Terminated,
110}
111
112/// Process-global logger lifecycle serialization.
113static LOGGER_LIFECYCLE: Mutex<LoggerLifecycle> = Mutex::new(LoggerLifecycle::Uninitialized);
114
115#[cfg(all(test, not(all(feature = "simulation", madsim))))]
116struct InitPublishHook {
117    reached: std::sync::mpsc::Sender<()>,
118    resume: std::sync::mpsc::Receiver<()>,
119}
120
121#[cfg(all(test, not(all(feature = "simulation", madsim))))]
122static INIT_PUBLISH_HOOK: Mutex<Option<InitPublishHook>> = Mutex::new(None);
123
124#[cfg(all(test, not(all(feature = "simulation", madsim))))]
125enum TestGuardAcquire {
126    LifecycleBusy,
127    Acquired(Option<LogGuard>),
128}
129
130static SHUTDOWN_ON_ERROR: OnceLock<ShutdownOnError> = OnceLock::new();
131
132/// The first error log captured after shutdown-on-error is armed.
133#[derive(Debug, Clone, PartialEq, Eq)]
134pub struct ShutdownOnErrorTrigger {
135    /// The UNIX timestamp (ns) of the error log.
136    pub timestamp: UnixNanos,
137    /// The log component that emitted the error.
138    pub component: Ustr,
139    /// The formatted error log message.
140    pub message: String,
141}
142
143#[derive(Debug, Default)]
144struct ShutdownOnError {
145    armed: AtomicBool,
146    triggered: AtomicBool,
147    pending: Mutex<Option<ShutdownOnErrorTrigger>>,
148}
149
150impl ShutdownOnError {
151    fn is_armed(&self) -> bool {
152        self.armed.load(Ordering::Acquire)
153    }
154
155    fn arm(&self, enabled: bool) {
156        self.pending.lock().take();
157        self.triggered.store(false, Ordering::Release);
158        self.armed.store(enabled, Ordering::Release);
159    }
160
161    fn disarm(&self) {
162        self.armed.store(false, Ordering::Release);
163        self.triggered.store(false, Ordering::Release);
164
165        self.pending.lock().take();
166    }
167
168    fn maybe_record_trigger<F>(
169        &self,
170        level: Level,
171        timestamp: UnixNanos,
172        component: Ustr,
173        message: F,
174    ) where
175        F: FnOnce() -> String,
176    {
177        if !self.armed.load(Ordering::Acquire) || level != Level::Error {
178            return;
179        }
180
181        let mut pending = self.pending.lock();
182
183        if self
184            .triggered
185            .compare_exchange(false, true, Ordering::AcqRel, Ordering::Acquire)
186            .is_err()
187        {
188            return;
189        }
190
191        *pending = Some(ShutdownOnErrorTrigger {
192            timestamp,
193            component,
194            message: message(),
195        });
196    }
197
198    fn take_trigger(&self) -> Option<ShutdownOnErrorTrigger> {
199        if !self.triggered.load(Ordering::Acquire) {
200            return None;
201        }
202
203        self.pending.lock().take()
204    }
205
206    fn try_drain_trigger<F>(&self, drain: F) -> bool
207    where
208        F: FnOnce(&ShutdownOnErrorTrigger) -> bool,
209    {
210        if !self.triggered.load(Ordering::Acquire) {
211            return false;
212        }
213
214        let mut pending = self.pending.lock();
215
216        let Some(trigger) = pending.as_ref() else {
217            return false;
218        };
219
220        if !drain(trigger) {
221            return false;
222        }
223
224        pending.take();
225        true
226    }
227}
228
229/// Arms shutdown-on-error handling for the current run.
230pub fn arm_shutdown_on_error(enabled: bool) {
231    shutdown_on_error().arm(enabled);
232}
233
234/// Disarms shutdown-on-error handling and clears any pending trigger.
235pub fn disarm_shutdown_on_error() {
236    shutdown_on_error().disarm();
237}
238
239/// Returns and clears the pending shutdown-on-error trigger, if one was recorded.
240pub fn take_shutdown_on_error_trigger() -> Option<ShutdownOnErrorTrigger> {
241    shutdown_on_error().take_trigger()
242}
243
244/// Conditionally drains the pending shutdown-on-error trigger.
245pub fn try_drain_shutdown_on_error_trigger<F>(drain: F) -> bool
246where
247    F: FnOnce(&ShutdownOnErrorTrigger) -> bool,
248{
249    shutdown_on_error().try_drain_trigger(drain)
250}
251
252fn shutdown_on_error() -> &'static ShutdownOnError {
253    SHUTDOWN_ON_ERROR.get_or_init(ShutdownOnError::default)
254}
255
256/// Producer-side filtering policy derived from [`LoggerConfig`].
257#[derive(Debug, Clone)]
258struct FilterPolicy {
259    /// Module filters pre-sorted by descending path length for longest-prefix lookup.
260    modules_by_longest_prefix: Vec<(Ustr, LevelFilter)>,
261    /// Per-component log level overrides.
262    components: AHashMap<Ustr, LevelFilter>,
263    /// Whether logs without an explicit component/module filter should be skipped.
264    components_only: bool,
265}
266
267impl FilterPolicy {
268    fn from_config(config: &LoggerConfig) -> Option<Self> {
269        let modules_by_longest_prefix = sorted_module_filters_from_map(&config.module_level);
270        if !config.log_components_only
271            && modules_by_longest_prefix.is_empty()
272            && config.component_level.is_empty()
273        {
274            return None;
275        }
276
277        Some(Self {
278            modules_by_longest_prefix,
279            components: config.component_level.clone(),
280            components_only: config.log_components_only,
281        })
282    }
283
284    fn should_skip(&self, component: &Ustr, level: Level) -> bool {
285        should_filter_log_inner(
286            component,
287            level,
288            &self.modules_by_longest_prefix,
289            &self.components,
290            self.components_only,
291        )
292    }
293}
294
295/// A high-performance logger utilizing a MPSC channel under the hood.
296///
297/// A logger is initialized with a [`LoggerConfig`] to set up different logging levels for
298/// stdout, file, and components. The logger spawns a thread that listens for [`LogEvent`]s
299/// sent via an MPSC channel.
300#[derive(Debug)]
301pub struct Logger {
302    /// Initialization snapshot for logging levels and behavior.
303    ///
304    /// Producer filters are derived into `filter_policy` at initialization; mutating this field
305    /// after registration does not reload component/module filters.
306    pub config: LoggerConfig,
307    /// Producer-side component/module filtering policy.
308    filter_policy: Option<FilterPolicy>,
309    /// Transmitter for sending log events to the 'logging' thread.
310    tx: std::sync::mpsc::Sender<LogEvent>,
311}
312
313/// Represents a type of log event.
314#[derive(Debug)]
315pub enum LogEvent {
316    /// A log line event.
317    Log(LogLine),
318    /// A command to flush all logger buffers.
319    Flush,
320    /// A command to flush and sync file logs to disk, then acknowledge completion.
321    Sync(std::sync::mpsc::Sender<anyhow::Result<()>>),
322    /// A command to close the logger.
323    Close,
324}
325
326/// Represents a log event which includes a message.
327#[derive(Clone, Debug, Serialize, Deserialize)]
328pub struct LogLine {
329    /// The timestamp for the event.
330    pub timestamp: UnixNanos,
331    /// The log level for the event.
332    pub level: Level,
333    /// The color for the log message content.
334    pub color: LogColor,
335    /// The Nautilus system component the log event originated from.
336    pub component: Ustr,
337    /// The log message content.
338    pub message: String,
339    /// Arbitrary structured key-value fields attached to this log event.
340    #[serde(default, skip_serializing_if = "SmallVec::is_empty")]
341    pub fields: LogFields,
342}
343
344impl Display for LogLine {
345    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
346        write!(f, "[{}] {}: {}", self.level, self.component, self.message)?;
347        for (k, v) in &self.fields {
348            write!(f, " {k}={v}")?;
349        }
350        Ok(())
351    }
352}
353
354/// A wrapper around a log line that provides formatted and cached representations.
355///
356/// This struct contains a log line and provides various formatted versions
357/// of it, such as plain string, colored string, and JSON. It also caches the
358/// results for repeated calls, optimizing performance when the same message
359/// needs to be logged multiple times in different formats.
360#[derive(Clone, Debug)]
361pub struct LogLineWrapper {
362    /// The underlying log line that contains the log data.
363    line: LogLine,
364    /// Cached plain string representation of the log line.
365    cache: Option<String>,
366    /// Cached colored string representation of the log line.
367    colored: Option<String>,
368    /// The ID of the trader associated with this log event.
369    trader_id: Ustr,
370}
371
372impl LogLineWrapper {
373    /// Creates a new [`LogLineWrapper`] instance.
374    #[must_use]
375    pub const fn new(line: LogLine, trader_id: Ustr) -> Self {
376        Self {
377            line,
378            cache: None,
379            colored: None,
380            trader_id,
381        }
382    }
383
384    /// Returns the plain log message string, caching the result.
385    ///
386    /// This method constructs the log line format and caches it for repeated calls. Useful when the
387    /// same log message needs to be printed multiple times.
388    pub fn get_string(&mut self) -> &str {
389        self.cache.get_or_insert_with(|| {
390            let timestamp = unix_nanos_to_iso8601(self.line.timestamp);
391            let mut s = String::with_capacity(plain_log_line_capacity(
392                &timestamp,
393                self.trader_id,
394                &self.line,
395            ));
396
397            write!(
398                s,
399                "{} [{}] {}.{}: {}",
400                timestamp, self.line.level, self.trader_id, self.line.component, self.line.message,
401            )
402            .expect("writing to String should not fail");
403
404            for (k, v) in &self.line.fields {
405                s.push(' ');
406                s.push_str(k);
407                s.push('=');
408                s.push_str(v);
409            }
410            s.push('\n');
411            s
412        })
413    }
414
415    /// Returns the colored log message string, caching the result.
416    ///
417    /// This method constructs the colored log line format and caches the result
418    /// for repeated calls, providing the message with ANSI color codes if the
419    /// logger is configured to use colors.
420    pub fn get_colored(&mut self) -> &str {
421        self.colored.get_or_insert_with(|| {
422            let timestamp = unix_nanos_to_iso8601(self.line.timestamp);
423            let color_ansi = self.line.color.as_ansi();
424            let mut s = String::with_capacity(colored_log_line_capacity(
425                &timestamp,
426                color_ansi,
427                self.trader_id,
428                &self.line,
429            ));
430
431            write!(
432                s,
433                "\x1b[1m{}\x1b[0m {}[{}] {}.{}: {}",
434                timestamp,
435                color_ansi,
436                self.line.level,
437                self.trader_id,
438                self.line.component,
439                self.line.message,
440            )
441            .expect("writing to String should not fail");
442
443            for (k, v) in &self.line.fields {
444                s.push(' ');
445                s.push_str(k);
446                s.push('=');
447                s.push_str(v);
448            }
449            s.push_str("\x1b[0m\n");
450            s
451        })
452    }
453
454    /// Returns the log message as a JSON string.
455    ///
456    /// This method serializes the log line and its associated metadata
457    /// (timestamp, trader ID, etc.) into a JSON string format. This is useful
458    /// for structured logging or when logs need to be stored in a JSON format.
459    /// # Panics
460    ///
461    /// Panics if serialization of the log event to JSON fails.
462    #[must_use]
463    pub fn get_json(&self) -> String {
464        let mut json_string =
465            serde_json::to_string(&self).expect("Error serializing log event to string");
466        json_string.push('\n');
467        json_string
468    }
469}
470
471fn formatted_fields_len(fields: &LogFields) -> usize {
472    fields.iter().map(|(k, v)| 2 + k.len() + v.len()).sum()
473}
474
475fn log_line_capacity(
476    timestamp: &str,
477    trader_id: Ustr,
478    line: &LogLine,
479    overhead: usize,
480    ansi_extra_len: usize,
481) -> usize {
482    timestamp.len()
483        + overhead
484        + ansi_extra_len
485        + MAX_LEVEL_DISPLAY_LEN
486        + trader_id.len()
487        + line.component.len()
488        + line.message.len()
489        + formatted_fields_len(&line.fields)
490}
491
492fn plain_log_line_capacity(timestamp: &str, trader_id: Ustr, line: &LogLine) -> usize {
493    log_line_capacity(timestamp, trader_id, line, PLAIN_FORMAT_OVERHEAD, 0)
494}
495
496fn colored_log_line_capacity(
497    timestamp: &str,
498    color_ansi: &str,
499    trader_id: Ustr,
500    line: &LogLine,
501) -> usize {
502    log_line_capacity(
503        timestamp,
504        trader_id,
505        line,
506        COLORED_FORMAT_OVERHEAD,
507        color_ansi.len(),
508    )
509}
510
511impl Serialize for LogLineWrapper {
512    fn serialize<S>(&self, serializer: S) -> Result<S::Ok, S::Error>
513    where
514        S: Serializer,
515    {
516        if has_duplicate_json_field(&self.line.fields) {
517            return serialize_log_line_with_indexmap(self, serializer);
518        }
519
520        let timestamp = unix_nanos_to_iso8601(self.line.timestamp);
521        let mut map = serializer.serialize_map(None)?;
522
523        map.serialize_entry("timestamp", &timestamp)?;
524        map.serialize_entry("trader_id", self.trader_id.as_str())?;
525        map.serialize_entry("level", &DisplayAsString(&self.line.level))?;
526        map.serialize_entry("color", &DisplayAsString(&self.line.color))?;
527        map.serialize_entry("component", self.line.component.as_str())?;
528        map.serialize_entry("message", &self.line.message)?;
529
530        for (k, v) in &self.line.fields {
531            let key = k.as_str();
532            if !is_reserved_json_key(key) {
533                map.serialize_entry(key, v)?;
534            }
535        }
536
537        map.end()
538    }
539}
540
541struct DisplayAsString<'a, T: ?Sized>(&'a T);
542
543impl<T> Serialize for DisplayAsString<'_, T>
544where
545    T: Display + ?Sized,
546{
547    fn serialize<S>(&self, serializer: S) -> Result<S::Ok, S::Error>
548    where
549        S: Serializer,
550    {
551        serializer.collect_str(self.0)
552    }
553}
554
555fn is_reserved_json_key(key: &str) -> bool {
556    matches!(
557        key,
558        "timestamp" | "trader_id" | "level" | "color" | "component" | "message"
559    )
560}
561
562fn has_duplicate_json_field(fields: &LogFields) -> bool {
563    if fields.is_empty() {
564        return false;
565    }
566
567    for (idx, (key, _)) in fields.iter().enumerate() {
568        let key = key.as_str();
569        if is_reserved_json_key(key) {
570            continue;
571        }
572
573        if fields
574            .iter()
575            .take(idx)
576            .any(|(prev, _)| !is_reserved_json_key(prev.as_str()) && prev == key)
577        {
578            return true;
579        }
580    }
581
582    false
583}
584
585fn serialize_log_line_with_indexmap<S>(
586    wrapper: &LogLineWrapper,
587    serializer: S,
588) -> Result<S::Ok, S::Error>
589where
590    S: Serializer,
591{
592    let mut json_obj = IndexMap::new();
593    let timestamp = unix_nanos_to_iso8601(wrapper.line.timestamp);
594    json_obj.insert("timestamp".to_string(), timestamp);
595    json_obj.insert("trader_id".to_string(), wrapper.trader_id.to_string());
596    json_obj.insert("level".to_string(), wrapper.line.level.to_string());
597    json_obj.insert("color".to_string(), wrapper.line.color.to_string());
598    json_obj.insert("component".to_string(), wrapper.line.component.to_string());
599    json_obj.insert("message".to_string(), wrapper.line.message.clone());
600    for (k, v) in &wrapper.line.fields {
601        let key = k.as_str();
602        if !is_reserved_json_key(key) {
603            json_obj.insert(k.to_string(), v.clone());
604        }
605    }
606
607    json_obj.serialize(serializer)
608}
609
610fn sorted_module_filters_from_map(
611    module_level: &AHashMap<Ustr, LevelFilter>,
612) -> Vec<(Ustr, LevelFilter)> {
613    let mut filters: Vec<_> = module_level
614        .iter()
615        .map(|(path, level)| (*path, *level))
616        .collect();
617    filters.sort_by_key(|(path, _)| std::cmp::Reverse(path.len()));
618    filters
619}
620
621fn current_log_timestamp() -> UnixNanos {
622    if LOGGING_REALTIME.load(Ordering::Relaxed) {
623        get_atomic_clock_realtime().get_time_ns()
624    } else {
625        get_atomic_clock_static().get_time_ns()
626    }
627}
628
629fn intern_repeated(value: &str) -> Ustr {
630    REPEATED_USTR_CACHE.with(|cache| {
631        let mut cache_state = cache.borrow_mut();
632        let ptr = value.as_ptr() as usize;
633        let len = value.len();
634
635        // Targets and components are usually repeated static strings; the content check keeps
636        // dynamic RecordBuilder targets correct if an allocator reuses the same pointer.
637        for entry in cache_state.entries.iter().flatten() {
638            if entry.ptr == ptr && entry.len == len && entry.value == value {
639                return entry.value;
640            }
641        }
642
643        let interned = Ustr::from(value);
644        let insert_idx = cache_state.next;
645        cache_state.entries[insert_idx] = Some(RepeatedUstrCacheEntry {
646            ptr,
647            len,
648            value: interned,
649        });
650        cache_state.next = (insert_idx + 1) % REPEATED_USTR_CACHE_CAP;
651        interned
652    })
653}
654
655#[derive(Clone, Copy)]
656struct RepeatedUstrCacheEntry {
657    ptr: usize,
658    len: usize,
659    value: Ustr,
660}
661
662#[derive(Clone, Copy)]
663struct RepeatedUstrCache {
664    entries: [Option<RepeatedUstrCacheEntry>; REPEATED_USTR_CACHE_CAP],
665    next: usize,
666}
667
668impl RepeatedUstrCache {
669    const fn new() -> Self {
670        Self {
671            entries: [None; REPEATED_USTR_CACHE_CAP],
672            next: 0,
673        }
674    }
675}
676
677fn intern_component_value(value: &log::kv::Value<'_>) -> Ustr {
678    match value.to_borrowed_str() {
679        Some(component) => intern_repeated(component),
680        None => Ustr::from(&value.to_string()),
681    }
682}
683
684#[derive(Default)]
685struct ComponentProbe {
686    component: Option<Ustr>,
687}
688
689impl<'kvs> log::kv::VisitSource<'kvs> for ComponentProbe {
690    fn visit_pair(
691        &mut self,
692        key: log::kv::Key<'kvs>,
693        value: log::kv::Value<'kvs>,
694    ) -> Result<(), log::kv::Error> {
695        if key.as_str() == KV_COMPONENT {
696            self.component = Some(intern_component_value(&value));
697        }
698        Ok(())
699    }
700}
701
702#[derive(Default)]
703struct PayloadCollector {
704    color: Option<LogColor>,
705    fields: LogFields,
706}
707
708impl<'kvs> log::kv::VisitSource<'kvs> for PayloadCollector {
709    fn visit_pair(
710        &mut self,
711        key: log::kv::Key<'kvs>,
712        value: log::kv::Value<'kvs>,
713    ) -> Result<(), log::kv::Error> {
714        match key.as_str() {
715            KV_COLOR => {
716                self.color = value.to_u64().map(|v| (v as u8).into());
717            }
718            KV_COMPONENT => {}
719            _ => {
720                self.fields
721                    .push((Ustr::from(key.as_str()), value.to_string()));
722            }
723        }
724        Ok(())
725    }
726}
727
728#[derive(Default)]
729struct FieldCollector {
730    color: Option<LogColor>,
731    component: Option<Ustr>,
732    fields: LogFields,
733}
734
735impl<'kvs> log::kv::VisitSource<'kvs> for FieldCollector {
736    fn visit_pair(
737        &mut self,
738        key: log::kv::Key<'kvs>,
739        value: log::kv::Value<'kvs>,
740    ) -> Result<(), log::kv::Error> {
741        match key.as_str() {
742            KV_COLOR => {
743                self.color = value.to_u64().map(|v| (v as u8).into());
744            }
745            KV_COMPONENT => {
746                self.component = Some(intern_component_value(&value));
747            }
748            _ => {
749                self.fields
750                    .push((Ustr::from(key.as_str()), value.to_string()));
751            }
752        }
753        Ok(())
754    }
755}
756
757impl Log for Logger {
758    fn enabled(&self, metadata: &log::Metadata) -> bool {
759        if LOGGING_BYPASSED.load(Ordering::Relaxed) {
760            return metadata.level() == Level::Error && shutdown_on_error().is_armed();
761        }
762
763        metadata.level() == Level::Error
764            || metadata.level() <= self.config.stdout_level
765            || metadata.level() <= self.config.fileout_level
766    }
767
768    fn log(&self, record: &log::Record) {
769        let level = record.level();
770
771        if LOGGING_BYPASSED.load(Ordering::Relaxed) {
772            if level == Level::Error {
773                record_shutdown_on_error(record);
774            }
775            return;
776        }
777
778        if self.enabled(record.metadata()) {
779            if let Some(filter_policy) = &self.filter_policy {
780                // Probe only the component before filtering. Filtered error logs still need
781                // enough payload to trigger shutdown-on-error.
782                let mut probe = ComponentProbe::default();
783                let _ = record.key_values().visit(&mut probe);
784                let component = probe
785                    .component
786                    .unwrap_or_else(|| intern_repeated(record.metadata().target()));
787
788                if filter_policy.should_skip(&component, level) {
789                    if level == Level::Error {
790                        shutdown_on_error().maybe_record_trigger(
791                            level,
792                            current_log_timestamp(),
793                            component,
794                            || format!("{}", record.args()),
795                        );
796                    }
797                    return;
798                }
799
800                let timestamp = current_log_timestamp();
801                let mut collector = PayloadCollector::default();
802                let _ = record.key_values().visit(&mut collector);
803                let color = collector.color.unwrap_or_else(|| level.into());
804
805                let line = LogLine {
806                    timestamp,
807                    level,
808                    color,
809                    component,
810                    message: format!("{}", record.args()),
811                    fields: collector.fields,
812                };
813
814                shutdown_on_error().maybe_record_trigger(
815                    line.level,
816                    line.timestamp,
817                    line.component,
818                    || line.message.clone(),
819                );
820                self.send_log_line(line);
821                return;
822            }
823
824            // With no component/module filters configured, keep the producer path to one KV visit.
825            let timestamp = current_log_timestamp();
826            let mut collector = FieldCollector::default();
827            let _ = record.key_values().visit(&mut collector);
828            let color = collector.color.unwrap_or_else(|| level.into());
829            let component = collector
830                .component
831                .unwrap_or_else(|| intern_repeated(record.metadata().target()));
832
833            let line = LogLine {
834                timestamp,
835                level,
836                color,
837                component,
838                message: format!("{}", record.args()),
839                fields: collector.fields,
840            };
841
842            shutdown_on_error().maybe_record_trigger(
843                line.level,
844                line.timestamp,
845                line.component,
846                || line.message.clone(),
847            );
848            self.send_log_line(line);
849        }
850    }
851
852    fn flush(&self) {
853        // Don't attempt to flush if we're already bypassed/shutdown
854        if LOGGING_BYPASSED.load(Ordering::Relaxed) {
855            return;
856        }
857
858        if let Err(e) = self.tx.send(LogEvent::Flush) {
859            let _ = writeln!(io::stderr(), "Error sending flush log event: {e}");
860        }
861    }
862}
863
864fn record_shutdown_on_error(record: &log::Record) {
865    let mut probe = ComponentProbe::default();
866    let _ = record.key_values().visit(&mut probe);
867    let component = probe
868        .component
869        .unwrap_or_else(|| intern_repeated(record.metadata().target()));
870
871    shutdown_on_error().maybe_record_trigger(
872        record.level(),
873        current_log_timestamp(),
874        component,
875        || format!("{}", record.args()),
876    );
877}
878
879impl Logger {
880    /// Creates a logger instance for direct benchmark harnesses.
881    ///
882    /// This bypasses the global `log::set_logger` singleton so benchmark code can compare
883    /// multiple logger configurations in one process. It does not spawn a writer thread.
884    #[doc(hidden)]
885    #[must_use]
886    pub fn new_for_benchmark(config: LoggerConfig, tx: std::sync::mpsc::Sender<LogEvent>) -> Self {
887        let filter_policy = FilterPolicy::from_config(&config);
888
889        Self {
890            config,
891            filter_policy,
892            tx,
893        }
894    }
895
896    fn send_log_line(&self, line: LogLine) {
897        if let Err(SendError(LogEvent::Log(line))) = self.tx.send(LogEvent::Log(line)) {
898            let _ = writeln!(
899                io::stderr(),
900                "Error sending log event (receiver closed): {line}"
901            );
902        }
903    }
904
905    /// Initializes the logger based on the `NAUTILUS_LOG` environment variable.
906    ///
907    /// # Errors
908    ///
909    /// Returns an error if reading the environment variable or parsing the configuration fails.
910    pub fn init_with_env(
911        trader_id: TraderId,
912        instance_id: UUID4,
913        file_config: FileWriterConfig,
914    ) -> anyhow::Result<LogGuard> {
915        let config = LoggerConfig::from_env()?;
916        Self::init_with_config(trader_id, instance_id, config, file_config)
917    }
918
919    /// Initializes the logger with the given configuration.
920    ///
921    /// # Errors
922    ///
923    /// Returns an error if the logger fails to register or initialize the background thread.
924    #[cfg_attr(
925        not(all(feature = "simulation", madsim)),
926        expect(clippy::needless_pass_by_value)
927    )]
928    pub fn init_with_config(
929        trader_id: TraderId,
930        instance_id: UUID4,
931        config: LoggerConfig,
932        file_config: FileWriterConfig,
933    ) -> anyhow::Result<LogGuard> {
934        let mut lifecycle = LOGGER_LIFECYCLE.lock();
935
936        match *lifecycle {
937            LoggerLifecycle::Running => {
938                return LogGuard::new_locked().ok_or_else(|| {
939                    anyhow::anyhow!(
940                        "Logging already initialized but new guard could not be created"
941                    )
942                });
943            }
944            LoggerLifecycle::Terminated => {
945                anyhow::bail!("Logging has been shut down and cannot be re-initialized");
946            }
947            LoggerLifecycle::Uninitialized => {}
948        }
949
950        // Open the log file before spawning the thread so an unusable path fails init
951        #[cfg(not(all(feature = "simulation", madsim)))]
952        let file_writer_opt = if config.fileout_level == LevelFilter::Off {
953            None
954        } else {
955            Some(FileWriter::new(
956                trader_id.to_string(),
957                instance_id.to_string(),
958                file_config.clone(),
959                config.fileout_level,
960                config.clear_log_file,
961                config.fileout_sync_on_flush,
962            )?)
963        };
964
965        let (tx, rx) = std::sync::mpsc::channel::<LogEvent>();
966        let filter_policy = FilterPolicy::from_config(&config);
967
968        #[cfg(not(all(feature = "simulation", madsim)))]
969        let handle = std::thread::Builder::new()
970            .name(LOGGING.to_string())
971            .spawn({
972                let config = config.clone();
973                move || {
974                    Self::handle_messages(trader_id.to_string(), config, file_writer_opt, rx);
975                }
976            })?;
977
978        let logger = Self {
979            config: config.clone(),
980            filter_policy,
981            tx: tx.clone(),
982        };
983
984        if let Err(e) = set_boxed_logger(Box::new(logger)) {
985            #[cfg(not(all(feature = "simulation", madsim)))]
986            {
987                let _ = tx.send(LogEvent::Close);
988                if handle.thread().id() != std::thread::current().id() {
989                    let _ = handle.join();
990                }
991            }
992            *lifecycle = LoggerLifecycle::Terminated;
993            return Err(e.into());
994        }
995
996        #[cfg(all(test, not(all(feature = "simulation", madsim))))]
997        if let Some(hook) = INIT_PUBLISH_HOOK.lock().take() {
998            let _ = hook.reached.send(());
999            let _ = hook.resume.recv();
1000        }
1001
1002        // Store the sender globally so additional guards can be created
1003        if let Err(tx) = LOGGER_TX.set(tx) {
1004            #[cfg(not(all(feature = "simulation", madsim)))]
1005            {
1006                let _ = tx.send(LogEvent::Close);
1007                if handle.thread().id() != std::thread::current().id() {
1008                    let _ = handle.join();
1009                }
1010            }
1011            drop(tx);
1012            *lifecycle = LoggerLifecycle::Terminated;
1013            anyhow::bail!("Global logging sender was already published");
1014        }
1015
1016        if config.bypass_logging {
1017            super::logging_set_bypass();
1018        }
1019
1020        let is_colored = config.is_colored;
1021
1022        let print_config = config.print_config;
1023        if print_config {
1024            println!("STATIC_MAX_LEVEL={STATIC_MAX_LEVEL}");
1025            println!("Logger initialized with {config:?} {file_config:?}");
1026        }
1027
1028        #[cfg(not(all(feature = "simulation", madsim)))]
1029        {
1030            // Store the handle globally
1031            let mut handle_guard = LOGGER_HANDLE.lock();
1032            debug_assert!(
1033                handle_guard.is_none(),
1034                "LOGGER_HANDLE already set - re-initialization not supported"
1035            );
1036            *handle_guard = Some(handle);
1037        }
1038
1039        #[cfg(all(feature = "simulation", madsim))]
1040        {
1041            // Under simulation, the background writer thread would escape the
1042            // madsim scheduler. Drop the receiver so the channel closes cleanly
1043            // and force the bypass flag so subsequent log calls no-op without
1044            // SendError noise.
1045            let _ = (trader_id, instance_id, config, file_config, rx);
1046            super::logging_set_bypass();
1047        }
1048
1049        let max_level = log::LevelFilter::Trace;
1050        set_max_level(max_level);
1051
1052        if print_config {
1053            println!("Logger set as `log` implementation with max level {max_level}");
1054        }
1055
1056        super::LOGGING_INITIALIZED.store(true, Ordering::SeqCst);
1057        super::LOGGING_COLORED.store(is_colored, Ordering::SeqCst);
1058        *lifecycle = LoggerLifecycle::Running;
1059
1060        LogGuard::new_locked()
1061            .ok_or_else(|| anyhow::anyhow!("Failed to create LogGuard from global sender"))
1062    }
1063
1064    #[cfg(not(all(feature = "simulation", madsim)))]
1065    #[expect(clippy::needless_pass_by_value)]
1066    fn handle_messages(
1067        trader_id: String,
1068        config: LoggerConfig,
1069        mut file_writer_opt: Option<FileWriter>,
1070        rx: std::sync::mpsc::Receiver<LogEvent>,
1071    ) {
1072        let LoggerConfig {
1073            stdout_level,
1074            fileout_level: _,
1075            component_level: _,
1076            module_level: _,
1077            log_components_only: _,
1078            is_colored,
1079            print_config: _,
1080            use_tracing: _,
1081            bypass_logging: _,
1082            file_config: _,
1083            clear_log_file: _,
1084            fileout_sync_on_flush: _,
1085            buffered_stdout,
1086        } = config;
1087
1088        let trader_id_cache = Ustr::from(&trader_id);
1089
1090        // Set up std I/O buffers
1091        let mut stdout_writer = StdoutWriter::new(stdout_level, is_colored, buffered_stdout);
1092        let mut stderr_writer = StderrWriter::new(is_colored);
1093
1094        let process_event = |event: LogEvent,
1095                             stdout_writer: &mut StdoutWriter,
1096                             stderr_writer: &mut StderrWriter,
1097                             file_writer_opt: &mut Option<FileWriter>| {
1098            match event {
1099                LogEvent::Log(line) => {
1100                    let mut wrapper = LogLineWrapper::new(line, trader_id_cache);
1101
1102                    if stderr_writer.enabled(&wrapper.line) {
1103                        if is_colored {
1104                            stderr_writer.write(wrapper.get_colored());
1105                        } else {
1106                            stderr_writer.write(wrapper.get_string());
1107                        }
1108                    }
1109
1110                    if stdout_writer.enabled(&wrapper.line) {
1111                        if is_colored {
1112                            stdout_writer.write(wrapper.get_colored());
1113                        } else {
1114                            stdout_writer.write(wrapper.get_string());
1115                        }
1116                    }
1117
1118                    if let Some(file_writer) = file_writer_opt
1119                        && file_writer.enabled(&wrapper.line)
1120                    {
1121                        if file_writer.json_format {
1122                            file_writer.write(&wrapper.get_json());
1123                        } else {
1124                            file_writer.write(wrapper.get_string());
1125                        }
1126                    }
1127                }
1128                LogEvent::Flush => {
1129                    stdout_writer.flush();
1130                    stderr_writer.flush();
1131
1132                    if let Some(file_writer) = file_writer_opt {
1133                        file_writer.flush();
1134                    }
1135                }
1136                LogEvent::Sync(done) => {
1137                    stdout_writer.flush();
1138                    stderr_writer.flush();
1139
1140                    let result = if let Some(file_writer) = file_writer_opt {
1141                        file_writer.flush_and_sync().map_err(anyhow::Error::from)
1142                    } else {
1143                        Ok(())
1144                    };
1145
1146                    let _ = done.send(result);
1147                }
1148                LogEvent::Close => {
1149                    // Close handled in the main loop; ignore here.
1150                }
1151            }
1152        };
1153
1154        let mut file_flush_due = Instant::now() + FILE_FLUSH_INTERVAL; // dst-ok
1155        let mut queued_since_check = 0;
1156
1157        // Continue to receive and handle log events until channel is hung up
1158        loop {
1159            let event = match Self::recv_event(
1160                &rx,
1161                &mut file_writer_opt,
1162                &mut file_flush_due,
1163                &mut queued_since_check,
1164            ) {
1165                Ok(event) => event,
1166                Err(RecvTimeoutError::Timeout) => continue,
1167                Err(RecvTimeoutError::Disconnected) => break,
1168            };
1169
1170            match event {
1171                LogEvent::Log(_) | LogEvent::Flush | LogEvent::Sync(_) => process_event(
1172                    event,
1173                    &mut stdout_writer,
1174                    &mut stderr_writer,
1175                    &mut file_writer_opt,
1176                ),
1177                LogEvent::Close => {
1178                    // First flush what's been written so far
1179                    stdout_writer.flush();
1180                    stderr_writer.flush();
1181
1182                    if let Some(ref mut file_writer) = file_writer_opt {
1183                        file_writer.flush();
1184                    }
1185
1186                    // Drain any remaining events that may have raced with shutdown
1187                    // This ensures logs enqueued just before/around shutdown aren't lost.
1188                    while let Ok(evt) = rx.try_recv() {
1189                        match evt {
1190                            LogEvent::Close => (), // ignore extra Close events
1191                            _ => process_event(
1192                                evt,
1193                                &mut stdout_writer,
1194                                &mut stderr_writer,
1195                                &mut file_writer_opt,
1196                            ),
1197                        }
1198                    }
1199
1200                    // Final flush after draining
1201                    stdout_writer.flush();
1202                    stderr_writer.flush();
1203
1204                    if let Some(ref mut file_writer) = file_writer_opt {
1205                        file_writer.flush_and_sync_logged();
1206                    }
1207
1208                    break;
1209                }
1210            }
1211        }
1212    }
1213
1214    // Checks the flush deadline once per batch of queued events or when the queue is empty, so
1215    // console-only traffic cannot starve the file flush and a busy thread avoids per-event clock reads
1216    #[cfg(not(all(feature = "simulation", madsim)))]
1217    fn recv_event(
1218        rx: &std::sync::mpsc::Receiver<LogEvent>,
1219        file_writer_opt: &mut Option<FileWriter>,
1220        file_flush_due: &mut Instant,
1221        queued_since_check: &mut u32,
1222    ) -> Result<LogEvent, RecvTimeoutError> {
1223        let queued = match rx.try_recv() {
1224            Ok(event) => Some(event),
1225            Err(TryRecvError::Empty) => None,
1226            Err(TryRecvError::Disconnected) => return Err(RecvTimeoutError::Disconnected),
1227        };
1228
1229        let Some(file_writer) = file_writer_opt else {
1230            return match queued {
1231                Some(event) => Ok(event),
1232                None => rx.recv().map_err(|_| RecvTimeoutError::Disconnected),
1233            };
1234        };
1235
1236        let queued = match queued {
1237            Some(event) if *queued_since_check + 1 < FILE_FLUSH_CHECK_EVENTS => {
1238                *queued_since_check += 1;
1239                return Ok(event);
1240            }
1241            queued => queued,
1242        };
1243
1244        *queued_since_check = 0;
1245        let now = Instant::now(); // dst-ok
1246
1247        if now >= *file_flush_due {
1248            if let Err(e) = file_writer.flush_buffer() {
1249                let _ = writeln!(io::stderr(), "Error flushing log file: {e:?}");
1250            }
1251
1252            *file_flush_due = now + FILE_FLUSH_INTERVAL;
1253        }
1254
1255        match queued {
1256            Some(event) => Ok(event),
1257            None => rx.recv_timeout(file_flush_due.saturating_duration_since(now)),
1258        }
1259    }
1260}
1261
1262/// Determines if a log line should be filtered out based on module and component filters.
1263///
1264/// Returns `true` if the line should be skipped (filtered out), `false` if it should be logged.
1265///
1266/// The `module_filters_sorted` slice must be pre-sorted by descending path length so the
1267/// first `starts_with` match is the longest prefix.
1268#[must_use]
1269pub fn should_filter_log(
1270    component: &Ustr,
1271    line_level: log::Level,
1272    module_filters_sorted: &[(Ustr, LevelFilter)],
1273    component_level: &AHashMap<Ustr, LevelFilter>,
1274    log_components_only: bool,
1275) -> bool {
1276    should_filter_log_inner(
1277        component,
1278        line_level,
1279        module_filters_sorted,
1280        component_level,
1281        log_components_only,
1282    )
1283}
1284
1285fn should_filter_log_inner(
1286    component: &Ustr,
1287    line_level: log::Level,
1288    module_filters_sorted: &[(Ustr, LevelFilter)],
1289    component_level: &AHashMap<Ustr, LevelFilter>,
1290    log_components_only: bool,
1291) -> bool {
1292    if module_filters_sorted.is_empty() && component_level.is_empty() {
1293        return log_components_only;
1294    }
1295
1296    // Module filter: first match in sorted list is longest prefix
1297    let module_filter = module_filters_sorted
1298        .iter()
1299        .find(|(path, _)| component.starts_with(path.as_str()))
1300        .map(|(_, level)| *level);
1301
1302    let component_filter = component_level.get(component).copied();
1303
1304    if log_components_only && module_filter.is_none() && component_filter.is_none() {
1305        return true;
1306    }
1307
1308    // Module filter takes precedence over component filter
1309    module_filter
1310        .or(component_filter)
1311        .is_some_and(|filter_level| line_level > filter_level)
1312}
1313
1314/// Gracefully shuts down the logging subsystem.
1315///
1316/// This is the sole terminal lifecycle operation. It prevents further logging, closes and joins
1317/// the writer thread, and prevents subsequent logger initialization.
1318///
1319/// # Safety
1320///
1321/// Safe to call multiple times. Thread join is skipped if called from the logging thread.
1322pub(crate) fn shutdown_graceful() {
1323    let mut lifecycle = LOGGER_LIFECYCLE.lock();
1324
1325    if *lifecycle == LoggerLifecycle::Terminated {
1326        return;
1327    }
1328
1329    // Prevent further logging
1330    LOGGING_BYPASSED.store(true, Ordering::SeqCst);
1331    log::set_max_level(log::LevelFilter::Off);
1332
1333    // Signal Close if the sender exists
1334    #[cfg(not(all(feature = "simulation", madsim)))]
1335    if let Some(tx) = LOGGER_TX.get() {
1336        let _ = tx.send(LogEvent::Close);
1337    }
1338
1339    if let Some(handle) = LOGGER_HANDLE.lock().take()
1340        && handle.thread().id() != std::thread::current().id()
1341    {
1342        let _ = handle.join();
1343    }
1344
1345    LOGGING_INITIALIZED.store(false, Ordering::SeqCst);
1346    *lifecycle = LoggerLifecycle::Terminated;
1347}
1348
1349/// Returns whether the process-global logger is running.
1350pub(crate) fn is_running() -> bool {
1351    *LOGGER_LIFECYCLE.lock() == LoggerLifecycle::Running
1352}
1353
1354/// Flushes and syncs file logs to disk through the logging thread.
1355///
1356/// This is a no-op when logging is not initialized or file logging is disabled.
1357///
1358/// # Errors
1359///
1360/// Returns an error if the sync request cannot be delivered or acknowledged.
1361pub fn sync_to_disk() -> anyhow::Result<()> {
1362    #[cfg(all(feature = "simulation", madsim))]
1363    {
1364        Ok(())
1365    }
1366
1367    #[cfg(not(all(feature = "simulation", madsim)))]
1368    {
1369        let lifecycle = LOGGER_LIFECYCLE.lock();
1370
1371        if *lifecycle != LoggerLifecycle::Running {
1372            return Ok(());
1373        }
1374
1375        let Some(tx) = LOGGER_TX.get() else {
1376            anyhow::bail!("Logging is running without a published sender");
1377        };
1378
1379        sync_sender_to_disk(tx)
1380    }
1381}
1382
1383#[cfg(not(all(feature = "simulation", madsim)))]
1384fn sync_sender_to_disk(tx: &std::sync::mpsc::Sender<LogEvent>) -> anyhow::Result<()> {
1385    let (done_tx, done_rx) = std::sync::mpsc::channel();
1386    tx.send(LogEvent::Sync(done_tx))
1387        .map_err(|e| anyhow::anyhow!("failed to request logging sync: {e}"))?;
1388
1389    done_rx
1390        .recv()
1391        .map_err(|e| anyhow::anyhow!("failed to receive logging sync acknowledgement: {e}"))?
1392}
1393
1394/// Logs a message with the given level, color, and component.
1395pub fn log<T: AsRef<str>>(level: LogLevel, color: LogColor, component: Ustr, message: T) {
1396    let color = Value::from(color as u8);
1397
1398    match level {
1399        LogLevel::Off => {}
1400        LogLevel::Trace => {
1401            log::trace!(component = component.to_value(), color = color; "{}", message.as_ref());
1402        }
1403        LogLevel::Debug => {
1404            log::debug!(component = component.to_value(), color = color; "{}", message.as_ref());
1405        }
1406        LogLevel::Info => {
1407            log::info!(component = component.to_value(), color = color; "{}", message.as_ref());
1408        }
1409        LogLevel::Warning => {
1410            log::warn!(component = component.to_value(), color = color; "{}", message.as_ref());
1411        }
1412        LogLevel::Error => {
1413            log::error!(component = component.to_value(), color = color; "{}", message.as_ref());
1414        }
1415    }
1416}
1417
1418/// A guard that manages the lifecycle of the logging subsystem.
1419///
1420/// `LogGuard` tracks active users of the process-global logging subsystem. Dropping the last guard
1421/// synchronously flushes and syncs pending file logs, but leaves the logging thread running so a
1422/// later initialization can acquire a valid guard. Only [`crate::logging::logging_shutdown`]
1423/// permanently terminates the logging thread.
1424///
1425/// # Reference Counting
1426///
1427/// The logging system maintains a global atomic counter of active `LogGuard` instances. This
1428/// ensures that:
1429/// - The logging thread remains active for the process lifetime, including while no guards exist.
1430/// - Pending log messages are flushed when intermediate guards are dropped.
1431/// - Pending file logs are synchronously flushed and synced when the last guard is dropped.
1432///
1433/// # Shutdown Behavior
1434///
1435/// Call [`crate::logging::logging_shutdown`] for terminal shutdown. After shutdown, no new guards
1436/// can be acquired and the logger cannot be re-initialized.
1437///
1438/// **Python on Windows:** Non-deterministic GC order during interpreter shutdown can
1439/// occasionally prevent proper thread join, resulting in truncated logs.
1440///
1441/// # Limits
1442///
1443/// The system supports a maximum of 255 concurrent `LogGuard` instances.
1444#[cfg_attr(feature = "python", pyo3::pyclass(module = "nautilus_trader.common"))]
1445#[cfg_attr(
1446    feature = "python",
1447    pyo3_stub_gen::derive::gen_stub_pyclass(module = "nautilus_trader.common")
1448)]
1449#[derive(Debug)]
1450pub struct LogGuard {
1451    #[cfg(not(all(feature = "simulation", madsim)))]
1452    tx: std::sync::mpsc::Sender<LogEvent>,
1453}
1454
1455impl LogGuard {
1456    /// Creates a new [`LogGuard`] instance from the global logger.
1457    ///
1458    /// Returns `None` if logging has not been initialized or the active `LogGuard`
1459    /// count would exceed 255.
1460    #[must_use]
1461    pub fn new() -> Option<Self> {
1462        let lifecycle = LOGGER_LIFECYCLE.lock();
1463
1464        Self::new_from_lifecycle(&lifecycle)
1465    }
1466
1467    fn new_from_lifecycle(lifecycle: &LoggerLifecycle) -> Option<Self> {
1468        if *lifecycle != LoggerLifecycle::Running {
1469            return None;
1470        }
1471
1472        Self::new_locked()
1473    }
1474
1475    #[cfg(all(test, not(all(feature = "simulation", madsim))))]
1476    fn try_new_for_test() -> TestGuardAcquire {
1477        match LOGGER_LIFECYCLE.try_lock() {
1478            Some(lifecycle) => TestGuardAcquire::Acquired(Self::new_from_lifecycle(&lifecycle)),
1479            None => TestGuardAcquire::LifecycleBusy,
1480        }
1481    }
1482
1483    fn new_locked() -> Option<Self> {
1484        #[cfg(not(all(feature = "simulation", madsim)))]
1485        let tx = LOGGER_TX.get()?;
1486        #[cfg(all(feature = "simulation", madsim))]
1487        LOGGER_TX.get()?;
1488        LOGGING_GUARDS_ACTIVE
1489            .try_update(Ordering::SeqCst, Ordering::SeqCst, |count| {
1490                if count == u8::MAX {
1491                    None
1492                } else {
1493                    Some(count + 1)
1494                }
1495            })
1496            .ok()?;
1497
1498        Some(Self {
1499            #[cfg(not(all(feature = "simulation", madsim)))]
1500            tx: tx.clone(),
1501        })
1502    }
1503}
1504
1505impl Drop for LogGuard {
1506    /// Handles cleanup when a `LogGuard` is dropped.
1507    ///
1508    /// Sends `Flush` if other guards remain active. The last guard synchronously flushes and syncs
1509    /// file output while leaving the process-global logging thread running.
1510    fn drop(&mut self) {
1511        let lifecycle = LOGGER_LIFECYCLE.lock();
1512        let previous_count = LOGGING_GUARDS_ACTIVE
1513            .try_update(Ordering::SeqCst, Ordering::SeqCst, |count| {
1514                assert!(count != 0, "LogGuard reference count underflow");
1515                Some(count - 1)
1516            })
1517            .expect("Failed to decrement LogGuard count");
1518
1519        if *lifecycle != LoggerLifecycle::Running {
1520            return;
1521        }
1522
1523        #[cfg(all(feature = "simulation", madsim))]
1524        let _ = previous_count;
1525
1526        #[cfg(not(all(feature = "simulation", madsim)))]
1527        if previous_count == 1 {
1528            if let Err(e) = sync_sender_to_disk(&self.tx) {
1529                let _ = writeln!(
1530                    io::stderr(),
1531                    "Error syncing logs after dropping the last LogGuard: {e}"
1532                );
1533            }
1534        } else {
1535            // Other LogGuards are still active, just flush our logs
1536            let _ = self.tx.send(LogEvent::Flush);
1537        }
1538    }
1539}
1540
1541#[cfg(test)]
1542mod tests {
1543    use ahash::AHashMap;
1544    use log::LevelFilter;
1545    use nautilus_core::UUID4;
1546    use nautilus_model::identifiers::TraderId;
1547    use rstest::*;
1548    use serde_json::Value;
1549    use tempfile::tempdir;
1550    use ustr::Ustr;
1551
1552    use super::*;
1553    use crate::enums::LogColor;
1554
1555    #[rstest]
1556    fn log_message_serialization() {
1557        let log_message = LogLine {
1558            timestamp: UnixNanos::default(),
1559            level: log::Level::Info,
1560            color: LogColor::Normal,
1561            component: Ustr::from("Portfolio"),
1562            message: "This is a log message".to_string(),
1563            fields: SmallVec::new(),
1564        };
1565
1566        let serialized_json = serde_json::to_string(&log_message).unwrap();
1567        let deserialized_value: Value = serde_json::from_str(&serialized_json).unwrap();
1568
1569        assert_eq!(deserialized_value["level"], "INFO");
1570        assert_eq!(deserialized_value["component"], "Portfolio");
1571        assert_eq!(deserialized_value["message"], "This is a log message");
1572    }
1573
1574    #[rstest]
1575    fn log_config_parsing() {
1576        let config =
1577            LoggerConfig::from_spec("stdout=Info;is_colored;fileout=Debug;RiskEngine=Error")
1578                .unwrap();
1579        assert_eq!(
1580            config,
1581            LoggerConfig {
1582                stdout_level: LevelFilter::Info,
1583                fileout_level: LevelFilter::Debug,
1584                component_level: AHashMap::from_iter(vec![(
1585                    Ustr::from("RiskEngine"),
1586                    LevelFilter::Error
1587                )]),
1588                module_level: AHashMap::new(),
1589                log_components_only: false,
1590                is_colored: true,
1591                print_config: false,
1592                use_tracing: false,
1593                ..Default::default()
1594            }
1595        );
1596    }
1597
1598    #[rstest]
1599    fn log_config_parsing2() {
1600        let config = LoggerConfig::from_spec("stdout=Warn;print_config;fileout=Error;").unwrap();
1601        assert_eq!(
1602            config,
1603            LoggerConfig {
1604                stdout_level: LevelFilter::Warn,
1605                fileout_level: LevelFilter::Error,
1606                component_level: AHashMap::new(),
1607                module_level: AHashMap::new(),
1608                log_components_only: false,
1609                is_colored: true,
1610                print_config: true,
1611                use_tracing: false,
1612                ..Default::default()
1613            }
1614        );
1615    }
1616
1617    #[rstest]
1618    fn log_config_parsing_with_log_components_only() {
1619        let config =
1620            LoggerConfig::from_spec("stdout=Info;log_components_only;RiskEngine=Debug").unwrap();
1621        assert_eq!(
1622            config,
1623            LoggerConfig {
1624                stdout_level: LevelFilter::Info,
1625                fileout_level: LevelFilter::Off,
1626                component_level: AHashMap::from_iter(vec![(
1627                    Ustr::from("RiskEngine"),
1628                    LevelFilter::Debug
1629                )]),
1630                module_level: AHashMap::new(),
1631                log_components_only: true,
1632                is_colored: true,
1633                print_config: false,
1634                use_tracing: false,
1635                ..Default::default()
1636            }
1637        );
1638    }
1639
1640    #[rstest]
1641    fn test_log_line_wrapper_plain_string() {
1642        let line = LogLine {
1643            timestamp: 1_650_000_000_000_000_000.into(),
1644            level: log::Level::Info,
1645            color: LogColor::Normal,
1646            component: Ustr::from("TestComponent"),
1647            message: "Test message".to_string(),
1648            fields: SmallVec::new(),
1649        };
1650
1651        let mut wrapper = LogLineWrapper::new(line, Ustr::from("TRADER-001"));
1652        let result = wrapper.get_string();
1653
1654        assert!(result.contains("TRADER-001"));
1655        assert!(result.contains("TestComponent"));
1656        assert!(result.contains("Test message"));
1657        assert!(result.contains("[INFO]"));
1658        assert!(result.ends_with('\n'));
1659        // Should NOT contain ANSI codes
1660        assert!(!result.contains("\x1b["));
1661    }
1662
1663    #[rstest]
1664    fn test_log_line_wrapper_colored_string() {
1665        let line = LogLine {
1666            timestamp: 1_650_000_000_000_000_000.into(),
1667            level: log::Level::Info,
1668            color: LogColor::Green,
1669            component: Ustr::from("TestComponent"),
1670            message: "Test message".to_string(),
1671            fields: SmallVec::new(),
1672        };
1673
1674        let mut wrapper = LogLineWrapper::new(line, Ustr::from("TRADER-001"));
1675        let result = wrapper.get_colored();
1676
1677        assert!(result.contains("TRADER-001"));
1678        assert!(result.contains("TestComponent"));
1679        assert!(result.contains("Test message"));
1680        // Should contain ANSI codes
1681        assert!(result.contains("\x1b["));
1682        assert!(result.ends_with('\n'));
1683    }
1684
1685    #[rstest]
1686    fn test_log_line_wrapper_json_output() {
1687        let line = LogLine {
1688            timestamp: 1_650_000_000_000_000_000.into(),
1689            level: log::Level::Warn,
1690            color: LogColor::Yellow,
1691            component: Ustr::from("RiskEngine"),
1692            message: "Warning message".to_string(),
1693            fields: SmallVec::new(),
1694        };
1695
1696        let wrapper = LogLineWrapper::new(line, Ustr::from("TRADER-002"));
1697        let json = wrapper.get_json();
1698
1699        let parsed: Value = serde_json::from_str(json.trim()).unwrap();
1700        assert_eq!(parsed["trader_id"], "TRADER-002");
1701        assert_eq!(parsed["component"], "RiskEngine");
1702        assert_eq!(parsed["message"], "Warning message");
1703        assert_eq!(parsed["level"], "WARN");
1704        assert_eq!(parsed["color"], "YELLOW");
1705    }
1706
1707    #[rstest]
1708    fn test_log_line_wrapper_caches_string() {
1709        let line = LogLine {
1710            timestamp: 1_650_000_000_000_000_000.into(),
1711            level: log::Level::Info,
1712            color: LogColor::Normal,
1713            component: Ustr::from("Test"),
1714            message: "Cached".to_string(),
1715            fields: SmallVec::new(),
1716        };
1717
1718        let mut wrapper = LogLineWrapper::new(line, Ustr::from("TRADER"));
1719        let first = wrapper.get_string().to_string();
1720        let second = wrapper.get_string().to_string();
1721
1722        assert_eq!(first, second);
1723    }
1724
1725    #[rstest]
1726    fn test_log_line_display() {
1727        let line = LogLine {
1728            timestamp: 0.into(),
1729            level: log::Level::Error,
1730            color: LogColor::Red,
1731            component: Ustr::from("Component"),
1732            message: "Error occurred".to_string(),
1733            fields: SmallVec::new(),
1734        };
1735
1736        let display = format!("{line}");
1737        assert_eq!(display, "[ERROR] Component: Error occurred");
1738    }
1739
1740    #[rstest]
1741    fn test_log_line_display_with_fields() {
1742        let line = LogLine {
1743            timestamp: 0.into(),
1744            level: log::Level::Info,
1745            color: LogColor::Normal,
1746            component: Ustr::from("RiskEngine"),
1747            message: "Order filled".to_string(),
1748            fields: smallvec::smallvec![
1749                (Ustr::from("venue"), "BINANCE".to_string()),
1750                (Ustr::from("order_id"), "O-001".to_string()),
1751            ],
1752        };
1753
1754        let display = format!("{line}");
1755        assert_eq!(
1756            display,
1757            "[INFO] RiskEngine: Order filled venue=BINANCE order_id=O-001"
1758        );
1759    }
1760
1761    #[rstest]
1762    fn test_log_line_wrapper_plain_string_with_fields() {
1763        let line = LogLine {
1764            timestamp: 1_650_000_000_000_000_000.into(),
1765            level: log::Level::Info,
1766            color: LogColor::Normal,
1767            component: Ustr::from("DataEngine"),
1768            message: "Connected".to_string(),
1769            fields: smallvec::smallvec![
1770                (Ustr::from("venue"), "BINANCE".to_string()),
1771                (Ustr::from("product_type"), "SPOT".to_string()),
1772            ],
1773        };
1774
1775        let mut wrapper = LogLineWrapper::new(line, Ustr::from("TRADER-001"));
1776        let result = wrapper.get_string();
1777
1778        assert!(result.contains("Connected"));
1779        assert!(result.contains("venue=BINANCE"));
1780        assert!(result.contains("product_type=SPOT"));
1781        assert!(result.ends_with('\n'));
1782        assert!(!result.contains("\x1b["));
1783    }
1784
1785    #[rstest]
1786    fn test_log_line_wrapper_json_with_fields() {
1787        let line = LogLine {
1788            timestamp: 1_650_000_000_000_000_000.into(),
1789            level: log::Level::Info,
1790            color: LogColor::Normal,
1791            component: Ustr::from("RiskEngine"),
1792            message: "Order filled".to_string(),
1793            fields: smallvec::smallvec![
1794                (Ustr::from("strategy_id"), "S-001".to_string()),
1795                (Ustr::from("venue"), "BINANCE".to_string()),
1796            ],
1797        };
1798
1799        let wrapper = LogLineWrapper::new(line, Ustr::from("TRADER-001"));
1800        let json = wrapper.get_json();
1801
1802        let parsed: Value = serde_json::from_str(json.trim()).unwrap();
1803        assert_eq!(parsed["component"], "RiskEngine");
1804        assert_eq!(parsed["message"], "Order filled");
1805        assert_eq!(parsed["strategy_id"], "S-001");
1806        assert_eq!(parsed["venue"], "BINANCE");
1807    }
1808
1809    #[rstest]
1810    fn test_log_line_wrapper_json_no_fields_has_no_extra_keys() {
1811        let line = LogLine {
1812            timestamp: 1_650_000_000_000_000_000.into(),
1813            level: log::Level::Info,
1814            color: LogColor::Normal,
1815            component: Ustr::from("Test"),
1816            message: "Simple".to_string(),
1817            fields: SmallVec::new(),
1818        };
1819
1820        let wrapper = LogLineWrapper::new(line, Ustr::from("TRADER-001"));
1821        let json = wrapper.get_json();
1822
1823        let parsed: Value = serde_json::from_str(json.trim()).unwrap();
1824        let obj = parsed.as_object().unwrap();
1825        assert_eq!(obj.len(), 6); // timestamp, trader_id, level, color, component, message
1826    }
1827
1828    #[rstest]
1829    fn test_log_line_wrapper_json_reserved_keys_not_overwritten() {
1830        let line = LogLine {
1831            timestamp: 1_650_000_000_000_000_000.into(),
1832            level: log::Level::Warn,
1833            color: LogColor::Normal,
1834            component: Ustr::from("Test"),
1835            message: "Real message".to_string(),
1836            fields: smallvec::smallvec![
1837                (Ustr::from("level"), "FAKE".to_string()),
1838                (Ustr::from("message"), "injected".to_string()),
1839                (Ustr::from("timestamp"), "bogus".to_string()),
1840                (Ustr::from("venue"), "BINANCE".to_string()),
1841            ],
1842        };
1843
1844        let wrapper = LogLineWrapper::new(line, Ustr::from("TRADER-001"));
1845        let json = wrapper.get_json();
1846        let parsed: Value = serde_json::from_str(json.trim()).unwrap();
1847
1848        assert_eq!(parsed["level"], "WARN");
1849        assert_eq!(parsed["message"], "Real message");
1850        assert_ne!(parsed["timestamp"], "bogus");
1851        assert_eq!(parsed["venue"], "BINANCE");
1852    }
1853
1854    #[rstest]
1855    fn test_log_line_wrapper_json_duplicate_extra_fields_last_value_wins() {
1856        let line = LogLine {
1857            timestamp: 1_650_000_000_000_000_000.into(),
1858            level: log::Level::Info,
1859            color: LogColor::Normal,
1860            component: Ustr::from("Test"),
1861            message: "Duplicate field".to_string(),
1862            fields: smallvec::smallvec![
1863                (Ustr::from("venue"), "BINANCE".to_string()),
1864                (Ustr::from("venue"), "OKX".to_string()),
1865            ],
1866        };
1867
1868        let wrapper = LogLineWrapper::new(line, Ustr::from("TRADER-001"));
1869        let json = wrapper.get_json();
1870        let parsed: Value = serde_json::from_str(json.trim()).unwrap();
1871
1872        assert_eq!(json.matches("\"venue\"").count(), 1);
1873        assert_eq!(parsed["venue"], "OKX");
1874    }
1875
1876    /// Converts the module-level map to a vector sorted by descending path length.
1877    fn sorted_module_filters(map: AHashMap<Ustr, LevelFilter>) -> Vec<(Ustr, LevelFilter)> {
1878        let mut v: Vec<_> = map.into_iter().collect();
1879        v.sort_by_key(|b| std::cmp::Reverse(b.0.len()));
1880        v
1881    }
1882
1883    #[rstest]
1884    fn test_filter_no_filters_passes_all() {
1885        let module_filters = vec![];
1886        let component_level = AHashMap::new();
1887
1888        assert!(!should_filter_log(
1889            &Ustr::from("anything"),
1890            Level::Trace,
1891            &module_filters,
1892            &component_level,
1893            false
1894        ));
1895    }
1896
1897    #[rstest]
1898    fn test_filter_component_exact_match() {
1899        let module_filters = vec![];
1900        let component_level = AHashMap::from_iter([(Ustr::from("RiskEngine"), LevelFilter::Error)]);
1901
1902        assert!(should_filter_log(
1903            &Ustr::from("RiskEngine"),
1904            Level::Info,
1905            &module_filters,
1906            &component_level,
1907            false
1908        ));
1909        assert!(!should_filter_log(
1910            &Ustr::from("RiskEngine"),
1911            Level::Error,
1912            &module_filters,
1913            &component_level,
1914            false
1915        ));
1916        assert!(!should_filter_log(
1917            &Ustr::from("Portfolio"),
1918            Level::Info,
1919            &module_filters,
1920            &component_level,
1921            false
1922        ));
1923    }
1924
1925    #[rstest]
1926    fn test_filter_module_prefix_match() {
1927        let module_filters = vec![(Ustr::from("nautilus_okx::websocket"), LevelFilter::Debug)];
1928        let component_level = AHashMap::new();
1929
1930        assert!(!should_filter_log(
1931            &Ustr::from("nautilus_okx::websocket"),
1932            Level::Debug,
1933            &module_filters,
1934            &component_level,
1935            false
1936        ));
1937        assert!(!should_filter_log(
1938            &Ustr::from("nautilus_okx::websocket::handler"),
1939            Level::Debug,
1940            &module_filters,
1941            &component_level,
1942            false
1943        ));
1944        assert!(should_filter_log(
1945            &Ustr::from("nautilus_okx::websocket::handler"),
1946            Level::Trace,
1947            &module_filters,
1948            &component_level,
1949            false
1950        ));
1951        assert!(!should_filter_log(
1952            &Ustr::from("nautilus_binance::data"),
1953            Level::Trace,
1954            &module_filters,
1955            &component_level,
1956            false
1957        ));
1958    }
1959
1960    #[rstest]
1961    fn test_filter_longest_prefix_wins() {
1962        let module_filters = sorted_module_filters(AHashMap::from_iter([
1963            (Ustr::from("nautilus_okx"), LevelFilter::Error),
1964            (Ustr::from("nautilus_okx::websocket"), LevelFilter::Debug),
1965        ]));
1966        let component_level = AHashMap::new();
1967
1968        assert!(!should_filter_log(
1969            &Ustr::from("nautilus_okx::websocket::handler"),
1970            Level::Debug,
1971            &module_filters,
1972            &component_level,
1973            false
1974        ));
1975        assert!(should_filter_log(
1976            &Ustr::from("nautilus_okx::data"),
1977            Level::Debug,
1978            &module_filters,
1979            &component_level,
1980            false
1981        ));
1982        assert!(!should_filter_log(
1983            &Ustr::from("nautilus_okx::data"),
1984            Level::Error,
1985            &module_filters,
1986            &component_level,
1987            false
1988        ));
1989    }
1990
1991    #[rstest]
1992    fn test_filter_module_precedence_over_component() {
1993        let module_filters = vec![(Ustr::from("nautilus_okx::websocket"), LevelFilter::Debug)];
1994        let component_level =
1995            AHashMap::from_iter([(Ustr::from("nautilus_okx::websocket"), LevelFilter::Error)]);
1996
1997        assert!(!should_filter_log(
1998            &Ustr::from("nautilus_okx::websocket"),
1999            Level::Debug,
2000            &module_filters,
2001            &component_level,
2002            false
2003        ));
2004    }
2005
2006    #[rstest]
2007    fn test_filter_log_components_only_blocks_unknown() {
2008        let module_filters = vec![];
2009        let component_level = AHashMap::from_iter([(Ustr::from("RiskEngine"), LevelFilter::Debug)]);
2010
2011        assert!(should_filter_log(
2012            &Ustr::from("Portfolio"),
2013            Level::Info,
2014            &module_filters,
2015            &component_level,
2016            true
2017        ));
2018        assert!(!should_filter_log(
2019            &Ustr::from("RiskEngine"),
2020            Level::Info,
2021            &module_filters,
2022            &component_level,
2023            true
2024        ));
2025    }
2026
2027    #[rstest]
2028    fn test_filter_log_components_only_with_module() {
2029        let module_filters = vec![(Ustr::from("nautilus_okx"), LevelFilter::Debug)];
2030        let component_level = AHashMap::new();
2031
2032        assert!(!should_filter_log(
2033            &Ustr::from("nautilus_okx::websocket"),
2034            Level::Debug,
2035            &module_filters,
2036            &component_level,
2037            true
2038        ));
2039        assert!(should_filter_log(
2040            &Ustr::from("nautilus_binance::data"),
2041            Level::Debug,
2042            &module_filters,
2043            &component_level,
2044            true
2045        ));
2046    }
2047
2048    #[rstest]
2049    fn test_filter_level_comparison() {
2050        let module_filters = vec![];
2051        let component_level = AHashMap::from_iter([(Ustr::from("Test"), LevelFilter::Warn)]);
2052
2053        assert!(!should_filter_log(
2054            &Ustr::from("Test"),
2055            Level::Error,
2056            &module_filters,
2057            &component_level,
2058            false
2059        ));
2060        assert!(!should_filter_log(
2061            &Ustr::from("Test"),
2062            Level::Warn,
2063            &module_filters,
2064            &component_level,
2065            false
2066        ));
2067        assert!(should_filter_log(
2068            &Ustr::from("Test"),
2069            Level::Info,
2070            &module_filters,
2071            &component_level,
2072            false
2073        ));
2074        assert!(should_filter_log(
2075            &Ustr::from("Test"),
2076            Level::Debug,
2077            &module_filters,
2078            &component_level,
2079            false
2080        ));
2081        assert!(should_filter_log(
2082            &Ustr::from("Test"),
2083            Level::Trace,
2084            &module_filters,
2085            &component_level,
2086            false
2087        ));
2088    }
2089
2090    // These tests use global logging state (one logger per process).
2091    // They run correctly with cargo-nextest which isolates each test in its own process.
2092    //
2093    // Gated out under `cfg(madsim)`: every test here drives the file-logging writer
2094    // thread, which is itself gated out under simulation (see `Logger::init_with_config`),
2095    // so log events are dropped and these tests would either hang on `wait_until` or
2096    // assert against an empty log file. Logging is outside the determinism contract.
2097    #[cfg(not(all(feature = "simulation", madsim)))]
2098    mod serial_tests {
2099        use std::{sync::atomic::Ordering, time::Duration};
2100
2101        use super::*;
2102        use crate::{
2103            logging::{
2104                LOGGING_BYPASSED, logging_clock_set_static_mode, logging_clock_set_static_time,
2105                logging_is_initialized, logging_set_bypass, logging_sync_to_disk,
2106            },
2107            testing::wait_until,
2108        };
2109
2110        #[rstest]
2111        fn test_shutdown_on_error_records_once_then_rearms() {
2112            disarm_shutdown_on_error();
2113
2114            let (tx, _rx) = std::sync::mpsc::channel();
2115            let logger = Logger::new_for_benchmark(LoggerConfig::default(), tx);
2116
2117            arm_shutdown_on_error(false);
2118            let args = format_args!("Disabled error");
2119            let record = log::Record::builder()
2120                .args(args)
2121                .level(Level::Error)
2122                .target("RunComponent")
2123                .build();
2124            log::Log::log(&logger, &record);
2125            assert_eq!(take_shutdown_on_error_trigger(), None);
2126
2127            arm_shutdown_on_error(true);
2128            let args = format_args!("First error");
2129            let record = log::Record::builder()
2130                .args(args)
2131                .level(Level::Error)
2132                .target("RunComponent")
2133                .build();
2134            log::Log::log(&logger, &record);
2135
2136            let args = format_args!("Second error");
2137            let record = log::Record::builder()
2138                .args(args)
2139                .level(Level::Error)
2140                .target("RunComponent")
2141                .build();
2142            log::Log::log(&logger, &record);
2143
2144            let first = take_shutdown_on_error_trigger().unwrap();
2145            assert_eq!(first.component, Ustr::from("RunComponent"));
2146            assert_eq!(first.message, "First error");
2147            assert_eq!(take_shutdown_on_error_trigger(), None);
2148
2149            arm_shutdown_on_error(true);
2150            let args = format_args!("Third error");
2151            let record = log::Record::builder()
2152                .args(args)
2153                .level(Level::Error)
2154                .target("RunComponent")
2155                .build();
2156            log::Log::log(&logger, &record);
2157
2158            let third = take_shutdown_on_error_trigger().unwrap();
2159            assert_eq!(third.component, Ustr::from("RunComponent"));
2160            assert_eq!(third.message, "Third error");
2161
2162            let (tx, rx) = std::sync::mpsc::channel();
2163            let logger = Logger::new_for_benchmark(
2164                LoggerConfig {
2165                    log_components_only: true,
2166                    ..Default::default()
2167                },
2168                tx,
2169            );
2170
2171            arm_shutdown_on_error(true);
2172            let args = format_args!("Filtered error");
2173            let record = log::Record::builder()
2174                .args(args)
2175                .level(Level::Error)
2176                .target("FilteredComponent")
2177                .build();
2178            log::Log::log(&logger, &record);
2179
2180            let trigger = take_shutdown_on_error_trigger().unwrap();
2181            assert_eq!(trigger.component, Ustr::from("FilteredComponent"));
2182            assert_eq!(trigger.message, "Filtered error");
2183            assert!(matches!(
2184                rx.try_recv(),
2185                Err(std::sync::mpsc::TryRecvError::Empty)
2186            ));
2187            disarm_shutdown_on_error();
2188        }
2189
2190        #[rstest]
2191        fn test_shutdown_on_error_records_bypassed_error() {
2192            LOGGING_BYPASSED.store(false, Ordering::Relaxed);
2193            disarm_shutdown_on_error();
2194
2195            let (tx, rx) = std::sync::mpsc::channel();
2196            let logger = Logger::new_for_benchmark(LoggerConfig::default(), tx);
2197            let metadata = log::Metadata::builder()
2198                .level(Level::Error)
2199                .target("BypassedComponent")
2200                .build();
2201
2202            logging_set_bypass();
2203            arm_shutdown_on_error(false);
2204            assert!(!log::Log::enabled(&logger, &metadata));
2205
2206            arm_shutdown_on_error(true);
2207            assert!(log::Log::enabled(&logger, &metadata));
2208
2209            let args = format_args!("Bypassed error");
2210            let record = log::Record::builder()
2211                .args(args)
2212                .level(Level::Error)
2213                .target("BypassedComponent")
2214                .build();
2215            log::Log::log(&logger, &record);
2216
2217            let trigger = take_shutdown_on_error_trigger().unwrap();
2218            assert_eq!(trigger.component, Ustr::from("BypassedComponent"));
2219            assert_eq!(trigger.message, "Bypassed error");
2220            assert!(matches!(
2221                rx.try_recv(),
2222                Err(std::sync::mpsc::TryRecvError::Empty)
2223            ));
2224
2225            LOGGING_BYPASSED.store(false, Ordering::Relaxed);
2226            disarm_shutdown_on_error();
2227        }
2228
2229        #[rstest]
2230        fn test_shutdown_on_error_failed_drain_keeps_trigger_pending() {
2231            LOGGING_BYPASSED.store(false, Ordering::Relaxed);
2232            disarm_shutdown_on_error();
2233
2234            let (tx, _rx) = std::sync::mpsc::channel();
2235            let logger = Logger::new_for_benchmark(LoggerConfig::default(), tx);
2236
2237            arm_shutdown_on_error(true);
2238            let args = format_args!("Pending error");
2239            let record = log::Record::builder()
2240                .args(args)
2241                .level(Level::Error)
2242                .target("PendingComponent")
2243                .build();
2244            log::Log::log(&logger, &record);
2245
2246            let drained = try_drain_shutdown_on_error_trigger(|trigger| {
2247                assert_eq!(trigger.component, Ustr::from("PendingComponent"));
2248                assert_eq!(trigger.message, "Pending error");
2249                false
2250            });
2251            assert!(!drained);
2252
2253            let trigger = take_shutdown_on_error_trigger().unwrap();
2254            assert_eq!(trigger.component, Ustr::from("PendingComponent"));
2255            assert_eq!(trigger.message, "Pending error");
2256            disarm_shutdown_on_error();
2257        }
2258
2259        #[rstest]
2260        fn test_logging_to_file() {
2261            let config = LoggerConfig {
2262                fileout_level: LevelFilter::Debug,
2263                ..Default::default()
2264            };
2265
2266            let temp_dir = tempdir().expect("Failed to create temporary directory");
2267            let file_config = FileWriterConfig {
2268                directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2269                ..Default::default()
2270            };
2271
2272            let log_guard = Logger::init_with_config(
2273                TraderId::from("TRADER-001"),
2274                UUID4::new(),
2275                config,
2276                file_config,
2277            );
2278
2279            logging_clock_set_static_mode();
2280            logging_clock_set_static_time(1_650_000_000_000_000);
2281
2282            log::info!(
2283                component = "RiskEngine";
2284                "This is a test"
2285            );
2286
2287            let mut log_contents = String::new();
2288
2289            wait_until(
2290                || {
2291                    std::fs::read_dir(&temp_dir)
2292                        .expect("Failed to read directory")
2293                        .filter_map(Result::ok)
2294                        .any(|entry| entry.path().is_file())
2295                },
2296                Duration::from_secs(3),
2297            );
2298
2299            drop(log_guard); // Ensure log buffers are flushed
2300
2301            wait_until(
2302                || {
2303                    let log_file_path = std::fs::read_dir(&temp_dir)
2304                        .expect("Failed to read directory")
2305                        .filter_map(Result::ok)
2306                        .find(|entry| entry.path().is_file())
2307                        .expect("No files found in directory")
2308                        .path();
2309                    log_contents = std::fs::read_to_string(log_file_path)
2310                        .expect("Error while reading log file");
2311                    !log_contents.is_empty()
2312                },
2313                Duration::from_secs(3),
2314            );
2315
2316            assert_eq!(
2317                log_contents,
2318                "1970-01-20T02:20:00.000000000Z [INFO] TRADER-001.RiskEngine: This is a test\n"
2319            );
2320        }
2321
2322        #[rstest]
2323        fn test_logging_sync_to_disk_flushes_fast_flush_policy() {
2324            let config = LoggerConfig {
2325                fileout_level: LevelFilter::Debug,
2326                fileout_sync_on_flush: false,
2327                ..Default::default()
2328            };
2329
2330            let temp_dir = tempdir().expect("Failed to create temporary directory");
2331            let file_config = FileWriterConfig {
2332                directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2333                ..Default::default()
2334            };
2335
2336            let log_guard = Logger::init_with_config(
2337                TraderId::from("TRADER-SYNC"),
2338                UUID4::new(),
2339                config,
2340                file_config,
2341            )
2342            .expect("Failed to initialize logger");
2343
2344            logging_clock_set_static_mode();
2345            logging_clock_set_static_time(1_650_000_000_000_000);
2346
2347            log::info!(
2348                component = "RiskEngine";
2349                "sync me"
2350            );
2351
2352            logging_sync_to_disk().expect("sync-to-disk should succeed");
2353
2354            let log_file_path = std::fs::read_dir(&temp_dir)
2355                .expect("Failed to read directory")
2356                .filter_map(Result::ok)
2357                .find(|entry| entry.path().is_file())
2358                .expect("No files found in directory")
2359                .path();
2360            let log_contents =
2361                std::fs::read_to_string(log_file_path).expect("Error while reading log file");
2362
2363            assert!(log_contents.contains("sync me"));
2364
2365            drop(log_guard);
2366        }
2367
2368        #[rstest]
2369        fn test_logging_to_file_flushes_without_sync() {
2370            let config = LoggerConfig {
2371                stdout_level: LevelFilter::Off,
2372                fileout_level: LevelFilter::Info,
2373                ..Default::default()
2374            };
2375
2376            let temp_dir = tempdir().expect("Failed to create temporary directory");
2377
2378            let file_config = FileWriterConfig {
2379                directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2380                ..Default::default()
2381            };
2382
2383            let log_guard = Logger::init_with_config(
2384                TraderId::from("TRADER-FLUSH"),
2385                UUID4::new(),
2386                config,
2387                file_config,
2388            )
2389            .expect("Failed to initialize logger");
2390
2391            log::info!(component = "RiskEngine"; "flushed on interval");
2392
2393            // No sync or guard drop: the line must reach the file through the interval flush
2394            wait_until(
2395                || {
2396                    std::fs::read_dir(&temp_dir)
2397                        .expect("Failed to read directory")
2398                        .filter_map(Result::ok)
2399                        .filter(|entry| entry.path().is_file())
2400                        .any(|entry| {
2401                            std::fs::read_to_string(entry.path())
2402                                .is_ok_and(|contents| contents.contains("flushed on interval"))
2403                        })
2404                },
2405                Duration::from_secs(3),
2406            );
2407
2408            drop(log_guard);
2409        }
2410
2411        #[rstest]
2412        fn test_init_returns_error_when_log_directory_is_unusable() {
2413            let config = LoggerConfig {
2414                stdout_level: LevelFilter::Off,
2415                fileout_level: LevelFilter::Info,
2416                ..Default::default()
2417            };
2418
2419            let temp_dir = tempdir().expect("Failed to create temporary directory");
2420            let blocking_file = temp_dir.path().join("not_a_directory");
2421            std::fs::write(&blocking_file, "").expect("Failed to create blocking file");
2422
2423            let error = Logger::init_with_config(
2424                TraderId::from("TRADER-FAIL"),
2425                UUID4::new(),
2426                config.clone(),
2427                FileWriterConfig {
2428                    directory: Some(blocking_file.to_str().unwrap().to_string()),
2429                    ..Default::default()
2430                },
2431            )
2432            .expect_err("init must fail when the log directory cannot be created");
2433
2434            assert_eq!(
2435                error.to_string(),
2436                format!("failed to create log directory {}", blocking_file.display())
2437            );
2438            assert!(!logging_is_initialized());
2439
2440            // A failed init leaves the lifecycle open for a corrected retry
2441            let log_guard = Logger::init_with_config(
2442                TraderId::from("TRADER-FAIL"),
2443                UUID4::new(),
2444                config,
2445                FileWriterConfig {
2446                    directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2447                    ..Default::default()
2448                },
2449            )
2450            .expect("init with a usable directory must succeed after a failed attempt");
2451
2452            assert!(logging_is_initialized());
2453
2454            drop(log_guard);
2455        }
2456
2457        #[rstest]
2458        fn test_recv_event_flushes_file_after_a_batch_of_queued_events() {
2459            let temp_dir = tempdir().expect("Failed to create temporary directory");
2460            let file_config = FileWriterConfig {
2461                directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2462                ..Default::default()
2463            };
2464            let file_writer = FileWriter::new(
2465                "TRADER-001".to_string(),
2466                "instance-123".to_string(),
2467                file_config,
2468                LevelFilter::Info,
2469                false,
2470                false,
2471            )
2472            .expect("Failed to create file writer");
2473            let mut file_writer_opt = Some(file_writer);
2474            let (tx, rx) = std::sync::mpsc::channel();
2475
2476            // Console-only traffic: queued events that never fill the file buffer
2477            for _ in 0..=FILE_FLUSH_CHECK_EVENTS {
2478                tx.send(LogEvent::Flush).unwrap();
2479            }
2480            file_writer_opt
2481                .as_mut()
2482                .unwrap()
2483                .write("pending file line\n");
2484            let mut file_flush_due = Instant::now();
2485            let mut queued_since_check = 0;
2486            let log_contents = || {
2487                let entry = std::fs::read_dir(&temp_dir)
2488                    .unwrap()
2489                    .next()
2490                    .unwrap()
2491                    .unwrap();
2492                std::fs::read_to_string(entry.path()).unwrap()
2493            };
2494
2495            for _ in 1..FILE_FLUSH_CHECK_EVENTS {
2496                Logger::recv_event(
2497                    &rx,
2498                    &mut file_writer_opt,
2499                    &mut file_flush_due,
2500                    &mut queued_since_check,
2501                )
2502                .unwrap();
2503            }
2504            let contents_before_check = log_contents();
2505            Logger::recv_event(
2506                &rx,
2507                &mut file_writer_opt,
2508                &mut file_flush_due,
2509                &mut queued_since_check,
2510            )
2511            .unwrap();
2512
2513            assert_eq!(contents_before_check, "");
2514            assert_eq!(log_contents(), "pending file line\n");
2515            assert_eq!(queued_since_check, 0);
2516            assert!(
2517                rx.try_recv().is_ok(),
2518                "the flush must happen while events are still queued"
2519            );
2520        }
2521
2522        #[rstest]
2523        fn test_last_guard_drop_syncs_backlog_tail() {
2524            const N: usize = 1000;
2525
2526            // Configure file logging at Info level
2527            let config = LoggerConfig {
2528                stdout_level: LevelFilter::Off,
2529                fileout_level: LevelFilter::Info,
2530                ..Default::default()
2531            };
2532
2533            let temp_dir = tempdir().expect("Failed to create temporary directory");
2534            let file_config = FileWriterConfig {
2535                directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2536                ..Default::default()
2537            };
2538
2539            let log_guard = Logger::init_with_config(
2540                TraderId::from("TRADER-TAIL"),
2541                UUID4::new(),
2542                config,
2543                file_config,
2544            )
2545            .expect("Failed to initialize logger");
2546
2547            // Use static time for reproducibility
2548            logging_clock_set_static_mode();
2549            logging_clock_set_static_time(1_700_000_000_000_000);
2550
2551            // Enqueue a known number of messages synchronously
2552            for i in 0..N {
2553                log::info!(component = "TailDrain"; "BacklogTest {i}");
2554            }
2555
2556            // Drop the last guard to synchronously flush and sync pending messages.
2557            drop(log_guard);
2558
2559            // Wait until the file exists and contains at least N lines with our marker
2560            let mut count = 0usize;
2561            wait_until(
2562                || {
2563                    if let Some(log_file) = std::fs::read_dir(&temp_dir)
2564                        .expect("Failed to read directory")
2565                        .filter_map(Result::ok)
2566                        .find(|entry| entry.path().is_file())
2567                    {
2568                        let log_file_path = log_file.path();
2569                        if let Ok(contents) = std::fs::read_to_string(log_file_path) {
2570                            count = contents
2571                                .lines()
2572                                .filter(|l| l.contains("BacklogTest "))
2573                                .count();
2574                            count >= N
2575                        } else {
2576                            false
2577                        }
2578                    } else {
2579                        false
2580                    }
2581                },
2582                Duration::from_secs(5),
2583            );
2584
2585            assert_eq!(count, N, "Expected all pending messages to be written");
2586        }
2587
2588        #[rstest]
2589        fn test_log_component_level_filtering() {
2590            let config =
2591                LoggerConfig::from_spec("stdout=Info;fileout=Debug;RiskEngine=Error").unwrap();
2592
2593            let temp_dir = tempdir().expect("Failed to create temporary directory");
2594            let file_config = FileWriterConfig {
2595                directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2596                ..Default::default()
2597            };
2598
2599            let log_guard = Logger::init_with_config(
2600                TraderId::from("TRADER-001"),
2601                UUID4::new(),
2602                config,
2603                file_config,
2604            );
2605
2606            logging_clock_set_static_mode();
2607            logging_clock_set_static_time(1_650_000_000_000_000);
2608
2609            log::info!(
2610                component = "RiskEngine";
2611                "This is a test"
2612            );
2613
2614            drop(log_guard); // Ensure log buffers are flushed
2615
2616            wait_until(
2617                || {
2618                    if let Some(log_file) = std::fs::read_dir(&temp_dir)
2619                        .expect("Failed to read directory")
2620                        .filter_map(Result::ok)
2621                        .find(|entry| entry.path().is_file())
2622                    {
2623                        let log_file_path = log_file.path();
2624                        let log_contents = std::fs::read_to_string(log_file_path)
2625                            .expect("Error while reading log file");
2626                        !log_contents.contains("RiskEngine")
2627                    } else {
2628                        false
2629                    }
2630                },
2631                Duration::from_secs(3),
2632            );
2633
2634            assert!(
2635                std::fs::read_dir(&temp_dir)
2636                    .expect("Failed to read directory")
2637                    .filter_map(Result::ok)
2638                    .any(|entry| entry.path().is_file()),
2639                "Log file exists"
2640            );
2641        }
2642
2643        #[rstest]
2644        fn test_logging_to_file_in_json_format() {
2645            let config =
2646                LoggerConfig::from_spec("stdout=Info;is_colored;fileout=Debug;RiskEngine=Info")
2647                    .unwrap();
2648
2649            let temp_dir = tempdir().expect("Failed to create temporary directory");
2650            let file_config = FileWriterConfig {
2651                directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2652                file_format: Some("json".to_string()),
2653                ..Default::default()
2654            };
2655
2656            let log_guard = Logger::init_with_config(
2657                TraderId::from("TRADER-001"),
2658                UUID4::new(),
2659                config,
2660                file_config,
2661            );
2662
2663            logging_clock_set_static_mode();
2664            logging_clock_set_static_time(1_650_000_000_000_000);
2665
2666            log::info!(
2667                component = "RiskEngine";
2668                "This is a test"
2669            );
2670
2671            let mut log_contents = String::new();
2672
2673            drop(log_guard); // Ensure log buffers are flushed
2674
2675            wait_until(
2676                || {
2677                    if let Some(log_file) = std::fs::read_dir(&temp_dir)
2678                        .expect("Failed to read directory")
2679                        .filter_map(Result::ok)
2680                        .find(|entry| entry.path().is_file())
2681                    {
2682                        let log_file_path = log_file.path();
2683                        log_contents = std::fs::read_to_string(log_file_path)
2684                            .expect("Error while reading log file");
2685                        !log_contents.is_empty()
2686                    } else {
2687                        false
2688                    }
2689                },
2690                Duration::from_secs(3),
2691            );
2692
2693            assert_eq!(
2694                log_contents,
2695                "{\"timestamp\":\"1970-01-20T02:20:00.000000000Z\",\"trader_id\":\"TRADER-001\",\"level\":\"INFO\",\"color\":\"NORMAL\",\"component\":\"RiskEngine\",\"message\":\"This is a test\"}\n"
2696            );
2697        }
2698
2699        #[rstest]
2700        fn test_init_sets_logging_is_initialized_flag() {
2701            let config = LoggerConfig::default();
2702            let file_config = FileWriterConfig::default();
2703
2704            let guard = Logger::init_with_config(
2705                TraderId::from("TRADER-001"),
2706                UUID4::new(),
2707                config,
2708                file_config,
2709            );
2710            assert!(guard.is_ok());
2711            assert!(logging_is_initialized());
2712
2713            drop(guard);
2714            assert!(logging_is_initialized());
2715        }
2716
2717        #[rstest]
2718        fn test_init_returns_error_when_log_guard_limit_reached() {
2719            let guard = Logger::init_with_config(
2720                TraderId::from("TRADER-001"),
2721                UUID4::new(),
2722                LoggerConfig::default(),
2723                FileWriterConfig::default(),
2724            )
2725            .expect("Failed to initialize logger");
2726
2727            LOGGING_GUARDS_ACTIVE.store(u8::MAX, Ordering::SeqCst);
2728            let result = Logger::init_with_config(
2729                TraderId::from("TRADER-001"),
2730                UUID4::new(),
2731                LoggerConfig::default(),
2732                FileWriterConfig::default(),
2733            );
2734            LOGGING_GUARDS_ACTIVE.store(1, Ordering::SeqCst);
2735            drop(guard);
2736
2737            assert_eq!(
2738                result.unwrap_err().to_string(),
2739                "Logging already initialized but new guard could not be created"
2740            );
2741        }
2742
2743        #[rstest]
2744        fn test_reinit_after_guard_drop_returns_live_guard() {
2745            let config = LoggerConfig::default();
2746            let file_config = FileWriterConfig::default();
2747
2748            let guard1 = Logger::init_with_config(
2749                TraderId::from("TRADER-001"),
2750                UUID4::new(),
2751                config.clone(),
2752                file_config.clone(),
2753            );
2754            assert!(guard1.is_ok());
2755            drop(guard1);
2756
2757            let guard2 = Logger::init_with_config(
2758                TraderId::from("TRADER-002"),
2759                UUID4::new(),
2760                config,
2761                file_config,
2762            );
2763            assert!(guard2.is_ok());
2764        }
2765
2766        #[rstest]
2767        fn test_bypass_before_init_prevents_logging() {
2768            logging_set_bypass();
2769            assert!(LOGGING_BYPASSED.load(Ordering::Relaxed));
2770
2771            let temp_dir = tempdir().expect("Failed to create temporary directory");
2772            let config = LoggerConfig {
2773                fileout_level: LevelFilter::Debug,
2774                ..Default::default()
2775            };
2776            let file_config = FileWriterConfig {
2777                directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2778                ..Default::default()
2779            };
2780
2781            let guard = Logger::init_with_config(
2782                TraderId::from("TRADER-001"),
2783                UUID4::new(),
2784                config,
2785                file_config,
2786            );
2787            assert!(guard.is_ok());
2788
2789            log::info!(
2790                component = "TestComponent";
2791                "This should be bypassed"
2792            );
2793            std::thread::sleep(Duration::from_millis(100));
2794            drop(guard);
2795
2796            // Bypass flag remains permanently set (no reset mechanism)
2797            assert!(LOGGING_BYPASSED.load(Ordering::Relaxed));
2798        }
2799
2800        #[rstest]
2801        fn test_module_level_filtering() {
2802            // Configure module-level filters (note: requires :: to be a module filter):
2803            // - nautilus::adapters=Warn (general adapter logs at Warn+)
2804            // - nautilus::adapters::okx=Debug (OKX adapter logs at Debug+)
2805            let config = LoggerConfig::from_spec(
2806                "stdout=Off;fileout=Trace;nautilus::adapters=Warn;nautilus::adapters::okx=Debug",
2807            )
2808            .unwrap();
2809
2810            let temp_dir = tempdir().expect("Failed to create temporary directory");
2811            let file_config = FileWriterConfig {
2812                directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2813                ..Default::default()
2814            };
2815
2816            let log_guard = Logger::init_with_config(
2817                TraderId::from("TRADER-MOD"),
2818                UUID4::new(),
2819                config,
2820                file_config,
2821            )
2822            .expect("Failed to initialize logger");
2823
2824            logging_clock_set_static_mode();
2825            logging_clock_set_static_time(1_650_000_000_000_000);
2826
2827            // Log from nautilus::adapters::okx::websocket - should pass (Debug allowed)
2828            log::debug!(
2829                component = "nautilus::adapters::okx::websocket";
2830                "OKX debug message"
2831            );
2832
2833            // Log from nautilus::adapters::okx - should pass (Debug allowed)
2834            log::info!(
2835                component = "nautilus::adapters::okx";
2836                "OKX info message"
2837            );
2838
2839            // Log from nautilus::adapters::binance - should be filtered (only Warn+ allowed)
2840            log::info!(
2841                component = "nautilus::adapters::binance";
2842                "Binance info message SHOULD NOT APPEAR"
2843            );
2844
2845            // Log from nautilus::adapters::binance at Warn - should pass
2846            log::warn!(
2847                component = "nautilus::adapters::binance";
2848                "Binance warn message"
2849            );
2850
2851            // Log from unrelated component - should pass (no filter)
2852            log::trace!(
2853                component = "Portfolio";
2854                "Portfolio trace message"
2855            );
2856
2857            drop(log_guard);
2858
2859            wait_until(
2860                || {
2861                    std::fs::read_dir(&temp_dir)
2862                        .expect("Failed to read directory")
2863                        .filter_map(Result::ok)
2864                        .any(|entry| entry.path().is_file())
2865                },
2866                Duration::from_secs(3),
2867            );
2868
2869            let log_file_path = std::fs::read_dir(&temp_dir)
2870                .expect("Failed to read directory")
2871                .filter_map(Result::ok)
2872                .find(|entry| entry.path().is_file())
2873                .expect("No log file found")
2874                .path();
2875
2876            let log_contents =
2877                std::fs::read_to_string(log_file_path).expect("Error reading log file");
2878
2879            assert!(
2880                log_contents.contains("OKX debug message"),
2881                "OKX debug should pass (longer prefix wins)"
2882            );
2883            assert!(
2884                log_contents.contains("OKX info message"),
2885                "OKX info should pass"
2886            );
2887            assert!(
2888                log_contents.contains("Binance warn message"),
2889                "Binance warn should pass"
2890            );
2891            assert!(
2892                log_contents.contains("Portfolio trace message"),
2893                "Unfiltered component should pass"
2894            );
2895            assert!(
2896                !log_contents.contains("SHOULD NOT APPEAR"),
2897                "Binance info should be filtered (adapters=Warn)"
2898            );
2899        }
2900
2901        #[rstest]
2902        fn test_logging_to_file_with_kv_fields() {
2903            let config = LoggerConfig {
2904                fileout_level: LevelFilter::Debug,
2905                ..Default::default()
2906            };
2907
2908            let temp_dir = tempdir().expect("Failed to create temporary directory");
2909            let file_config = FileWriterConfig {
2910                directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2911                ..Default::default()
2912            };
2913
2914            let log_guard = Logger::init_with_config(
2915                TraderId::from("TRADER-001"),
2916                UUID4::new(),
2917                config,
2918                file_config,
2919            );
2920
2921            logging_clock_set_static_mode();
2922            logging_clock_set_static_time(1_650_000_000_000_000);
2923
2924            log::info!(
2925                component = "DataEngine",
2926                venue = "BINANCE",
2927                product_type = "SPOT";
2928                "WebSocket connected"
2929            );
2930
2931            let mut log_contents = String::new();
2932
2933            drop(log_guard);
2934
2935            wait_until(
2936                || {
2937                    if let Some(log_file) = std::fs::read_dir(&temp_dir)
2938                        .expect("Failed to read directory")
2939                        .filter_map(Result::ok)
2940                        .find(|entry| entry.path().is_file())
2941                    {
2942                        log_contents = std::fs::read_to_string(log_file.path())
2943                            .expect("Error while reading log file");
2944                        !log_contents.is_empty()
2945                    } else {
2946                        false
2947                    }
2948                },
2949                Duration::from_secs(3),
2950            );
2951
2952            assert!(
2953                log_contents.contains("WebSocket connected"),
2954                "Message should be present"
2955            );
2956            assert!(
2957                log_contents.contains("venue=BINANCE"),
2958                "venue field should appear in output, was:\n{log_contents}"
2959            );
2960            assert!(
2961                log_contents.contains("product_type=SPOT"),
2962                "product_type field should appear in output, was:\n{log_contents}"
2963            );
2964        }
2965
2966        #[rstest]
2967        fn test_logging_to_file_json_with_kv_fields() {
2968            let config =
2969                LoggerConfig::from_spec("stdout=Off;fileout=Debug;DataEngine=Debug").unwrap();
2970
2971            let temp_dir = tempdir().expect("Failed to create temporary directory");
2972            let file_config = FileWriterConfig {
2973                directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2974                file_format: Some("json".to_string()),
2975                ..Default::default()
2976            };
2977
2978            let log_guard = Logger::init_with_config(
2979                TraderId::from("TRADER-001"),
2980                UUID4::new(),
2981                config,
2982                file_config,
2983            );
2984
2985            logging_clock_set_static_mode();
2986            logging_clock_set_static_time(1_650_000_000_000_000);
2987
2988            log::info!(
2989                component = "DataEngine",
2990                venue = "BINANCE",
2991                order_id = "O-12345";
2992                "Order filled"
2993            );
2994
2995            let mut log_contents = String::new();
2996
2997            drop(log_guard);
2998
2999            wait_until(
3000                || {
3001                    if let Some(log_file) = std::fs::read_dir(&temp_dir)
3002                        .expect("Failed to read directory")
3003                        .filter_map(Result::ok)
3004                        .find(|entry| entry.path().is_file())
3005                    {
3006                        log_contents = std::fs::read_to_string(log_file.path())
3007                            .expect("Error while reading log file");
3008                        !log_contents.is_empty()
3009                    } else {
3010                        false
3011                    }
3012                },
3013                Duration::from_secs(3),
3014            );
3015
3016            let parsed: serde_json::Value =
3017                serde_json::from_str(log_contents.trim()).expect("Should be valid JSON");
3018            assert_eq!(parsed["component"], "DataEngine");
3019            assert_eq!(parsed["message"], "Order filled");
3020            assert_eq!(parsed["venue"], "BINANCE");
3021            assert_eq!(parsed["order_id"], "O-12345");
3022        }
3023    }
3024
3025    #[cfg(not(all(feature = "simulation", madsim)))]
3026    mod lifecycle_tests {
3027        use std::{
3028            process::Command,
3029            sync::{Arc, Barrier},
3030        };
3031
3032        use super::*;
3033        use crate::logging::{logging_is_initialized, logging_shutdown, logging_sync_to_disk};
3034
3035        const LIFECYCLE_CHILD_ENV: &str = "NAUTILUS_LOGGER_LIFECYCLE_CHILD";
3036
3037        fn in_lifecycle_child(marker: &str) -> bool {
3038            std::env::var(LIFECYCLE_CHILD_ENV).as_deref() == Ok(marker)
3039        }
3040
3041        fn run_lifecycle_child(test_name: &str, marker: &str) {
3042            let output = Command::new(std::env::current_exe().expect("test executable must exist"))
3043                .arg(test_name)
3044                .arg("--nocapture")
3045                .arg("--test-threads=1")
3046                .env(LIFECYCLE_CHILD_ENV, marker)
3047                .output()
3048                .expect("lifecycle child process must start");
3049
3050            assert!(
3051                output.status.success(),
3052                "lifecycle child failed with {}\nstdout:\n{}\nstderr:\n{}",
3053                output.status,
3054                String::from_utf8_lossy(&output.stdout),
3055                String::from_utf8_lossy(&output.stderr),
3056            );
3057        }
3058
3059        #[rstest]
3060        fn test_init_publish_boundary_serializes_guard_acquisition() {
3061            const MARKER: &str = "init-publish-boundary";
3062            if !in_lifecycle_child(MARKER) {
3063                run_lifecycle_child(
3064                    "test_init_publish_boundary_serializes_guard_acquisition",
3065                    MARKER,
3066                );
3067                return;
3068            }
3069
3070            let (publish_reached_tx, publish_reached_rx) = std::sync::mpsc::channel();
3071            let (publish_resume_tx, publish_resume_rx) = std::sync::mpsc::channel();
3072            *INIT_PUBLISH_HOOK.lock() = Some(InitPublishHook {
3073                reached: publish_reached_tx,
3074                resume: publish_resume_rx,
3075            });
3076
3077            let init_thread = std::thread::spawn(|| {
3078                Logger::init_with_config(
3079                    TraderId::from("TRADER-BOUNDARY"),
3080                    UUID4::new(),
3081                    LoggerConfig {
3082                        stdout_level: LevelFilter::Off,
3083                        ..Default::default()
3084                    },
3085                    FileWriterConfig::default(),
3086                )
3087            });
3088            publish_reached_rx
3089                .recv()
3090                .expect("initializer must reach the install/publish boundary");
3091
3092            // This seam proves initialization retains LOGGER_LIFECYCLE through publication.
3093            // Public LogGuard::new() coverage belongs to the contention and sequential tests.
3094            assert!(
3095                matches!(
3096                    LogGuard::try_new_for_test(),
3097                    TestGuardAcquire::LifecycleBusy
3098                ),
3099                "initializer must hold the lifecycle mutex before sender publication completes"
3100            );
3101
3102            publish_resume_tx
3103                .send(())
3104                .expect("initializer must resume publication");
3105            let init_guard = init_thread
3106                .join()
3107                .expect("initializer thread must not panic")
3108                .expect("initialization must succeed");
3109            let TestGuardAcquire::Acquired(Some(second_guard)) = LogGuard::try_new_for_test()
3110            else {
3111                panic!("publication must release the lifecycle mutex and expose a valid guard");
3112            };
3113            drop((init_guard, second_guard));
3114            logging_shutdown();
3115        }
3116
3117        #[rstest]
3118        fn test_concurrent_init_high_contention() {
3119            const MARKER: &str = "concurrent-init";
3120            const THREADS: usize = 64;
3121
3122            if !in_lifecycle_child(MARKER) {
3123                run_lifecycle_child("test_concurrent_init_high_contention", MARKER);
3124                return;
3125            }
3126
3127            let barrier = Arc::new(Barrier::new(THREADS));
3128            let mut threads = Vec::with_capacity(THREADS);
3129            for index in 0..THREADS {
3130                let barrier = Arc::clone(&barrier);
3131                threads.push(std::thread::spawn(move || {
3132                    barrier.wait();
3133                    Logger::init_with_config(
3134                        TraderId::from(format!("TRADER-{index:02}")),
3135                        UUID4::new(),
3136                        LoggerConfig {
3137                            stdout_level: LevelFilter::Off,
3138                            ..Default::default()
3139                        },
3140                        FileWriterConfig::default(),
3141                    )
3142                }));
3143            }
3144
3145            let guards = threads
3146                .into_iter()
3147                .map(|thread| {
3148                    thread
3149                        .join()
3150                        .expect("initializer thread must not panic")
3151                        .expect("every concurrent initialization must return a guard")
3152                })
3153                .collect::<Vec<_>>();
3154            logging_sync_to_disk().expect("logging sync must succeed after concurrent init");
3155            drop(guards);
3156            logging_shutdown();
3157        }
3158
3159        #[rstest]
3160        fn test_sequential_init_reuses_live_worker_and_original_file() {
3161            const MARKER: &str = "sequential-init";
3162            if !in_lifecycle_child(MARKER) {
3163                run_lifecycle_child(
3164                    "test_sequential_init_reuses_live_worker_and_original_file",
3165                    MARKER,
3166                );
3167                return;
3168            }
3169
3170            let temp_dir = tempdir().expect("temporary directory must be created");
3171            let config = LoggerConfig {
3172                stdout_level: LevelFilter::Off,
3173                fileout_level: LevelFilter::Info,
3174                ..Default::default()
3175            };
3176            let file_config = FileWriterConfig {
3177                directory: Some(temp_dir.path().to_str().unwrap().to_string()),
3178                ..Default::default()
3179            };
3180
3181            let first_guard = Logger::init_with_config(
3182                TraderId::from("TRADER-SEQUENTIAL"),
3183                UUID4::new(),
3184                config,
3185                file_config,
3186            )
3187            .expect("first initialization must succeed");
3188            log::info!(component = "LifecycleTest"; "lifecycle marker A");
3189            drop(first_guard);
3190
3191            assert!(logging_is_initialized());
3192            assert!(is_running());
3193
3194            let second_guard = Logger::init_with_config(
3195                TraderId::from("TRADER-IGNORED"),
3196                UUID4::new(),
3197                LoggerConfig::default(),
3198                FileWriterConfig::default(),
3199            )
3200            .expect("second initialization must return a live guard");
3201            log::info!(component = "LifecycleTest"; "lifecycle marker B");
3202            logging_sync_to_disk().expect("logging sync must succeed after re-acquisition");
3203
3204            let log_path = std::fs::read_dir(&temp_dir)
3205                .expect("log directory must be readable")
3206                .filter_map(Result::ok)
3207                .find(|entry| entry.path().is_file())
3208                .expect("original logger must create a log file")
3209                .path();
3210            let contents = std::fs::read_to_string(log_path).expect("log file must be readable");
3211            assert!(contents.contains("lifecycle marker A"));
3212            assert!(contents.contains("lifecycle marker B"));
3213
3214            drop(second_guard);
3215            logging_shutdown();
3216
3217            let error = Logger::init_with_config(
3218                TraderId::from("TRADER-TERMINATED"),
3219                UUID4::new(),
3220                LoggerConfig::default(),
3221                FileWriterConfig::default(),
3222            )
3223            .expect_err("initialization after terminal shutdown must fail");
3224            assert_eq!(
3225                error.to_string(),
3226                "Logging has been shut down and cannot be re-initialized"
3227            );
3228        }
3229
3230        #[cfg(unix)]
3231        #[rstest]
3232        fn test_logging_survives_closed_stderr_pipe() {
3233            use std::{process::Stdio, time::Duration};
3234
3235            use crate::testing::wait_until;
3236
3237            const MARKER: &str = "closed-stderr";
3238
3239            if !in_lifecycle_child(MARKER) {
3240                // Close the read end of the child's stderr pipe so its ERROR writes fail with EPIPE
3241                let mut child =
3242                    Command::new(std::env::current_exe().expect("test executable must exist"))
3243                        .arg("test_logging_survives_closed_stderr_pipe")
3244                        .arg("--nocapture")
3245                        .arg("--test-threads=1")
3246                        .env(LIFECYCLE_CHILD_ENV, MARKER)
3247                        .stdout(Stdio::piped())
3248                        .stderr(Stdio::piped())
3249                        .spawn()
3250                        .expect("lifecycle child process must start");
3251                drop(child.stderr.take());
3252                let output = child
3253                    .wait_with_output()
3254                    .expect("lifecycle child process must finish");
3255
3256                assert!(
3257                    output.status.success(),
3258                    "lifecycle child failed with {}\nstdout:\n{}",
3259                    output.status,
3260                    String::from_utf8_lossy(&output.stdout),
3261                );
3262                return;
3263            }
3264
3265            wait_until(
3266                || io::stderr().write_all(b"\n").is_err(),
3267                Duration::from_secs(5),
3268            );
3269
3270            let temp_dir = tempdir().expect("temporary directory must be created");
3271
3272            let config = LoggerConfig {
3273                stdout_level: LevelFilter::Off,
3274                fileout_level: LevelFilter::Info,
3275                ..Default::default()
3276            };
3277
3278            let file_config = FileWriterConfig {
3279                directory: Some(temp_dir.path().to_str().unwrap().to_string()),
3280                ..Default::default()
3281            };
3282
3283            let guard = Logger::init_with_config(
3284                TraderId::from("TRADER-STDERR"),
3285                UUID4::new(),
3286                config,
3287                file_config,
3288            )
3289            .expect("initialization must succeed");
3290            log::error!(component = "StderrTest"; "error with closed stderr");
3291            log::info!(component = "StderrTest"; "info after stderr failure");
3292            logging_sync_to_disk().expect("logging thread must survive a closed stderr");
3293
3294            let log_path = std::fs::read_dir(&temp_dir)
3295                .expect("log directory must be readable")
3296                .filter_map(Result::ok)
3297                .find(|entry| entry.path().is_file())
3298                .expect("logger must create a log file")
3299                .path();
3300            let contents = std::fs::read_to_string(log_path).expect("log file must be readable");
3301            assert!(contents.contains("error with closed stderr"));
3302            assert!(contents.contains("info after stderr failure"));
3303
3304            drop(guard);
3305            logging_shutdown();
3306        }
3307    }
3308
3309    #[cfg(all(feature = "simulation", madsim))]
3310    mod sim_tests {
3311        use std::sync::atomic::Ordering;
3312
3313        use super::*;
3314        use crate::logging::LOGGING_BYPASSED;
3315
3316        #[rstest]
3317        fn test_init_under_madsim_skips_writer_thread_and_forces_bypass() {
3318            let config = LoggerConfig {
3319                bypass_logging: false,
3320                ..Default::default()
3321            };
3322            let temp_dir = tempdir().expect("Failed to create temporary directory");
3323            let file_config = FileWriterConfig {
3324                directory: Some(temp_dir.path().to_str().unwrap().to_string()),
3325                ..Default::default()
3326            };
3327
3328            let _guard = Logger::init_with_config(
3329                TraderId::from("TRADER-SIM"),
3330                UUID4::new(),
3331                config,
3332                file_config,
3333            )
3334            .expect("init should succeed under simulation");
3335
3336            assert!(LOGGING_INITIALIZED.load(Ordering::SeqCst));
3337            assert!(
3338                LOGGING_BYPASSED.load(Ordering::SeqCst),
3339                "bypass must be forced under cfg(madsim) even when config disables it"
3340            );
3341            assert!(
3342                LOGGER_HANDLE.lock().is_none(),
3343                "writer thread must not be spawned under cfg(madsim)"
3344            );
3345        }
3346    }
3347}