1use 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#[cfg(not(all(feature = "simulation", madsim)))]
66const FILE_FLUSH_INTERVAL: Duration = Duration::from_millis(100);
67
68#[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
95pub type LogFields = SmallVec<[(Ustr, String); LOG_FIELDS_INLINE_CAP]>;
98
99static LOGGER_TX: OnceLock<std::sync::mpsc::Sender<LogEvent>> = OnceLock::new();
101
102static 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
112static 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#[derive(Debug, Clone, PartialEq, Eq)]
134pub struct ShutdownOnErrorTrigger {
135 pub timestamp: UnixNanos,
137 pub component: Ustr,
139 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
229pub fn arm_shutdown_on_error(enabled: bool) {
231 shutdown_on_error().arm(enabled);
232}
233
234pub fn disarm_shutdown_on_error() {
236 shutdown_on_error().disarm();
237}
238
239pub fn take_shutdown_on_error_trigger() -> Option<ShutdownOnErrorTrigger> {
241 shutdown_on_error().take_trigger()
242}
243
244pub 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#[derive(Debug, Clone)]
258struct FilterPolicy {
259 modules_by_longest_prefix: Vec<(Ustr, LevelFilter)>,
261 components: AHashMap<Ustr, LevelFilter>,
263 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#[derive(Debug)]
301pub struct Logger {
302 pub config: LoggerConfig,
307 filter_policy: Option<FilterPolicy>,
309 tx: std::sync::mpsc::Sender<LogEvent>,
311}
312
313#[derive(Debug)]
315pub enum LogEvent {
316 Log(LogLine),
318 Flush,
320 Sync(std::sync::mpsc::Sender<anyhow::Result<()>>),
322 Close,
324}
325
326#[derive(Clone, Debug, Serialize, Deserialize)]
328pub struct LogLine {
329 pub timestamp: UnixNanos,
331 pub level: Level,
333 pub color: LogColor,
335 pub component: Ustr,
337 pub message: String,
339 #[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#[derive(Clone, Debug)]
361pub struct LogLineWrapper {
362 line: LogLine,
364 cache: Option<String>,
366 colored: Option<String>,
368 trader_id: Ustr,
370}
371
372impl LogLineWrapper {
373 #[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 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 ×tamp,
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 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 ×tamp,
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 #[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", ×tamp)?;
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 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 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 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 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 #[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 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 #[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 #[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 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 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 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 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 }
1151 }
1152 };
1153
1154 let mut file_flush_due = Instant::now() + FILE_FLUSH_INTERVAL; let mut queued_since_check = 0;
1156
1157 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 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 while let Ok(evt) = rx.try_recv() {
1189 match evt {
1190 LogEvent::Close => (), _ => process_event(
1192 evt,
1193 &mut stdout_writer,
1194 &mut stderr_writer,
1195 &mut file_writer_opt,
1196 ),
1197 }
1198 }
1199
1200 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 #[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(); 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#[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 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
1310 .or(component_filter)
1311 .is_some_and(|filter_level| line_level > filter_level)
1312}
1313
1314pub(crate) fn shutdown_graceful() {
1323 let mut lifecycle = LOGGER_LIFECYCLE.lock();
1324
1325 if *lifecycle == LoggerLifecycle::Terminated {
1326 return;
1327 }
1328
1329 LOGGING_BYPASSED.store(true, Ordering::SeqCst);
1331 log::set_max_level(log::LevelFilter::Off);
1332
1333 #[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
1349pub(crate) fn is_running() -> bool {
1351 *LOGGER_LIFECYCLE.lock() == LoggerLifecycle::Running
1352}
1353
1354pub 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
1394pub 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#[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 #[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 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 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 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 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); }
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 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 #[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); 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 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 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 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 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 logging_clock_set_static_mode();
2549 logging_clock_set_static_time(1_700_000_000_000_000);
2550
2551 for i in 0..N {
2553 log::info!(component = "TailDrain"; "BacklogTest {i}");
2554 }
2555
2556 drop(log_guard);
2558
2559 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); 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); 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 assert!(LOGGING_BYPASSED.load(Ordering::Relaxed));
2798 }
2799
2800 #[rstest]
2801 fn test_module_level_filtering() {
2802 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::debug!(
2829 component = "nautilus::adapters::okx::websocket";
2830 "OKX debug message"
2831 );
2832
2833 log::info!(
2835 component = "nautilus::adapters::okx";
2836 "OKX info message"
2837 );
2838
2839 log::info!(
2841 component = "nautilus::adapters::binance";
2842 "Binance info message SHOULD NOT APPEAR"
2843 );
2844
2845 log::warn!(
2847 component = "nautilus::adapters::binance";
2848 "Binance warn message"
2849 );
2850
2851 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 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 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}