1use std::{
19 cell::RefCell,
20 fmt::{Display, Write as _},
21 sync::{
22 OnceLock,
23 atomic::{AtomicBool, Ordering},
24 mpsc::SendError,
25 },
26};
27
28use ahash::AHashMap;
29use indexmap::IndexMap;
30use log::{
31 Level, LevelFilter, Log, STATIC_MAX_LEVEL,
32 kv::{ToValue, Value},
33 set_boxed_logger, set_max_level,
34};
35use nautilus_core::{
36 UUID4, UnixNanos,
37 datetime::unix_nanos_to_iso8601,
38 time::{get_atomic_clock_realtime, get_atomic_clock_static},
39};
40use nautilus_model::identifiers::TraderId;
41use parking_lot::Mutex;
42use serde::{Deserialize, Serialize, Serializer, ser::SerializeMap};
43use smallvec::SmallVec;
44use ustr::Ustr;
45
46pub use super::config::LoggerConfig;
47use super::{LOGGING_BYPASSED, LOGGING_GUARDS_ACTIVE, LOGGING_INITIALIZED, LOGGING_REALTIME};
48#[cfg(not(all(feature = "simulation", madsim)))]
49use crate::logging::writer::{FileWriter, LogWriter, StderrWriter, StdoutWriter};
50use crate::{
51 enums::{LogColor, LogLevel},
52 logging::writer::FileWriterConfig,
53};
54
55#[cfg(not(all(feature = "simulation", madsim)))]
56const LOGGING: &str = "logging";
57const KV_COLOR: &str = "color";
58const KV_COMPONENT: &str = "component";
59const LOG_FIELDS_INLINE_CAP: usize = 0;
60const MAX_LEVEL_DISPLAY_LEN: usize = "ERROR".len();
61const ANSI_BOLD_LEN: usize = "\x1b[1m".len();
62const ANSI_RESET_LEN: usize = "\x1b[0m".len();
63const PLAIN_FORMAT_OVERHEAD: usize = " [".len() + "] ".len() + ".".len() + ": ".len() + "\n".len();
64const COLORED_FORMAT_OVERHEAD: usize = ANSI_BOLD_LEN
65 + ANSI_RESET_LEN
66 + " ".len()
67 + "[".len()
68 + "] ".len()
69 + ".".len()
70 + ": ".len()
71 + ANSI_RESET_LEN
72 + "\n".len();
73const REPEATED_USTR_CACHE_CAP: usize = 8;
74
75thread_local! {
76 static REPEATED_USTR_CACHE: RefCell<RepeatedUstrCache> =
77 const { RefCell::new(RepeatedUstrCache::new()) };
78}
79
80pub type LogFields = SmallVec<[(Ustr, String); LOG_FIELDS_INLINE_CAP]>;
83
84static LOGGER_TX: OnceLock<std::sync::mpsc::Sender<LogEvent>> = OnceLock::new();
86
87static LOGGER_HANDLE: Mutex<Option<std::thread::JoinHandle<()>>> = Mutex::new(None);
89
90#[derive(Debug, Clone, Copy, PartialEq, Eq)]
91enum LoggerLifecycle {
92 Uninitialized,
93 Running,
94 Terminated,
95}
96
97static LOGGER_LIFECYCLE: Mutex<LoggerLifecycle> = Mutex::new(LoggerLifecycle::Uninitialized);
99
100#[cfg(all(test, not(all(feature = "simulation", madsim))))]
101struct InitPublishHook {
102 reached: std::sync::mpsc::Sender<()>,
103 resume: std::sync::mpsc::Receiver<()>,
104}
105
106#[cfg(all(test, not(all(feature = "simulation", madsim))))]
107static INIT_PUBLISH_HOOK: Mutex<Option<InitPublishHook>> = Mutex::new(None);
108
109#[cfg(all(test, not(all(feature = "simulation", madsim))))]
110enum TestGuardAcquire {
111 LifecycleBusy,
112 Acquired(Option<LogGuard>),
113}
114
115static SHUTDOWN_ON_ERROR: OnceLock<ShutdownOnError> = OnceLock::new();
116
117#[derive(Debug, Clone, PartialEq, Eq)]
119pub struct ShutdownOnErrorTrigger {
120 pub timestamp: UnixNanos,
122 pub component: Ustr,
124 pub message: String,
126}
127
128#[derive(Debug, Default)]
129struct ShutdownOnError {
130 armed: AtomicBool,
131 triggered: AtomicBool,
132 pending: Mutex<Option<ShutdownOnErrorTrigger>>,
133}
134
135impl ShutdownOnError {
136 fn is_armed(&self) -> bool {
137 self.armed.load(Ordering::Acquire)
138 }
139
140 fn arm(&self, enabled: bool) {
141 self.pending.lock().take();
142 self.triggered.store(false, Ordering::Release);
143 self.armed.store(enabled, Ordering::Release);
144 }
145
146 fn disarm(&self) {
147 self.armed.store(false, Ordering::Release);
148 self.triggered.store(false, Ordering::Release);
149
150 self.pending.lock().take();
151 }
152
153 fn maybe_record_trigger<F>(
154 &self,
155 level: Level,
156 timestamp: UnixNanos,
157 component: Ustr,
158 message: F,
159 ) where
160 F: FnOnce() -> String,
161 {
162 if !self.armed.load(Ordering::Acquire) || level != Level::Error {
163 return;
164 }
165
166 let mut pending = self.pending.lock();
167
168 if self
169 .triggered
170 .compare_exchange(false, true, Ordering::AcqRel, Ordering::Acquire)
171 .is_err()
172 {
173 return;
174 }
175
176 *pending = Some(ShutdownOnErrorTrigger {
177 timestamp,
178 component,
179 message: message(),
180 });
181 }
182
183 fn take_trigger(&self) -> Option<ShutdownOnErrorTrigger> {
184 if !self.triggered.load(Ordering::Acquire) {
185 return None;
186 }
187
188 self.pending.lock().take()
189 }
190
191 fn try_drain_trigger<F>(&self, drain: F) -> bool
192 where
193 F: FnOnce(&ShutdownOnErrorTrigger) -> bool,
194 {
195 if !self.triggered.load(Ordering::Acquire) {
196 return false;
197 }
198
199 let mut pending = self.pending.lock();
200
201 let Some(trigger) = pending.as_ref() else {
202 return false;
203 };
204
205 if !drain(trigger) {
206 return false;
207 }
208
209 pending.take();
210 true
211 }
212}
213
214pub fn arm_shutdown_on_error(enabled: bool) {
216 shutdown_on_error().arm(enabled);
217}
218
219pub fn disarm_shutdown_on_error() {
221 shutdown_on_error().disarm();
222}
223
224pub fn take_shutdown_on_error_trigger() -> Option<ShutdownOnErrorTrigger> {
226 shutdown_on_error().take_trigger()
227}
228
229pub fn try_drain_shutdown_on_error_trigger<F>(drain: F) -> bool
231where
232 F: FnOnce(&ShutdownOnErrorTrigger) -> bool,
233{
234 shutdown_on_error().try_drain_trigger(drain)
235}
236
237fn shutdown_on_error() -> &'static ShutdownOnError {
238 SHUTDOWN_ON_ERROR.get_or_init(ShutdownOnError::default)
239}
240
241#[derive(Debug, Clone)]
243struct FilterPolicy {
244 modules_by_longest_prefix: Vec<(Ustr, LevelFilter)>,
246 components: AHashMap<Ustr, LevelFilter>,
248 components_only: bool,
250}
251
252impl FilterPolicy {
253 fn from_config(config: &LoggerConfig) -> Option<Self> {
254 let modules_by_longest_prefix = sorted_module_filters_from_map(&config.module_level);
255 if !config.log_components_only
256 && modules_by_longest_prefix.is_empty()
257 && config.component_level.is_empty()
258 {
259 return None;
260 }
261
262 Some(Self {
263 modules_by_longest_prefix,
264 components: config.component_level.clone(),
265 components_only: config.log_components_only,
266 })
267 }
268
269 fn should_skip(&self, component: &Ustr, level: Level) -> bool {
270 should_filter_log_inner(
271 component,
272 level,
273 &self.modules_by_longest_prefix,
274 &self.components,
275 self.components_only,
276 )
277 }
278}
279
280#[derive(Debug)]
286pub struct Logger {
287 pub config: LoggerConfig,
292 filter_policy: Option<FilterPolicy>,
294 tx: std::sync::mpsc::Sender<LogEvent>,
296}
297
298#[derive(Debug)]
300pub enum LogEvent {
301 Log(LogLine),
303 Flush,
305 Sync(std::sync::mpsc::Sender<anyhow::Result<()>>),
307 Close,
309}
310
311#[derive(Clone, Debug, Serialize, Deserialize)]
313pub struct LogLine {
314 pub timestamp: UnixNanos,
316 pub level: Level,
318 pub color: LogColor,
320 pub component: Ustr,
322 pub message: String,
324 #[serde(default, skip_serializing_if = "SmallVec::is_empty")]
326 pub fields: LogFields,
327}
328
329impl Display for LogLine {
330 fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
331 write!(f, "[{}] {}: {}", self.level, self.component, self.message)?;
332 for (k, v) in &self.fields {
333 write!(f, " {k}={v}")?;
334 }
335 Ok(())
336 }
337}
338
339#[derive(Clone, Debug)]
346pub struct LogLineWrapper {
347 line: LogLine,
349 cache: Option<String>,
351 colored: Option<String>,
353 trader_id: Ustr,
355}
356
357impl LogLineWrapper {
358 #[must_use]
360 pub const fn new(line: LogLine, trader_id: Ustr) -> Self {
361 Self {
362 line,
363 cache: None,
364 colored: None,
365 trader_id,
366 }
367 }
368
369 pub fn get_string(&mut self) -> &str {
374 self.cache.get_or_insert_with(|| {
375 let timestamp = unix_nanos_to_iso8601(self.line.timestamp);
376 let mut s = String::with_capacity(plain_log_line_capacity(
377 ×tamp,
378 self.trader_id,
379 &self.line,
380 ));
381
382 write!(
383 s,
384 "{} [{}] {}.{}: {}",
385 timestamp, self.line.level, self.trader_id, self.line.component, self.line.message,
386 )
387 .expect("writing to String should not fail");
388
389 for (k, v) in &self.line.fields {
390 s.push(' ');
391 s.push_str(k);
392 s.push('=');
393 s.push_str(v);
394 }
395 s.push('\n');
396 s
397 })
398 }
399
400 pub fn get_colored(&mut self) -> &str {
406 self.colored.get_or_insert_with(|| {
407 let timestamp = unix_nanos_to_iso8601(self.line.timestamp);
408 let color_ansi = self.line.color.as_ansi();
409 let mut s = String::with_capacity(colored_log_line_capacity(
410 ×tamp,
411 color_ansi,
412 self.trader_id,
413 &self.line,
414 ));
415
416 write!(
417 s,
418 "\x1b[1m{}\x1b[0m {}[{}] {}.{}: {}",
419 timestamp,
420 color_ansi,
421 self.line.level,
422 self.trader_id,
423 self.line.component,
424 self.line.message,
425 )
426 .expect("writing to String should not fail");
427
428 for (k, v) in &self.line.fields {
429 s.push(' ');
430 s.push_str(k);
431 s.push('=');
432 s.push_str(v);
433 }
434 s.push_str("\x1b[0m\n");
435 s
436 })
437 }
438
439 #[must_use]
448 pub fn get_json(&self) -> String {
449 let mut json_string =
450 serde_json::to_string(&self).expect("Error serializing log event to string");
451 json_string.push('\n');
452 json_string
453 }
454}
455
456fn formatted_fields_len(fields: &LogFields) -> usize {
457 fields.iter().map(|(k, v)| 2 + k.len() + v.len()).sum()
458}
459
460fn log_line_capacity(
461 timestamp: &str,
462 trader_id: Ustr,
463 line: &LogLine,
464 overhead: usize,
465 ansi_extra_len: usize,
466) -> usize {
467 timestamp.len()
468 + overhead
469 + ansi_extra_len
470 + MAX_LEVEL_DISPLAY_LEN
471 + trader_id.len()
472 + line.component.len()
473 + line.message.len()
474 + formatted_fields_len(&line.fields)
475}
476
477fn plain_log_line_capacity(timestamp: &str, trader_id: Ustr, line: &LogLine) -> usize {
478 log_line_capacity(timestamp, trader_id, line, PLAIN_FORMAT_OVERHEAD, 0)
479}
480
481fn colored_log_line_capacity(
482 timestamp: &str,
483 color_ansi: &str,
484 trader_id: Ustr,
485 line: &LogLine,
486) -> usize {
487 log_line_capacity(
488 timestamp,
489 trader_id,
490 line,
491 COLORED_FORMAT_OVERHEAD,
492 color_ansi.len(),
493 )
494}
495
496impl Serialize for LogLineWrapper {
497 fn serialize<S>(&self, serializer: S) -> Result<S::Ok, S::Error>
498 where
499 S: Serializer,
500 {
501 if has_duplicate_json_field(&self.line.fields) {
502 return serialize_log_line_with_indexmap(self, serializer);
503 }
504
505 let timestamp = unix_nanos_to_iso8601(self.line.timestamp);
506 let mut map = serializer.serialize_map(None)?;
507
508 map.serialize_entry("timestamp", ×tamp)?;
509 map.serialize_entry("trader_id", self.trader_id.as_str())?;
510 map.serialize_entry("level", &DisplayAsString(&self.line.level))?;
511 map.serialize_entry("color", &DisplayAsString(&self.line.color))?;
512 map.serialize_entry("component", self.line.component.as_str())?;
513 map.serialize_entry("message", &self.line.message)?;
514
515 for (k, v) in &self.line.fields {
516 let key = k.as_str();
517 if !is_reserved_json_key(key) {
518 map.serialize_entry(key, v)?;
519 }
520 }
521
522 map.end()
523 }
524}
525
526struct DisplayAsString<'a, T: ?Sized>(&'a T);
527
528impl<T> Serialize for DisplayAsString<'_, T>
529where
530 T: Display + ?Sized,
531{
532 fn serialize<S>(&self, serializer: S) -> Result<S::Ok, S::Error>
533 where
534 S: Serializer,
535 {
536 serializer.collect_str(self.0)
537 }
538}
539
540fn is_reserved_json_key(key: &str) -> bool {
541 matches!(
542 key,
543 "timestamp" | "trader_id" | "level" | "color" | "component" | "message"
544 )
545}
546
547fn has_duplicate_json_field(fields: &LogFields) -> bool {
548 if fields.is_empty() {
549 return false;
550 }
551
552 for (idx, (key, _)) in fields.iter().enumerate() {
553 let key = key.as_str();
554 if is_reserved_json_key(key) {
555 continue;
556 }
557
558 if fields
559 .iter()
560 .take(idx)
561 .any(|(prev, _)| !is_reserved_json_key(prev.as_str()) && prev.as_str() == key)
562 {
563 return true;
564 }
565 }
566
567 false
568}
569
570fn serialize_log_line_with_indexmap<S>(
571 wrapper: &LogLineWrapper,
572 serializer: S,
573) -> Result<S::Ok, S::Error>
574where
575 S: Serializer,
576{
577 let mut json_obj = IndexMap::new();
578 let timestamp = unix_nanos_to_iso8601(wrapper.line.timestamp);
579 json_obj.insert("timestamp".to_string(), timestamp);
580 json_obj.insert("trader_id".to_string(), wrapper.trader_id.to_string());
581 json_obj.insert("level".to_string(), wrapper.line.level.to_string());
582 json_obj.insert("color".to_string(), wrapper.line.color.to_string());
583 json_obj.insert("component".to_string(), wrapper.line.component.to_string());
584 json_obj.insert("message".to_string(), wrapper.line.message.clone());
585 for (k, v) in &wrapper.line.fields {
586 let key = k.as_str();
587 if !is_reserved_json_key(key) {
588 json_obj.insert(k.to_string(), v.clone());
589 }
590 }
591
592 json_obj.serialize(serializer)
593}
594
595fn sorted_module_filters_from_map(
596 module_level: &AHashMap<Ustr, LevelFilter>,
597) -> Vec<(Ustr, LevelFilter)> {
598 let mut filters: Vec<_> = module_level
599 .iter()
600 .map(|(path, level)| (*path, *level))
601 .collect();
602 filters.sort_by_key(|(path, _)| std::cmp::Reverse(path.len()));
603 filters
604}
605
606fn current_log_timestamp() -> UnixNanos {
607 if LOGGING_REALTIME.load(Ordering::Relaxed) {
608 get_atomic_clock_realtime().get_time_ns()
609 } else {
610 get_atomic_clock_static().get_time_ns()
611 }
612}
613
614fn intern_repeated(value: &str) -> Ustr {
615 REPEATED_USTR_CACHE.with(|cache| {
616 let mut cache_state = cache.borrow_mut();
617 let ptr = value.as_ptr() as usize;
618 let len = value.len();
619
620 for entry in cache_state.entries.iter().flatten() {
623 if entry.ptr == ptr && entry.len == len && entry.value.as_str() == value {
624 return entry.value;
625 }
626 }
627
628 let interned = Ustr::from(value);
629 let insert_idx = cache_state.next;
630 cache_state.entries[insert_idx] = Some(RepeatedUstrCacheEntry {
631 ptr,
632 len,
633 value: interned,
634 });
635 cache_state.next = (insert_idx + 1) % REPEATED_USTR_CACHE_CAP;
636 interned
637 })
638}
639
640#[derive(Clone, Copy)]
641struct RepeatedUstrCacheEntry {
642 ptr: usize,
643 len: usize,
644 value: Ustr,
645}
646
647#[derive(Clone, Copy)]
648struct RepeatedUstrCache {
649 entries: [Option<RepeatedUstrCacheEntry>; REPEATED_USTR_CACHE_CAP],
650 next: usize,
651}
652
653impl RepeatedUstrCache {
654 const fn new() -> Self {
655 Self {
656 entries: [None; REPEATED_USTR_CACHE_CAP],
657 next: 0,
658 }
659 }
660}
661
662fn intern_component_value(value: &log::kv::Value<'_>) -> Ustr {
663 match value.to_borrowed_str() {
664 Some(component) => intern_repeated(component),
665 None => Ustr::from(&value.to_string()),
666 }
667}
668
669#[derive(Default)]
670struct ComponentProbe {
671 component: Option<Ustr>,
672}
673
674impl<'kvs> log::kv::VisitSource<'kvs> for ComponentProbe {
675 fn visit_pair(
676 &mut self,
677 key: log::kv::Key<'kvs>,
678 value: log::kv::Value<'kvs>,
679 ) -> Result<(), log::kv::Error> {
680 if key.as_str() == KV_COMPONENT {
681 self.component = Some(intern_component_value(&value));
682 }
683 Ok(())
684 }
685}
686
687#[derive(Default)]
688struct PayloadCollector {
689 color: Option<LogColor>,
690 fields: LogFields,
691}
692
693impl<'kvs> log::kv::VisitSource<'kvs> for PayloadCollector {
694 fn visit_pair(
695 &mut self,
696 key: log::kv::Key<'kvs>,
697 value: log::kv::Value<'kvs>,
698 ) -> Result<(), log::kv::Error> {
699 match key.as_str() {
700 KV_COLOR => {
701 self.color = value.to_u64().map(|v| (v as u8).into());
702 }
703 KV_COMPONENT => {}
704 _ => {
705 self.fields
706 .push((Ustr::from(key.as_str()), value.to_string()));
707 }
708 }
709 Ok(())
710 }
711}
712
713#[derive(Default)]
714struct FieldCollector {
715 color: Option<LogColor>,
716 component: Option<Ustr>,
717 fields: LogFields,
718}
719
720impl<'kvs> log::kv::VisitSource<'kvs> for FieldCollector {
721 fn visit_pair(
722 &mut self,
723 key: log::kv::Key<'kvs>,
724 value: log::kv::Value<'kvs>,
725 ) -> Result<(), log::kv::Error> {
726 match key.as_str() {
727 KV_COLOR => {
728 self.color = value.to_u64().map(|v| (v as u8).into());
729 }
730 KV_COMPONENT => {
731 self.component = Some(intern_component_value(&value));
732 }
733 _ => {
734 self.fields
735 .push((Ustr::from(key.as_str()), value.to_string()));
736 }
737 }
738 Ok(())
739 }
740}
741
742impl Log for Logger {
743 fn enabled(&self, metadata: &log::Metadata) -> bool {
744 if LOGGING_BYPASSED.load(Ordering::Relaxed) {
745 return metadata.level() == Level::Error && shutdown_on_error().is_armed();
746 }
747
748 metadata.level() == Level::Error
749 || metadata.level() <= self.config.stdout_level
750 || metadata.level() <= self.config.fileout_level
751 }
752
753 fn log(&self, record: &log::Record) {
754 let level = record.level();
755
756 if LOGGING_BYPASSED.load(Ordering::Relaxed) {
757 if level == Level::Error {
758 record_shutdown_on_error(record);
759 }
760 return;
761 }
762
763 if self.enabled(record.metadata()) {
764 if let Some(filter_policy) = &self.filter_policy {
765 let mut probe = ComponentProbe::default();
768 let _ = record.key_values().visit(&mut probe);
769 let component = probe
770 .component
771 .unwrap_or_else(|| intern_repeated(record.metadata().target()));
772
773 if filter_policy.should_skip(&component, level) {
774 if level == Level::Error {
775 shutdown_on_error().maybe_record_trigger(
776 level,
777 current_log_timestamp(),
778 component,
779 || format!("{}", record.args()),
780 );
781 }
782 return;
783 }
784
785 let timestamp = current_log_timestamp();
786 let mut collector = PayloadCollector::default();
787 let _ = record.key_values().visit(&mut collector);
788 let color = collector.color.unwrap_or_else(|| level.into());
789
790 let line = LogLine {
791 timestamp,
792 level,
793 color,
794 component,
795 message: format!("{}", record.args()),
796 fields: collector.fields,
797 };
798
799 shutdown_on_error().maybe_record_trigger(
800 line.level,
801 line.timestamp,
802 line.component,
803 || line.message.clone(),
804 );
805 self.send_log_line(line);
806 return;
807 }
808
809 let timestamp = current_log_timestamp();
811 let mut collector = FieldCollector::default();
812 let _ = record.key_values().visit(&mut collector);
813 let color = collector.color.unwrap_or_else(|| level.into());
814 let component = collector
815 .component
816 .unwrap_or_else(|| intern_repeated(record.metadata().target()));
817
818 let line = LogLine {
819 timestamp,
820 level,
821 color,
822 component,
823 message: format!("{}", record.args()),
824 fields: collector.fields,
825 };
826
827 shutdown_on_error().maybe_record_trigger(
828 line.level,
829 line.timestamp,
830 line.component,
831 || line.message.clone(),
832 );
833 self.send_log_line(line);
834 }
835 }
836
837 fn flush(&self) {
838 if LOGGING_BYPASSED.load(Ordering::Relaxed) {
840 return;
841 }
842
843 if let Err(e) = self.tx.send(LogEvent::Flush) {
844 eprintln!("Error sending flush log event: {e}");
845 }
846 }
847}
848
849fn record_shutdown_on_error(record: &log::Record) {
850 let mut probe = ComponentProbe::default();
851 let _ = record.key_values().visit(&mut probe);
852 let component = probe
853 .component
854 .unwrap_or_else(|| intern_repeated(record.metadata().target()));
855
856 shutdown_on_error().maybe_record_trigger(
857 record.level(),
858 current_log_timestamp(),
859 component,
860 || format!("{}", record.args()),
861 );
862}
863
864impl Logger {
865 #[doc(hidden)]
870 #[must_use]
871 pub fn new_for_benchmark(config: LoggerConfig, tx: std::sync::mpsc::Sender<LogEvent>) -> Self {
872 let filter_policy = FilterPolicy::from_config(&config);
873
874 Self {
875 config,
876 filter_policy,
877 tx,
878 }
879 }
880
881 fn send_log_line(&self, line: LogLine) {
882 if let Err(SendError(LogEvent::Log(line))) = self.tx.send(LogEvent::Log(line)) {
883 eprintln!("Error sending log event (receiver closed): {line}");
884 }
885 }
886
887 pub fn init_with_env(
893 trader_id: TraderId,
894 instance_id: UUID4,
895 file_config: FileWriterConfig,
896 ) -> anyhow::Result<LogGuard> {
897 let config = LoggerConfig::from_env()?;
898 Self::init_with_config(trader_id, instance_id, config, file_config)
899 }
900
901 #[cfg_attr(
907 not(all(feature = "simulation", madsim)),
908 expect(clippy::needless_pass_by_value)
909 )]
910 pub fn init_with_config(
911 trader_id: TraderId,
912 instance_id: UUID4,
913 config: LoggerConfig,
914 file_config: FileWriterConfig,
915 ) -> anyhow::Result<LogGuard> {
916 let mut lifecycle = LOGGER_LIFECYCLE.lock();
917
918 match *lifecycle {
919 LoggerLifecycle::Running => {
920 return LogGuard::new_locked().ok_or_else(|| {
921 anyhow::anyhow!(
922 "Logging already initialized but new guard could not be created"
923 )
924 });
925 }
926 LoggerLifecycle::Terminated => {
927 anyhow::bail!("Logging has been shut down and cannot be re-initialized");
928 }
929 LoggerLifecycle::Uninitialized => {}
930 }
931
932 let (tx, rx) = std::sync::mpsc::channel::<LogEvent>();
933 let filter_policy = FilterPolicy::from_config(&config);
934
935 #[cfg(not(all(feature = "simulation", madsim)))]
936 let handle = std::thread::Builder::new()
937 .name(LOGGING.to_string())
938 .spawn({
939 let config = config.clone();
940 let file_config = file_config.clone();
941 move || {
942 Self::handle_messages(
943 trader_id.to_string(),
944 instance_id.to_string(),
945 config,
946 file_config,
947 rx,
948 );
949 }
950 })?;
951
952 let logger = Self {
953 config: config.clone(),
954 filter_policy,
955 tx: tx.clone(),
956 };
957
958 if let Err(e) = set_boxed_logger(Box::new(logger)) {
959 #[cfg(not(all(feature = "simulation", madsim)))]
960 {
961 let _ = tx.send(LogEvent::Close);
962 if handle.thread().id() != std::thread::current().id() {
963 let _ = handle.join();
964 }
965 }
966 *lifecycle = LoggerLifecycle::Terminated;
967 return Err(e.into());
968 }
969
970 #[cfg(all(test, not(all(feature = "simulation", madsim))))]
971 if let Some(hook) = INIT_PUBLISH_HOOK.lock().take() {
972 let _ = hook.reached.send(());
973 let _ = hook.resume.recv();
974 }
975
976 if let Err(tx) = LOGGER_TX.set(tx) {
978 #[cfg(not(all(feature = "simulation", madsim)))]
979 {
980 let _ = tx.send(LogEvent::Close);
981 if handle.thread().id() != std::thread::current().id() {
982 let _ = handle.join();
983 }
984 }
985 drop(tx);
986 *lifecycle = LoggerLifecycle::Terminated;
987 anyhow::bail!("Global logging sender was already published");
988 }
989
990 if config.bypass_logging {
991 super::logging_set_bypass();
992 }
993
994 let is_colored = config.is_colored;
995
996 let print_config = config.print_config;
997 if print_config {
998 println!("STATIC_MAX_LEVEL={STATIC_MAX_LEVEL}");
999 println!("Logger initialized with {config:?} {file_config:?}");
1000 }
1001
1002 #[cfg(not(all(feature = "simulation", madsim)))]
1003 {
1004 let mut handle_guard = LOGGER_HANDLE.lock();
1006 debug_assert!(
1007 handle_guard.is_none(),
1008 "LOGGER_HANDLE already set - re-initialization not supported"
1009 );
1010 *handle_guard = Some(handle);
1011 }
1012
1013 #[cfg(all(feature = "simulation", madsim))]
1014 {
1015 let _ = (trader_id, instance_id, config, file_config, rx);
1020 super::logging_set_bypass();
1021 }
1022
1023 let max_level = log::LevelFilter::Trace;
1024 set_max_level(max_level);
1025
1026 if print_config {
1027 println!("Logger set as `log` implementation with max level {max_level}");
1028 }
1029
1030 super::LOGGING_INITIALIZED.store(true, Ordering::SeqCst);
1031 super::LOGGING_COLORED.store(is_colored, Ordering::SeqCst);
1032 *lifecycle = LoggerLifecycle::Running;
1033
1034 LogGuard::new_locked()
1035 .ok_or_else(|| anyhow::anyhow!("Failed to create LogGuard from global sender"))
1036 }
1037
1038 #[cfg(not(all(feature = "simulation", madsim)))]
1039 #[expect(clippy::needless_pass_by_value)]
1040 fn handle_messages(
1041 trader_id: String,
1042 instance_id: String,
1043 config: LoggerConfig,
1044 file_config: FileWriterConfig,
1045 rx: std::sync::mpsc::Receiver<LogEvent>,
1046 ) {
1047 let LoggerConfig {
1048 stdout_level,
1049 fileout_level,
1050 component_level: _,
1051 module_level: _,
1052 log_components_only: _,
1053 is_colored,
1054 print_config: _,
1055 use_tracing: _,
1056 bypass_logging: _,
1057 file_config: _,
1058 clear_log_file,
1059 fileout_sync_on_flush,
1060 buffered_stdout,
1061 } = config;
1062
1063 let trader_id_cache = Ustr::from(&trader_id);
1064
1065 let mut stdout_writer = StdoutWriter::new(stdout_level, is_colored, buffered_stdout);
1067 let mut stderr_writer = StderrWriter::new(is_colored);
1068
1069 let mut file_writer_opt = if fileout_level == LevelFilter::Off {
1071 None
1072 } else {
1073 FileWriter::new(
1074 trader_id,
1075 instance_id,
1076 file_config,
1077 fileout_level,
1078 clear_log_file,
1079 fileout_sync_on_flush,
1080 )
1081 };
1082
1083 let process_event = |event: LogEvent,
1084 stdout_writer: &mut StdoutWriter,
1085 stderr_writer: &mut StderrWriter,
1086 file_writer_opt: &mut Option<FileWriter>| {
1087 match event {
1088 LogEvent::Log(line) => {
1089 let mut wrapper = LogLineWrapper::new(line, trader_id_cache);
1090
1091 if stderr_writer.enabled(&wrapper.line) {
1092 if is_colored {
1093 stderr_writer.write(wrapper.get_colored());
1094 } else {
1095 stderr_writer.write(wrapper.get_string());
1096 }
1097 }
1098
1099 if stdout_writer.enabled(&wrapper.line) {
1100 if is_colored {
1101 stdout_writer.write(wrapper.get_colored());
1102 } else {
1103 stdout_writer.write(wrapper.get_string());
1104 }
1105 }
1106
1107 if let Some(file_writer) = file_writer_opt
1108 && file_writer.enabled(&wrapper.line)
1109 {
1110 if file_writer.json_format {
1111 file_writer.write(&wrapper.get_json());
1112 } else {
1113 file_writer.write(wrapper.get_string());
1114 }
1115 }
1116 }
1117 LogEvent::Flush => {
1118 stdout_writer.flush();
1119 stderr_writer.flush();
1120
1121 if let Some(file_writer) = file_writer_opt {
1122 file_writer.flush();
1123 }
1124 }
1125 LogEvent::Sync(done) => {
1126 stdout_writer.flush();
1127 stderr_writer.flush();
1128
1129 let result = if let Some(file_writer) = file_writer_opt {
1130 file_writer.flush_and_sync().map_err(anyhow::Error::from)
1131 } else {
1132 Ok(())
1133 };
1134
1135 let _ = done.send(result);
1136 }
1137 LogEvent::Close => {
1138 }
1140 }
1141 };
1142
1143 while let Ok(event) = rx.recv() {
1145 match event {
1146 LogEvent::Log(_) | LogEvent::Flush | LogEvent::Sync(_) => process_event(
1147 event,
1148 &mut stdout_writer,
1149 &mut stderr_writer,
1150 &mut file_writer_opt,
1151 ),
1152 LogEvent::Close => {
1153 stdout_writer.flush();
1155 stderr_writer.flush();
1156
1157 if let Some(ref mut file_writer) = file_writer_opt {
1158 file_writer.flush();
1159 }
1160
1161 while let Ok(evt) = rx.try_recv() {
1164 match evt {
1165 LogEvent::Close => (), _ => process_event(
1167 evt,
1168 &mut stdout_writer,
1169 &mut stderr_writer,
1170 &mut file_writer_opt,
1171 ),
1172 }
1173 }
1174
1175 stdout_writer.flush();
1177 stderr_writer.flush();
1178
1179 if let Some(ref mut file_writer) = file_writer_opt {
1180 file_writer.flush_and_sync_logged();
1181 }
1182
1183 break;
1184 }
1185 }
1186 }
1187 }
1188}
1189
1190#[must_use]
1197pub fn should_filter_log(
1198 component: &Ustr,
1199 line_level: log::Level,
1200 module_filters_sorted: &[(Ustr, LevelFilter)],
1201 component_level: &AHashMap<Ustr, LevelFilter>,
1202 log_components_only: bool,
1203) -> bool {
1204 should_filter_log_inner(
1205 component,
1206 line_level,
1207 module_filters_sorted,
1208 component_level,
1209 log_components_only,
1210 )
1211}
1212
1213fn should_filter_log_inner(
1214 component: &Ustr,
1215 line_level: log::Level,
1216 module_filters_sorted: &[(Ustr, LevelFilter)],
1217 component_level: &AHashMap<Ustr, LevelFilter>,
1218 log_components_only: bool,
1219) -> bool {
1220 if module_filters_sorted.is_empty() && component_level.is_empty() {
1221 return log_components_only;
1222 }
1223
1224 let module_filter = module_filters_sorted
1226 .iter()
1227 .find(|(path, _)| component.starts_with(path.as_str()))
1228 .map(|(_, level)| *level);
1229
1230 let component_filter = component_level.get(component).copied();
1231
1232 if log_components_only && module_filter.is_none() && component_filter.is_none() {
1233 return true;
1234 }
1235
1236 module_filter
1238 .or(component_filter)
1239 .is_some_and(|filter_level| line_level > filter_level)
1240}
1241
1242pub(crate) fn shutdown_graceful() {
1251 let mut lifecycle = LOGGER_LIFECYCLE.lock();
1252
1253 if *lifecycle == LoggerLifecycle::Terminated {
1254 return;
1255 }
1256
1257 LOGGING_BYPASSED.store(true, Ordering::SeqCst);
1259 log::set_max_level(log::LevelFilter::Off);
1260
1261 #[cfg(not(all(feature = "simulation", madsim)))]
1263 if let Some(tx) = LOGGER_TX.get() {
1264 let _ = tx.send(LogEvent::Close);
1265 }
1266
1267 if let Some(handle) = LOGGER_HANDLE.lock().take()
1268 && handle.thread().id() != std::thread::current().id()
1269 {
1270 let _ = handle.join();
1271 }
1272
1273 LOGGING_INITIALIZED.store(false, Ordering::SeqCst);
1274 *lifecycle = LoggerLifecycle::Terminated;
1275}
1276
1277pub(crate) fn is_running() -> bool {
1279 *LOGGER_LIFECYCLE.lock() == LoggerLifecycle::Running
1280}
1281
1282pub fn sync_to_disk() -> anyhow::Result<()> {
1290 #[cfg(all(feature = "simulation", madsim))]
1291 {
1292 Ok(())
1293 }
1294
1295 #[cfg(not(all(feature = "simulation", madsim)))]
1296 {
1297 let lifecycle = LOGGER_LIFECYCLE.lock();
1298
1299 if *lifecycle != LoggerLifecycle::Running {
1300 return Ok(());
1301 }
1302
1303 let Some(tx) = LOGGER_TX.get() else {
1304 anyhow::bail!("Logging is running without a published sender");
1305 };
1306
1307 sync_sender_to_disk(tx)
1308 }
1309}
1310
1311#[cfg(not(all(feature = "simulation", madsim)))]
1312fn sync_sender_to_disk(tx: &std::sync::mpsc::Sender<LogEvent>) -> anyhow::Result<()> {
1313 let (done_tx, done_rx) = std::sync::mpsc::channel();
1314 tx.send(LogEvent::Sync(done_tx))
1315 .map_err(|e| anyhow::anyhow!("failed to request logging sync: {e}"))?;
1316
1317 done_rx
1318 .recv()
1319 .map_err(|e| anyhow::anyhow!("failed to receive logging sync acknowledgement: {e}"))?
1320}
1321
1322pub fn log<T: AsRef<str>>(level: LogLevel, color: LogColor, component: Ustr, message: T) {
1324 let color = Value::from(color as u8);
1325
1326 match level {
1327 LogLevel::Off => {}
1328 LogLevel::Trace => {
1329 log::trace!(component = component.to_value(), color = color; "{}", message.as_ref());
1330 }
1331 LogLevel::Debug => {
1332 log::debug!(component = component.to_value(), color = color; "{}", message.as_ref());
1333 }
1334 LogLevel::Info => {
1335 log::info!(component = component.to_value(), color = color; "{}", message.as_ref());
1336 }
1337 LogLevel::Warning => {
1338 log::warn!(component = component.to_value(), color = color; "{}", message.as_ref());
1339 }
1340 LogLevel::Error => {
1341 log::error!(component = component.to_value(), color = color; "{}", message.as_ref());
1342 }
1343 }
1344}
1345
1346#[cfg_attr(feature = "python", pyo3::pyclass(module = "nautilus_trader.common"))]
1373#[cfg_attr(
1374 feature = "python",
1375 pyo3_stub_gen::derive::gen_stub_pyclass(module = "nautilus_trader.common")
1376)]
1377#[derive(Debug)]
1378pub struct LogGuard {
1379 #[cfg(not(all(feature = "simulation", madsim)))]
1380 tx: std::sync::mpsc::Sender<LogEvent>,
1381}
1382
1383impl LogGuard {
1384 #[must_use]
1389 pub fn new() -> Option<Self> {
1390 let lifecycle = LOGGER_LIFECYCLE.lock();
1391
1392 Self::new_from_lifecycle(&lifecycle)
1393 }
1394
1395 fn new_from_lifecycle(lifecycle: &LoggerLifecycle) -> Option<Self> {
1396 if *lifecycle != LoggerLifecycle::Running {
1397 return None;
1398 }
1399
1400 Self::new_locked()
1401 }
1402
1403 #[cfg(all(test, not(all(feature = "simulation", madsim))))]
1404 fn try_new_for_test() -> TestGuardAcquire {
1405 match LOGGER_LIFECYCLE.try_lock() {
1406 Some(lifecycle) => TestGuardAcquire::Acquired(Self::new_from_lifecycle(&lifecycle)),
1407 None => TestGuardAcquire::LifecycleBusy,
1408 }
1409 }
1410
1411 fn new_locked() -> Option<Self> {
1412 #[cfg(not(all(feature = "simulation", madsim)))]
1413 let tx = LOGGER_TX.get()?;
1414 #[cfg(all(feature = "simulation", madsim))]
1415 LOGGER_TX.get()?;
1416 LOGGING_GUARDS_ACTIVE
1417 .try_update(Ordering::SeqCst, Ordering::SeqCst, |count| {
1418 if count == u8::MAX {
1419 None
1420 } else {
1421 Some(count + 1)
1422 }
1423 })
1424 .ok()?;
1425
1426 Some(Self {
1427 #[cfg(not(all(feature = "simulation", madsim)))]
1428 tx: tx.clone(),
1429 })
1430 }
1431}
1432
1433impl Drop for LogGuard {
1434 fn drop(&mut self) {
1439 let lifecycle = LOGGER_LIFECYCLE.lock();
1440 let previous_count = LOGGING_GUARDS_ACTIVE
1441 .try_update(Ordering::SeqCst, Ordering::SeqCst, |count| {
1442 assert!(count != 0, "LogGuard reference count underflow");
1443 Some(count - 1)
1444 })
1445 .expect("Failed to decrement LogGuard count");
1446
1447 if *lifecycle != LoggerLifecycle::Running {
1448 return;
1449 }
1450
1451 #[cfg(all(feature = "simulation", madsim))]
1452 let _ = previous_count;
1453
1454 #[cfg(not(all(feature = "simulation", madsim)))]
1455 if previous_count == 1 {
1456 if let Err(e) = sync_sender_to_disk(&self.tx) {
1457 eprintln!("Error syncing logs after dropping the last LogGuard: {e}");
1458 }
1459 } else {
1460 let _ = self.tx.send(LogEvent::Flush);
1462 }
1463 }
1464}
1465
1466#[cfg(test)]
1467mod tests {
1468 use ahash::AHashMap;
1469 use log::LevelFilter;
1470 use nautilus_core::UUID4;
1471 use nautilus_model::identifiers::TraderId;
1472 use rstest::*;
1473 use serde_json::Value;
1474 use tempfile::tempdir;
1475 use ustr::Ustr;
1476
1477 use super::*;
1478 use crate::enums::LogColor;
1479
1480 #[rstest]
1481 fn log_message_serialization() {
1482 let log_message = LogLine {
1483 timestamp: UnixNanos::default(),
1484 level: log::Level::Info,
1485 color: LogColor::Normal,
1486 component: Ustr::from("Portfolio"),
1487 message: "This is a log message".to_string(),
1488 fields: SmallVec::new(),
1489 };
1490
1491 let serialized_json = serde_json::to_string(&log_message).unwrap();
1492 let deserialized_value: Value = serde_json::from_str(&serialized_json).unwrap();
1493
1494 assert_eq!(deserialized_value["level"], "INFO");
1495 assert_eq!(deserialized_value["component"], "Portfolio");
1496 assert_eq!(deserialized_value["message"], "This is a log message");
1497 }
1498
1499 #[rstest]
1500 fn log_config_parsing() {
1501 let config =
1502 LoggerConfig::from_spec("stdout=Info;is_colored;fileout=Debug;RiskEngine=Error")
1503 .unwrap();
1504 assert_eq!(
1505 config,
1506 LoggerConfig {
1507 stdout_level: LevelFilter::Info,
1508 fileout_level: LevelFilter::Debug,
1509 component_level: AHashMap::from_iter(vec![(
1510 Ustr::from("RiskEngine"),
1511 LevelFilter::Error
1512 )]),
1513 module_level: AHashMap::new(),
1514 log_components_only: false,
1515 is_colored: true,
1516 print_config: false,
1517 use_tracing: false,
1518 ..Default::default()
1519 }
1520 );
1521 }
1522
1523 #[rstest]
1524 fn log_config_parsing2() {
1525 let config = LoggerConfig::from_spec("stdout=Warn;print_config;fileout=Error;").unwrap();
1526 assert_eq!(
1527 config,
1528 LoggerConfig {
1529 stdout_level: LevelFilter::Warn,
1530 fileout_level: LevelFilter::Error,
1531 component_level: AHashMap::new(),
1532 module_level: AHashMap::new(),
1533 log_components_only: false,
1534 is_colored: true,
1535 print_config: true,
1536 use_tracing: false,
1537 ..Default::default()
1538 }
1539 );
1540 }
1541
1542 #[rstest]
1543 fn log_config_parsing_with_log_components_only() {
1544 let config =
1545 LoggerConfig::from_spec("stdout=Info;log_components_only;RiskEngine=Debug").unwrap();
1546 assert_eq!(
1547 config,
1548 LoggerConfig {
1549 stdout_level: LevelFilter::Info,
1550 fileout_level: LevelFilter::Off,
1551 component_level: AHashMap::from_iter(vec![(
1552 Ustr::from("RiskEngine"),
1553 LevelFilter::Debug
1554 )]),
1555 module_level: AHashMap::new(),
1556 log_components_only: true,
1557 is_colored: true,
1558 print_config: false,
1559 use_tracing: false,
1560 ..Default::default()
1561 }
1562 );
1563 }
1564
1565 #[rstest]
1566 fn test_log_line_wrapper_plain_string() {
1567 let line = LogLine {
1568 timestamp: 1_650_000_000_000_000_000.into(),
1569 level: log::Level::Info,
1570 color: LogColor::Normal,
1571 component: Ustr::from("TestComponent"),
1572 message: "Test message".to_string(),
1573 fields: SmallVec::new(),
1574 };
1575
1576 let mut wrapper = LogLineWrapper::new(line, Ustr::from("TRADER-001"));
1577 let result = wrapper.get_string();
1578
1579 assert!(result.contains("TRADER-001"));
1580 assert!(result.contains("TestComponent"));
1581 assert!(result.contains("Test message"));
1582 assert!(result.contains("[INFO]"));
1583 assert!(result.ends_with('\n'));
1584 assert!(!result.contains("\x1b["));
1586 }
1587
1588 #[rstest]
1589 fn test_log_line_wrapper_colored_string() {
1590 let line = LogLine {
1591 timestamp: 1_650_000_000_000_000_000.into(),
1592 level: log::Level::Info,
1593 color: LogColor::Green,
1594 component: Ustr::from("TestComponent"),
1595 message: "Test message".to_string(),
1596 fields: SmallVec::new(),
1597 };
1598
1599 let mut wrapper = LogLineWrapper::new(line, Ustr::from("TRADER-001"));
1600 let result = wrapper.get_colored();
1601
1602 assert!(result.contains("TRADER-001"));
1603 assert!(result.contains("TestComponent"));
1604 assert!(result.contains("Test message"));
1605 assert!(result.contains("\x1b["));
1607 assert!(result.ends_with('\n'));
1608 }
1609
1610 #[rstest]
1611 fn test_log_line_wrapper_json_output() {
1612 let line = LogLine {
1613 timestamp: 1_650_000_000_000_000_000.into(),
1614 level: log::Level::Warn,
1615 color: LogColor::Yellow,
1616 component: Ustr::from("RiskEngine"),
1617 message: "Warning message".to_string(),
1618 fields: SmallVec::new(),
1619 };
1620
1621 let wrapper = LogLineWrapper::new(line, Ustr::from("TRADER-002"));
1622 let json = wrapper.get_json();
1623
1624 let parsed: Value = serde_json::from_str(json.trim()).unwrap();
1625 assert_eq!(parsed["trader_id"], "TRADER-002");
1626 assert_eq!(parsed["component"], "RiskEngine");
1627 assert_eq!(parsed["message"], "Warning message");
1628 assert_eq!(parsed["level"], "WARN");
1629 assert_eq!(parsed["color"], "YELLOW");
1630 }
1631
1632 #[rstest]
1633 fn test_log_line_wrapper_caches_string() {
1634 let line = LogLine {
1635 timestamp: 1_650_000_000_000_000_000.into(),
1636 level: log::Level::Info,
1637 color: LogColor::Normal,
1638 component: Ustr::from("Test"),
1639 message: "Cached".to_string(),
1640 fields: SmallVec::new(),
1641 };
1642
1643 let mut wrapper = LogLineWrapper::new(line, Ustr::from("TRADER"));
1644 let first = wrapper.get_string().to_string();
1645 let second = wrapper.get_string().to_string();
1646
1647 assert_eq!(first, second);
1648 }
1649
1650 #[rstest]
1651 fn test_log_line_display() {
1652 let line = LogLine {
1653 timestamp: 0.into(),
1654 level: log::Level::Error,
1655 color: LogColor::Red,
1656 component: Ustr::from("Component"),
1657 message: "Error occurred".to_string(),
1658 fields: SmallVec::new(),
1659 };
1660
1661 let display = format!("{line}");
1662 assert_eq!(display, "[ERROR] Component: Error occurred");
1663 }
1664
1665 #[rstest]
1666 fn test_log_line_display_with_fields() {
1667 let line = LogLine {
1668 timestamp: 0.into(),
1669 level: log::Level::Info,
1670 color: LogColor::Normal,
1671 component: Ustr::from("RiskEngine"),
1672 message: "Order filled".to_string(),
1673 fields: smallvec::smallvec![
1674 (Ustr::from("venue"), "BINANCE".to_string()),
1675 (Ustr::from("order_id"), "O-001".to_string()),
1676 ],
1677 };
1678
1679 let display = format!("{line}");
1680 assert_eq!(
1681 display,
1682 "[INFO] RiskEngine: Order filled venue=BINANCE order_id=O-001"
1683 );
1684 }
1685
1686 #[rstest]
1687 fn test_log_line_wrapper_plain_string_with_fields() {
1688 let line = LogLine {
1689 timestamp: 1_650_000_000_000_000_000.into(),
1690 level: log::Level::Info,
1691 color: LogColor::Normal,
1692 component: Ustr::from("DataEngine"),
1693 message: "Connected".to_string(),
1694 fields: smallvec::smallvec![
1695 (Ustr::from("venue"), "BINANCE".to_string()),
1696 (Ustr::from("product_type"), "SPOT".to_string()),
1697 ],
1698 };
1699
1700 let mut wrapper = LogLineWrapper::new(line, Ustr::from("TRADER-001"));
1701 let result = wrapper.get_string();
1702
1703 assert!(result.contains("Connected"));
1704 assert!(result.contains("venue=BINANCE"));
1705 assert!(result.contains("product_type=SPOT"));
1706 assert!(result.ends_with('\n'));
1707 assert!(!result.contains("\x1b["));
1708 }
1709
1710 #[rstest]
1711 fn test_log_line_wrapper_json_with_fields() {
1712 let line = LogLine {
1713 timestamp: 1_650_000_000_000_000_000.into(),
1714 level: log::Level::Info,
1715 color: LogColor::Normal,
1716 component: Ustr::from("RiskEngine"),
1717 message: "Order filled".to_string(),
1718 fields: smallvec::smallvec![
1719 (Ustr::from("strategy_id"), "S-001".to_string()),
1720 (Ustr::from("venue"), "BINANCE".to_string()),
1721 ],
1722 };
1723
1724 let wrapper = LogLineWrapper::new(line, Ustr::from("TRADER-001"));
1725 let json = wrapper.get_json();
1726
1727 let parsed: Value = serde_json::from_str(json.trim()).unwrap();
1728 assert_eq!(parsed["component"], "RiskEngine");
1729 assert_eq!(parsed["message"], "Order filled");
1730 assert_eq!(parsed["strategy_id"], "S-001");
1731 assert_eq!(parsed["venue"], "BINANCE");
1732 }
1733
1734 #[rstest]
1735 fn test_log_line_wrapper_json_no_fields_has_no_extra_keys() {
1736 let line = LogLine {
1737 timestamp: 1_650_000_000_000_000_000.into(),
1738 level: log::Level::Info,
1739 color: LogColor::Normal,
1740 component: Ustr::from("Test"),
1741 message: "Simple".to_string(),
1742 fields: SmallVec::new(),
1743 };
1744
1745 let wrapper = LogLineWrapper::new(line, Ustr::from("TRADER-001"));
1746 let json = wrapper.get_json();
1747
1748 let parsed: Value = serde_json::from_str(json.trim()).unwrap();
1749 let obj = parsed.as_object().unwrap();
1750 assert_eq!(obj.len(), 6); }
1752
1753 #[rstest]
1754 fn test_log_line_wrapper_json_reserved_keys_not_overwritten() {
1755 let line = LogLine {
1756 timestamp: 1_650_000_000_000_000_000.into(),
1757 level: log::Level::Warn,
1758 color: LogColor::Normal,
1759 component: Ustr::from("Test"),
1760 message: "Real message".to_string(),
1761 fields: smallvec::smallvec![
1762 (Ustr::from("level"), "FAKE".to_string()),
1763 (Ustr::from("message"), "injected".to_string()),
1764 (Ustr::from("timestamp"), "bogus".to_string()),
1765 (Ustr::from("venue"), "BINANCE".to_string()),
1766 ],
1767 };
1768
1769 let wrapper = LogLineWrapper::new(line, Ustr::from("TRADER-001"));
1770 let json = wrapper.get_json();
1771 let parsed: Value = serde_json::from_str(json.trim()).unwrap();
1772
1773 assert_eq!(parsed["level"], "WARN");
1774 assert_eq!(parsed["message"], "Real message");
1775 assert_ne!(parsed["timestamp"], "bogus");
1776 assert_eq!(parsed["venue"], "BINANCE");
1777 }
1778
1779 #[rstest]
1780 fn test_log_line_wrapper_json_duplicate_extra_fields_last_value_wins() {
1781 let line = LogLine {
1782 timestamp: 1_650_000_000_000_000_000.into(),
1783 level: log::Level::Info,
1784 color: LogColor::Normal,
1785 component: Ustr::from("Test"),
1786 message: "Duplicate field".to_string(),
1787 fields: smallvec::smallvec![
1788 (Ustr::from("venue"), "BINANCE".to_string()),
1789 (Ustr::from("venue"), "OKX".to_string()),
1790 ],
1791 };
1792
1793 let wrapper = LogLineWrapper::new(line, Ustr::from("TRADER-001"));
1794 let json = wrapper.get_json();
1795 let parsed: Value = serde_json::from_str(json.trim()).unwrap();
1796
1797 assert_eq!(json.matches("\"venue\"").count(), 1);
1798 assert_eq!(parsed["venue"], "OKX");
1799 }
1800
1801 fn sorted_module_filters(map: AHashMap<Ustr, LevelFilter>) -> Vec<(Ustr, LevelFilter)> {
1803 let mut v: Vec<_> = map.into_iter().collect();
1804 v.sort_by_key(|b| std::cmp::Reverse(b.0.len()));
1805 v
1806 }
1807
1808 #[rstest]
1809 fn test_filter_no_filters_passes_all() {
1810 let module_filters = vec![];
1811 let component_level = AHashMap::new();
1812
1813 assert!(!should_filter_log(
1814 &Ustr::from("anything"),
1815 Level::Trace,
1816 &module_filters,
1817 &component_level,
1818 false
1819 ));
1820 }
1821
1822 #[rstest]
1823 fn test_filter_component_exact_match() {
1824 let module_filters = vec![];
1825 let component_level = AHashMap::from_iter([(Ustr::from("RiskEngine"), LevelFilter::Error)]);
1826
1827 assert!(should_filter_log(
1828 &Ustr::from("RiskEngine"),
1829 Level::Info,
1830 &module_filters,
1831 &component_level,
1832 false
1833 ));
1834 assert!(!should_filter_log(
1835 &Ustr::from("RiskEngine"),
1836 Level::Error,
1837 &module_filters,
1838 &component_level,
1839 false
1840 ));
1841 assert!(!should_filter_log(
1842 &Ustr::from("Portfolio"),
1843 Level::Info,
1844 &module_filters,
1845 &component_level,
1846 false
1847 ));
1848 }
1849
1850 #[rstest]
1851 fn test_filter_module_prefix_match() {
1852 let module_filters = vec![(Ustr::from("nautilus_okx::websocket"), LevelFilter::Debug)];
1853 let component_level = AHashMap::new();
1854
1855 assert!(!should_filter_log(
1856 &Ustr::from("nautilus_okx::websocket"),
1857 Level::Debug,
1858 &module_filters,
1859 &component_level,
1860 false
1861 ));
1862 assert!(!should_filter_log(
1863 &Ustr::from("nautilus_okx::websocket::handler"),
1864 Level::Debug,
1865 &module_filters,
1866 &component_level,
1867 false
1868 ));
1869 assert!(should_filter_log(
1870 &Ustr::from("nautilus_okx::websocket::handler"),
1871 Level::Trace,
1872 &module_filters,
1873 &component_level,
1874 false
1875 ));
1876 assert!(!should_filter_log(
1877 &Ustr::from("nautilus_binance::data"),
1878 Level::Trace,
1879 &module_filters,
1880 &component_level,
1881 false
1882 ));
1883 }
1884
1885 #[rstest]
1886 fn test_filter_longest_prefix_wins() {
1887 let module_filters = sorted_module_filters(AHashMap::from_iter([
1888 (Ustr::from("nautilus_okx"), LevelFilter::Error),
1889 (Ustr::from("nautilus_okx::websocket"), LevelFilter::Debug),
1890 ]));
1891 let component_level = AHashMap::new();
1892
1893 assert!(!should_filter_log(
1894 &Ustr::from("nautilus_okx::websocket::handler"),
1895 Level::Debug,
1896 &module_filters,
1897 &component_level,
1898 false
1899 ));
1900 assert!(should_filter_log(
1901 &Ustr::from("nautilus_okx::data"),
1902 Level::Debug,
1903 &module_filters,
1904 &component_level,
1905 false
1906 ));
1907 assert!(!should_filter_log(
1908 &Ustr::from("nautilus_okx::data"),
1909 Level::Error,
1910 &module_filters,
1911 &component_level,
1912 false
1913 ));
1914 }
1915
1916 #[rstest]
1917 fn test_filter_module_precedence_over_component() {
1918 let module_filters = vec![(Ustr::from("nautilus_okx::websocket"), LevelFilter::Debug)];
1919 let component_level =
1920 AHashMap::from_iter([(Ustr::from("nautilus_okx::websocket"), LevelFilter::Error)]);
1921
1922 assert!(!should_filter_log(
1923 &Ustr::from("nautilus_okx::websocket"),
1924 Level::Debug,
1925 &module_filters,
1926 &component_level,
1927 false
1928 ));
1929 }
1930
1931 #[rstest]
1932 fn test_filter_log_components_only_blocks_unknown() {
1933 let module_filters = vec![];
1934 let component_level = AHashMap::from_iter([(Ustr::from("RiskEngine"), LevelFilter::Debug)]);
1935
1936 assert!(should_filter_log(
1937 &Ustr::from("Portfolio"),
1938 Level::Info,
1939 &module_filters,
1940 &component_level,
1941 true
1942 ));
1943 assert!(!should_filter_log(
1944 &Ustr::from("RiskEngine"),
1945 Level::Info,
1946 &module_filters,
1947 &component_level,
1948 true
1949 ));
1950 }
1951
1952 #[rstest]
1953 fn test_filter_log_components_only_with_module() {
1954 let module_filters = vec![(Ustr::from("nautilus_okx"), LevelFilter::Debug)];
1955 let component_level = AHashMap::new();
1956
1957 assert!(!should_filter_log(
1958 &Ustr::from("nautilus_okx::websocket"),
1959 Level::Debug,
1960 &module_filters,
1961 &component_level,
1962 true
1963 ));
1964 assert!(should_filter_log(
1965 &Ustr::from("nautilus_binance::data"),
1966 Level::Debug,
1967 &module_filters,
1968 &component_level,
1969 true
1970 ));
1971 }
1972
1973 #[rstest]
1974 fn test_filter_level_comparison() {
1975 let module_filters = vec![];
1976 let component_level = AHashMap::from_iter([(Ustr::from("Test"), LevelFilter::Warn)]);
1977
1978 assert!(!should_filter_log(
1979 &Ustr::from("Test"),
1980 Level::Error,
1981 &module_filters,
1982 &component_level,
1983 false
1984 ));
1985 assert!(!should_filter_log(
1986 &Ustr::from("Test"),
1987 Level::Warn,
1988 &module_filters,
1989 &component_level,
1990 false
1991 ));
1992 assert!(should_filter_log(
1993 &Ustr::from("Test"),
1994 Level::Info,
1995 &module_filters,
1996 &component_level,
1997 false
1998 ));
1999 assert!(should_filter_log(
2000 &Ustr::from("Test"),
2001 Level::Debug,
2002 &module_filters,
2003 &component_level,
2004 false
2005 ));
2006 assert!(should_filter_log(
2007 &Ustr::from("Test"),
2008 Level::Trace,
2009 &module_filters,
2010 &component_level,
2011 false
2012 ));
2013 }
2014
2015 #[cfg(not(all(feature = "simulation", madsim)))]
2023 mod serial_tests {
2024 use std::{sync::atomic::Ordering, time::Duration};
2025
2026 use super::*;
2027 use crate::{
2028 logging::{
2029 LOGGING_BYPASSED, logging_clock_set_static_mode, logging_clock_set_static_time,
2030 logging_is_initialized, logging_set_bypass, logging_sync_to_disk,
2031 },
2032 testing::wait_until,
2033 };
2034
2035 #[rstest]
2036 fn test_shutdown_on_error_records_once_then_rearms() {
2037 disarm_shutdown_on_error();
2038
2039 let (tx, _rx) = std::sync::mpsc::channel();
2040 let logger = Logger::new_for_benchmark(LoggerConfig::default(), tx);
2041
2042 arm_shutdown_on_error(false);
2043 let args = format_args!("Disabled error");
2044 let record = log::Record::builder()
2045 .args(args)
2046 .level(Level::Error)
2047 .target("RunComponent")
2048 .build();
2049 log::Log::log(&logger, &record);
2050 assert_eq!(take_shutdown_on_error_trigger(), None);
2051
2052 arm_shutdown_on_error(true);
2053 let args = format_args!("First error");
2054 let record = log::Record::builder()
2055 .args(args)
2056 .level(Level::Error)
2057 .target("RunComponent")
2058 .build();
2059 log::Log::log(&logger, &record);
2060
2061 let args = format_args!("Second error");
2062 let record = log::Record::builder()
2063 .args(args)
2064 .level(Level::Error)
2065 .target("RunComponent")
2066 .build();
2067 log::Log::log(&logger, &record);
2068
2069 let first = take_shutdown_on_error_trigger().unwrap();
2070 assert_eq!(first.component, Ustr::from("RunComponent"));
2071 assert_eq!(first.message, "First error");
2072 assert_eq!(take_shutdown_on_error_trigger(), None);
2073
2074 arm_shutdown_on_error(true);
2075 let args = format_args!("Third error");
2076 let record = log::Record::builder()
2077 .args(args)
2078 .level(Level::Error)
2079 .target("RunComponent")
2080 .build();
2081 log::Log::log(&logger, &record);
2082
2083 let third = take_shutdown_on_error_trigger().unwrap();
2084 assert_eq!(third.component, Ustr::from("RunComponent"));
2085 assert_eq!(third.message, "Third error");
2086
2087 let (tx, rx) = std::sync::mpsc::channel();
2088 let logger = Logger::new_for_benchmark(
2089 LoggerConfig {
2090 log_components_only: true,
2091 ..Default::default()
2092 },
2093 tx,
2094 );
2095
2096 arm_shutdown_on_error(true);
2097 let args = format_args!("Filtered error");
2098 let record = log::Record::builder()
2099 .args(args)
2100 .level(Level::Error)
2101 .target("FilteredComponent")
2102 .build();
2103 log::Log::log(&logger, &record);
2104
2105 let trigger = take_shutdown_on_error_trigger().unwrap();
2106 assert_eq!(trigger.component, Ustr::from("FilteredComponent"));
2107 assert_eq!(trigger.message, "Filtered error");
2108 assert!(matches!(
2109 rx.try_recv(),
2110 Err(std::sync::mpsc::TryRecvError::Empty)
2111 ));
2112 disarm_shutdown_on_error();
2113 }
2114
2115 #[rstest]
2116 fn test_shutdown_on_error_records_bypassed_error() {
2117 LOGGING_BYPASSED.store(false, Ordering::Relaxed);
2118 disarm_shutdown_on_error();
2119
2120 let (tx, rx) = std::sync::mpsc::channel();
2121 let logger = Logger::new_for_benchmark(LoggerConfig::default(), tx);
2122 let metadata = log::Metadata::builder()
2123 .level(Level::Error)
2124 .target("BypassedComponent")
2125 .build();
2126
2127 logging_set_bypass();
2128 arm_shutdown_on_error(false);
2129 assert!(!log::Log::enabled(&logger, &metadata));
2130
2131 arm_shutdown_on_error(true);
2132 assert!(log::Log::enabled(&logger, &metadata));
2133
2134 let args = format_args!("Bypassed error");
2135 let record = log::Record::builder()
2136 .args(args)
2137 .level(Level::Error)
2138 .target("BypassedComponent")
2139 .build();
2140 log::Log::log(&logger, &record);
2141
2142 let trigger = take_shutdown_on_error_trigger().unwrap();
2143 assert_eq!(trigger.component, Ustr::from("BypassedComponent"));
2144 assert_eq!(trigger.message, "Bypassed error");
2145 assert!(matches!(
2146 rx.try_recv(),
2147 Err(std::sync::mpsc::TryRecvError::Empty)
2148 ));
2149
2150 LOGGING_BYPASSED.store(false, Ordering::Relaxed);
2151 disarm_shutdown_on_error();
2152 }
2153
2154 #[rstest]
2155 fn test_shutdown_on_error_failed_drain_keeps_trigger_pending() {
2156 LOGGING_BYPASSED.store(false, Ordering::Relaxed);
2157 disarm_shutdown_on_error();
2158
2159 let (tx, _rx) = std::sync::mpsc::channel();
2160 let logger = Logger::new_for_benchmark(LoggerConfig::default(), tx);
2161
2162 arm_shutdown_on_error(true);
2163 let args = format_args!("Pending error");
2164 let record = log::Record::builder()
2165 .args(args)
2166 .level(Level::Error)
2167 .target("PendingComponent")
2168 .build();
2169 log::Log::log(&logger, &record);
2170
2171 let drained = try_drain_shutdown_on_error_trigger(|trigger| {
2172 assert_eq!(trigger.component, Ustr::from("PendingComponent"));
2173 assert_eq!(trigger.message, "Pending error");
2174 false
2175 });
2176 assert!(!drained);
2177
2178 let trigger = take_shutdown_on_error_trigger().unwrap();
2179 assert_eq!(trigger.component, Ustr::from("PendingComponent"));
2180 assert_eq!(trigger.message, "Pending error");
2181 disarm_shutdown_on_error();
2182 }
2183
2184 #[rstest]
2185 fn test_logging_to_file() {
2186 let config = LoggerConfig {
2187 fileout_level: LevelFilter::Debug,
2188 ..Default::default()
2189 };
2190
2191 let temp_dir = tempdir().expect("Failed to create temporary directory");
2192 let file_config = FileWriterConfig {
2193 directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2194 ..Default::default()
2195 };
2196
2197 let log_guard = Logger::init_with_config(
2198 TraderId::from("TRADER-001"),
2199 UUID4::new(),
2200 config,
2201 file_config,
2202 );
2203
2204 logging_clock_set_static_mode();
2205 logging_clock_set_static_time(1_650_000_000_000_000);
2206
2207 log::info!(
2208 component = "RiskEngine";
2209 "This is a test"
2210 );
2211
2212 let mut log_contents = String::new();
2213
2214 wait_until(
2215 || {
2216 std::fs::read_dir(&temp_dir)
2217 .expect("Failed to read directory")
2218 .filter_map(Result::ok)
2219 .any(|entry| entry.path().is_file())
2220 },
2221 Duration::from_secs(3),
2222 );
2223
2224 drop(log_guard); wait_until(
2227 || {
2228 let log_file_path = std::fs::read_dir(&temp_dir)
2229 .expect("Failed to read directory")
2230 .filter_map(Result::ok)
2231 .find(|entry| entry.path().is_file())
2232 .expect("No files found in directory")
2233 .path();
2234 log_contents = std::fs::read_to_string(log_file_path)
2235 .expect("Error while reading log file");
2236 !log_contents.is_empty()
2237 },
2238 Duration::from_secs(3),
2239 );
2240
2241 assert_eq!(
2242 log_contents,
2243 "1970-01-20T02:20:00.000000000Z [INFO] TRADER-001.RiskEngine: This is a test\n"
2244 );
2245 }
2246
2247 #[rstest]
2248 fn test_logging_sync_to_disk_flushes_fast_flush_policy() {
2249 let config = LoggerConfig {
2250 fileout_level: LevelFilter::Debug,
2251 fileout_sync_on_flush: false,
2252 ..Default::default()
2253 };
2254
2255 let temp_dir = tempdir().expect("Failed to create temporary directory");
2256 let file_config = FileWriterConfig {
2257 directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2258 ..Default::default()
2259 };
2260
2261 let log_guard = Logger::init_with_config(
2262 TraderId::from("TRADER-SYNC"),
2263 UUID4::new(),
2264 config,
2265 file_config,
2266 )
2267 .expect("Failed to initialize logger");
2268
2269 logging_clock_set_static_mode();
2270 logging_clock_set_static_time(1_650_000_000_000_000);
2271
2272 log::info!(
2273 component = "RiskEngine";
2274 "sync me"
2275 );
2276
2277 logging_sync_to_disk().expect("sync-to-disk should succeed");
2278
2279 let log_file_path = std::fs::read_dir(&temp_dir)
2280 .expect("Failed to read directory")
2281 .filter_map(Result::ok)
2282 .find(|entry| entry.path().is_file())
2283 .expect("No files found in directory")
2284 .path();
2285 let log_contents =
2286 std::fs::read_to_string(log_file_path).expect("Error while reading log file");
2287
2288 assert!(log_contents.contains("sync me"));
2289
2290 drop(log_guard);
2291 }
2292
2293 #[rstest]
2294 fn test_last_guard_drop_syncs_backlog_tail() {
2295 const N: usize = 1000;
2296
2297 let config = LoggerConfig {
2299 stdout_level: LevelFilter::Off,
2300 fileout_level: LevelFilter::Info,
2301 ..Default::default()
2302 };
2303
2304 let temp_dir = tempdir().expect("Failed to create temporary directory");
2305 let file_config = FileWriterConfig {
2306 directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2307 ..Default::default()
2308 };
2309
2310 let log_guard = Logger::init_with_config(
2311 TraderId::from("TRADER-TAIL"),
2312 UUID4::new(),
2313 config,
2314 file_config,
2315 )
2316 .expect("Failed to initialize logger");
2317
2318 logging_clock_set_static_mode();
2320 logging_clock_set_static_time(1_700_000_000_000_000);
2321
2322 for i in 0..N {
2324 log::info!(component = "TailDrain"; "BacklogTest {i}");
2325 }
2326
2327 drop(log_guard);
2329
2330 let mut count = 0usize;
2332 wait_until(
2333 || {
2334 if let Some(log_file) = std::fs::read_dir(&temp_dir)
2335 .expect("Failed to read directory")
2336 .filter_map(Result::ok)
2337 .find(|entry| entry.path().is_file())
2338 {
2339 let log_file_path = log_file.path();
2340 if let Ok(contents) = std::fs::read_to_string(log_file_path) {
2341 count = contents
2342 .lines()
2343 .filter(|l| l.contains("BacklogTest "))
2344 .count();
2345 count >= N
2346 } else {
2347 false
2348 }
2349 } else {
2350 false
2351 }
2352 },
2353 Duration::from_secs(5),
2354 );
2355
2356 assert_eq!(count, N, "Expected all pending messages to be written");
2357 }
2358
2359 #[rstest]
2360 fn test_log_component_level_filtering() {
2361 let config =
2362 LoggerConfig::from_spec("stdout=Info;fileout=Debug;RiskEngine=Error").unwrap();
2363
2364 let temp_dir = tempdir().expect("Failed to create temporary directory");
2365 let file_config = FileWriterConfig {
2366 directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2367 ..Default::default()
2368 };
2369
2370 let log_guard = Logger::init_with_config(
2371 TraderId::from("TRADER-001"),
2372 UUID4::new(),
2373 config,
2374 file_config,
2375 );
2376
2377 logging_clock_set_static_mode();
2378 logging_clock_set_static_time(1_650_000_000_000_000);
2379
2380 log::info!(
2381 component = "RiskEngine";
2382 "This is a test"
2383 );
2384
2385 drop(log_guard); wait_until(
2388 || {
2389 if let Some(log_file) = std::fs::read_dir(&temp_dir)
2390 .expect("Failed to read directory")
2391 .filter_map(Result::ok)
2392 .find(|entry| entry.path().is_file())
2393 {
2394 let log_file_path = log_file.path();
2395 let log_contents = std::fs::read_to_string(log_file_path)
2396 .expect("Error while reading log file");
2397 !log_contents.contains("RiskEngine")
2398 } else {
2399 false
2400 }
2401 },
2402 Duration::from_secs(3),
2403 );
2404
2405 assert!(
2406 std::fs::read_dir(&temp_dir)
2407 .expect("Failed to read directory")
2408 .filter_map(Result::ok)
2409 .any(|entry| entry.path().is_file()),
2410 "Log file exists"
2411 );
2412 }
2413
2414 #[rstest]
2415 fn test_logging_to_file_in_json_format() {
2416 let config =
2417 LoggerConfig::from_spec("stdout=Info;is_colored;fileout=Debug;RiskEngine=Info")
2418 .unwrap();
2419
2420 let temp_dir = tempdir().expect("Failed to create temporary directory");
2421 let file_config = FileWriterConfig {
2422 directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2423 file_format: Some("json".to_string()),
2424 ..Default::default()
2425 };
2426
2427 let log_guard = Logger::init_with_config(
2428 TraderId::from("TRADER-001"),
2429 UUID4::new(),
2430 config,
2431 file_config,
2432 );
2433
2434 logging_clock_set_static_mode();
2435 logging_clock_set_static_time(1_650_000_000_000_000);
2436
2437 log::info!(
2438 component = "RiskEngine";
2439 "This is a test"
2440 );
2441
2442 let mut log_contents = String::new();
2443
2444 drop(log_guard); wait_until(
2447 || {
2448 if let Some(log_file) = std::fs::read_dir(&temp_dir)
2449 .expect("Failed to read directory")
2450 .filter_map(Result::ok)
2451 .find(|entry| entry.path().is_file())
2452 {
2453 let log_file_path = log_file.path();
2454 log_contents = std::fs::read_to_string(log_file_path)
2455 .expect("Error while reading log file");
2456 !log_contents.is_empty()
2457 } else {
2458 false
2459 }
2460 },
2461 Duration::from_secs(3),
2462 );
2463
2464 assert_eq!(
2465 log_contents,
2466 "{\"timestamp\":\"1970-01-20T02:20:00.000000000Z\",\"trader_id\":\"TRADER-001\",\"level\":\"INFO\",\"color\":\"NORMAL\",\"component\":\"RiskEngine\",\"message\":\"This is a test\"}\n"
2467 );
2468 }
2469
2470 #[rstest]
2471 fn test_init_sets_logging_is_initialized_flag() {
2472 let config = LoggerConfig::default();
2473 let file_config = FileWriterConfig::default();
2474
2475 let guard = Logger::init_with_config(
2476 TraderId::from("TRADER-001"),
2477 UUID4::new(),
2478 config,
2479 file_config,
2480 );
2481 assert!(guard.is_ok());
2482 assert!(logging_is_initialized());
2483
2484 drop(guard);
2485 assert!(logging_is_initialized());
2486 }
2487
2488 #[rstest]
2489 fn test_init_returns_error_when_log_guard_limit_reached() {
2490 let guard = Logger::init_with_config(
2491 TraderId::from("TRADER-001"),
2492 UUID4::new(),
2493 LoggerConfig::default(),
2494 FileWriterConfig::default(),
2495 )
2496 .expect("Failed to initialize logger");
2497
2498 LOGGING_GUARDS_ACTIVE.store(u8::MAX, Ordering::SeqCst);
2499 let result = Logger::init_with_config(
2500 TraderId::from("TRADER-001"),
2501 UUID4::new(),
2502 LoggerConfig::default(),
2503 FileWriterConfig::default(),
2504 );
2505 LOGGING_GUARDS_ACTIVE.store(1, Ordering::SeqCst);
2506 drop(guard);
2507
2508 assert_eq!(
2509 result.unwrap_err().to_string(),
2510 "Logging already initialized but new guard could not be created"
2511 );
2512 }
2513
2514 #[rstest]
2515 fn test_reinit_after_guard_drop_returns_live_guard() {
2516 let config = LoggerConfig::default();
2517 let file_config = FileWriterConfig::default();
2518
2519 let guard1 = Logger::init_with_config(
2520 TraderId::from("TRADER-001"),
2521 UUID4::new(),
2522 config.clone(),
2523 file_config.clone(),
2524 );
2525 assert!(guard1.is_ok());
2526 drop(guard1);
2527
2528 let guard2 = Logger::init_with_config(
2529 TraderId::from("TRADER-002"),
2530 UUID4::new(),
2531 config,
2532 file_config,
2533 );
2534 assert!(guard2.is_ok());
2535 }
2536
2537 #[rstest]
2538 fn test_bypass_before_init_prevents_logging() {
2539 logging_set_bypass();
2540 assert!(LOGGING_BYPASSED.load(Ordering::Relaxed));
2541
2542 let temp_dir = tempdir().expect("Failed to create temporary directory");
2543 let config = LoggerConfig {
2544 fileout_level: LevelFilter::Debug,
2545 ..Default::default()
2546 };
2547 let file_config = FileWriterConfig {
2548 directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2549 ..Default::default()
2550 };
2551
2552 let guard = Logger::init_with_config(
2553 TraderId::from("TRADER-001"),
2554 UUID4::new(),
2555 config,
2556 file_config,
2557 );
2558 assert!(guard.is_ok());
2559
2560 log::info!(
2561 component = "TestComponent";
2562 "This should be bypassed"
2563 );
2564 std::thread::sleep(Duration::from_millis(100));
2565 drop(guard);
2566
2567 assert!(LOGGING_BYPASSED.load(Ordering::Relaxed));
2569 }
2570
2571 #[rstest]
2572 fn test_module_level_filtering() {
2573 let config = LoggerConfig::from_spec(
2577 "stdout=Off;fileout=Trace;nautilus::adapters=Warn;nautilus::adapters::okx=Debug",
2578 )
2579 .unwrap();
2580
2581 let temp_dir = tempdir().expect("Failed to create temporary directory");
2582 let file_config = FileWriterConfig {
2583 directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2584 ..Default::default()
2585 };
2586
2587 let log_guard = Logger::init_with_config(
2588 TraderId::from("TRADER-MOD"),
2589 UUID4::new(),
2590 config,
2591 file_config,
2592 )
2593 .expect("Failed to initialize logger");
2594
2595 logging_clock_set_static_mode();
2596 logging_clock_set_static_time(1_650_000_000_000_000);
2597
2598 log::debug!(
2600 component = "nautilus::adapters::okx::websocket";
2601 "OKX debug message"
2602 );
2603
2604 log::info!(
2606 component = "nautilus::adapters::okx";
2607 "OKX info message"
2608 );
2609
2610 log::info!(
2612 component = "nautilus::adapters::binance";
2613 "Binance info message SHOULD NOT APPEAR"
2614 );
2615
2616 log::warn!(
2618 component = "nautilus::adapters::binance";
2619 "Binance warn message"
2620 );
2621
2622 log::trace!(
2624 component = "Portfolio";
2625 "Portfolio trace message"
2626 );
2627
2628 drop(log_guard);
2629
2630 wait_until(
2631 || {
2632 std::fs::read_dir(&temp_dir)
2633 .expect("Failed to read directory")
2634 .filter_map(Result::ok)
2635 .any(|entry| entry.path().is_file())
2636 },
2637 Duration::from_secs(3),
2638 );
2639
2640 let log_file_path = std::fs::read_dir(&temp_dir)
2641 .expect("Failed to read directory")
2642 .filter_map(Result::ok)
2643 .find(|entry| entry.path().is_file())
2644 .expect("No log file found")
2645 .path();
2646
2647 let log_contents =
2648 std::fs::read_to_string(log_file_path).expect("Error reading log file");
2649
2650 assert!(
2651 log_contents.contains("OKX debug message"),
2652 "OKX debug should pass (longer prefix wins)"
2653 );
2654 assert!(
2655 log_contents.contains("OKX info message"),
2656 "OKX info should pass"
2657 );
2658 assert!(
2659 log_contents.contains("Binance warn message"),
2660 "Binance warn should pass"
2661 );
2662 assert!(
2663 log_contents.contains("Portfolio trace message"),
2664 "Unfiltered component should pass"
2665 );
2666 assert!(
2667 !log_contents.contains("SHOULD NOT APPEAR"),
2668 "Binance info should be filtered (adapters=Warn)"
2669 );
2670 }
2671
2672 #[rstest]
2673 fn test_logging_to_file_with_kv_fields() {
2674 let config = LoggerConfig {
2675 fileout_level: LevelFilter::Debug,
2676 ..Default::default()
2677 };
2678
2679 let temp_dir = tempdir().expect("Failed to create temporary directory");
2680 let file_config = FileWriterConfig {
2681 directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2682 ..Default::default()
2683 };
2684
2685 let log_guard = Logger::init_with_config(
2686 TraderId::from("TRADER-001"),
2687 UUID4::new(),
2688 config,
2689 file_config,
2690 );
2691
2692 logging_clock_set_static_mode();
2693 logging_clock_set_static_time(1_650_000_000_000_000);
2694
2695 log::info!(
2696 component = "DataEngine",
2697 venue = "BINANCE",
2698 product_type = "SPOT";
2699 "WebSocket connected"
2700 );
2701
2702 let mut log_contents = String::new();
2703
2704 drop(log_guard);
2705
2706 wait_until(
2707 || {
2708 if let Some(log_file) = std::fs::read_dir(&temp_dir)
2709 .expect("Failed to read directory")
2710 .filter_map(Result::ok)
2711 .find(|entry| entry.path().is_file())
2712 {
2713 log_contents = std::fs::read_to_string(log_file.path())
2714 .expect("Error while reading log file");
2715 !log_contents.is_empty()
2716 } else {
2717 false
2718 }
2719 },
2720 Duration::from_secs(3),
2721 );
2722
2723 assert!(
2724 log_contents.contains("WebSocket connected"),
2725 "Message should be present"
2726 );
2727 assert!(
2728 log_contents.contains("venue=BINANCE"),
2729 "venue field should appear in output, was:\n{log_contents}"
2730 );
2731 assert!(
2732 log_contents.contains("product_type=SPOT"),
2733 "product_type field should appear in output, was:\n{log_contents}"
2734 );
2735 }
2736
2737 #[rstest]
2738 fn test_logging_to_file_json_with_kv_fields() {
2739 let config =
2740 LoggerConfig::from_spec("stdout=Off;fileout=Debug;DataEngine=Debug").unwrap();
2741
2742 let temp_dir = tempdir().expect("Failed to create temporary directory");
2743 let file_config = FileWriterConfig {
2744 directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2745 file_format: Some("json".to_string()),
2746 ..Default::default()
2747 };
2748
2749 let log_guard = Logger::init_with_config(
2750 TraderId::from("TRADER-001"),
2751 UUID4::new(),
2752 config,
2753 file_config,
2754 );
2755
2756 logging_clock_set_static_mode();
2757 logging_clock_set_static_time(1_650_000_000_000_000);
2758
2759 log::info!(
2760 component = "DataEngine",
2761 venue = "BINANCE",
2762 order_id = "O-12345";
2763 "Order filled"
2764 );
2765
2766 let mut log_contents = String::new();
2767
2768 drop(log_guard);
2769
2770 wait_until(
2771 || {
2772 if let Some(log_file) = std::fs::read_dir(&temp_dir)
2773 .expect("Failed to read directory")
2774 .filter_map(Result::ok)
2775 .find(|entry| entry.path().is_file())
2776 {
2777 log_contents = std::fs::read_to_string(log_file.path())
2778 .expect("Error while reading log file");
2779 !log_contents.is_empty()
2780 } else {
2781 false
2782 }
2783 },
2784 Duration::from_secs(3),
2785 );
2786
2787 let parsed: serde_json::Value =
2788 serde_json::from_str(log_contents.trim()).expect("Should be valid JSON");
2789 assert_eq!(parsed["component"], "DataEngine");
2790 assert_eq!(parsed["message"], "Order filled");
2791 assert_eq!(parsed["venue"], "BINANCE");
2792 assert_eq!(parsed["order_id"], "O-12345");
2793 }
2794 }
2795
2796 #[cfg(not(all(feature = "simulation", madsim)))]
2797 mod lifecycle_tests {
2798 use std::{
2799 process::Command,
2800 sync::{Arc, Barrier},
2801 };
2802
2803 use super::*;
2804 use crate::logging::{logging_is_initialized, logging_shutdown, logging_sync_to_disk};
2805
2806 const LIFECYCLE_CHILD_ENV: &str = "NAUTILUS_LOGGER_LIFECYCLE_CHILD";
2807
2808 fn in_lifecycle_child(marker: &str) -> bool {
2809 std::env::var(LIFECYCLE_CHILD_ENV).as_deref() == Ok(marker)
2810 }
2811
2812 fn run_lifecycle_child(test_name: &str, marker: &str) {
2813 let output = Command::new(std::env::current_exe().expect("test executable must exist"))
2814 .arg(test_name)
2815 .arg("--nocapture")
2816 .arg("--test-threads=1")
2817 .env(LIFECYCLE_CHILD_ENV, marker)
2818 .output()
2819 .expect("lifecycle child process must start");
2820
2821 assert!(
2822 output.status.success(),
2823 "lifecycle child failed with {}\nstdout:\n{}\nstderr:\n{}",
2824 output.status,
2825 String::from_utf8_lossy(&output.stdout),
2826 String::from_utf8_lossy(&output.stderr),
2827 );
2828 }
2829
2830 #[rstest]
2831 fn test_init_publish_boundary_serializes_guard_acquisition() {
2832 const MARKER: &str = "init-publish-boundary";
2833 if !in_lifecycle_child(MARKER) {
2834 run_lifecycle_child(
2835 "test_init_publish_boundary_serializes_guard_acquisition",
2836 MARKER,
2837 );
2838 return;
2839 }
2840
2841 let (publish_reached_tx, publish_reached_rx) = std::sync::mpsc::channel();
2842 let (publish_resume_tx, publish_resume_rx) = std::sync::mpsc::channel();
2843 *INIT_PUBLISH_HOOK.lock() = Some(InitPublishHook {
2844 reached: publish_reached_tx,
2845 resume: publish_resume_rx,
2846 });
2847
2848 let init_thread = std::thread::spawn(|| {
2849 Logger::init_with_config(
2850 TraderId::from("TRADER-BOUNDARY"),
2851 UUID4::new(),
2852 LoggerConfig {
2853 stdout_level: LevelFilter::Off,
2854 ..Default::default()
2855 },
2856 FileWriterConfig::default(),
2857 )
2858 });
2859 publish_reached_rx
2860 .recv()
2861 .expect("initializer must reach the install/publish boundary");
2862
2863 assert!(
2866 matches!(
2867 LogGuard::try_new_for_test(),
2868 TestGuardAcquire::LifecycleBusy
2869 ),
2870 "initializer must hold the lifecycle mutex before sender publication completes"
2871 );
2872
2873 publish_resume_tx
2874 .send(())
2875 .expect("initializer must resume publication");
2876 let init_guard = init_thread
2877 .join()
2878 .expect("initializer thread must not panic")
2879 .expect("initialization must succeed");
2880 let TestGuardAcquire::Acquired(Some(second_guard)) = LogGuard::try_new_for_test()
2881 else {
2882 panic!("publication must release the lifecycle mutex and expose a valid guard");
2883 };
2884 drop((init_guard, second_guard));
2885 logging_shutdown();
2886 }
2887
2888 #[rstest]
2889 fn test_concurrent_init_high_contention() {
2890 const MARKER: &str = "concurrent-init";
2891 const THREADS: usize = 64;
2892
2893 if !in_lifecycle_child(MARKER) {
2894 run_lifecycle_child("test_concurrent_init_high_contention", MARKER);
2895 return;
2896 }
2897
2898 let barrier = Arc::new(Barrier::new(THREADS));
2899 let mut threads = Vec::with_capacity(THREADS);
2900 for index in 0..THREADS {
2901 let barrier = Arc::clone(&barrier);
2902 threads.push(std::thread::spawn(move || {
2903 barrier.wait();
2904 Logger::init_with_config(
2905 TraderId::from(format!("TRADER-{index:02}")),
2906 UUID4::new(),
2907 LoggerConfig {
2908 stdout_level: LevelFilter::Off,
2909 ..Default::default()
2910 },
2911 FileWriterConfig::default(),
2912 )
2913 }));
2914 }
2915
2916 let guards = threads
2917 .into_iter()
2918 .map(|thread| {
2919 thread
2920 .join()
2921 .expect("initializer thread must not panic")
2922 .expect("every concurrent initialization must return a guard")
2923 })
2924 .collect::<Vec<_>>();
2925 logging_sync_to_disk().expect("logging sync must succeed after concurrent init");
2926 drop(guards);
2927 logging_shutdown();
2928 }
2929
2930 #[rstest]
2931 fn test_sequential_init_reuses_live_worker_and_original_file() {
2932 const MARKER: &str = "sequential-init";
2933 if !in_lifecycle_child(MARKER) {
2934 run_lifecycle_child(
2935 "test_sequential_init_reuses_live_worker_and_original_file",
2936 MARKER,
2937 );
2938 return;
2939 }
2940
2941 let temp_dir = tempdir().expect("temporary directory must be created");
2942 let config = LoggerConfig {
2943 stdout_level: LevelFilter::Off,
2944 fileout_level: LevelFilter::Info,
2945 ..Default::default()
2946 };
2947 let file_config = FileWriterConfig {
2948 directory: Some(temp_dir.path().to_str().unwrap().to_string()),
2949 ..Default::default()
2950 };
2951
2952 let first_guard = Logger::init_with_config(
2953 TraderId::from("TRADER-SEQUENTIAL"),
2954 UUID4::new(),
2955 config,
2956 file_config,
2957 )
2958 .expect("first initialization must succeed");
2959 log::info!(component = "LifecycleTest"; "lifecycle marker A");
2960 drop(first_guard);
2961
2962 assert!(logging_is_initialized());
2963 assert!(is_running());
2964
2965 let second_guard = Logger::init_with_config(
2966 TraderId::from("TRADER-IGNORED"),
2967 UUID4::new(),
2968 LoggerConfig::default(),
2969 FileWriterConfig::default(),
2970 )
2971 .expect("second initialization must return a live guard");
2972 log::info!(component = "LifecycleTest"; "lifecycle marker B");
2973 logging_sync_to_disk().expect("logging sync must succeed after re-acquisition");
2974
2975 let log_path = std::fs::read_dir(&temp_dir)
2976 .expect("log directory must be readable")
2977 .filter_map(Result::ok)
2978 .find(|entry| entry.path().is_file())
2979 .expect("original logger must create a log file")
2980 .path();
2981 let contents = std::fs::read_to_string(log_path).expect("log file must be readable");
2982 assert!(contents.contains("lifecycle marker A"));
2983 assert!(contents.contains("lifecycle marker B"));
2984
2985 drop(second_guard);
2986 logging_shutdown();
2987
2988 let error = Logger::init_with_config(
2989 TraderId::from("TRADER-TERMINATED"),
2990 UUID4::new(),
2991 LoggerConfig::default(),
2992 FileWriterConfig::default(),
2993 )
2994 .expect_err("initialization after terminal shutdown must fail");
2995 assert_eq!(
2996 error.to_string(),
2997 "Logging has been shut down and cannot be re-initialized"
2998 );
2999 }
3000 }
3001
3002 #[cfg(all(feature = "simulation", madsim))]
3003 mod sim_tests {
3004 use std::sync::atomic::Ordering;
3005
3006 use super::*;
3007 use crate::logging::LOGGING_BYPASSED;
3008
3009 #[rstest]
3010 fn test_init_under_madsim_skips_writer_thread_and_forces_bypass() {
3011 let config = LoggerConfig {
3012 bypass_logging: false,
3013 ..Default::default()
3014 };
3015 let temp_dir = tempdir().expect("Failed to create temporary directory");
3016 let file_config = FileWriterConfig {
3017 directory: Some(temp_dir.path().to_str().unwrap().to_string()),
3018 ..Default::default()
3019 };
3020
3021 let _guard = Logger::init_with_config(
3022 TraderId::from("TRADER-SIM"),
3023 UUID4::new(),
3024 config,
3025 file_config,
3026 )
3027 .expect("init should succeed under simulation");
3028
3029 assert!(LOGGING_INITIALIZED.load(Ordering::SeqCst));
3030 assert!(
3031 LOGGING_BYPASSED.load(Ordering::SeqCst),
3032 "bypass must be forced under cfg(madsim) even when config disables it"
3033 );
3034 assert!(
3035 LOGGER_HANDLE.lock().is_none(),
3036 "writer thread must not be spawned under cfg(madsim)"
3037 );
3038 }
3039 }
3040}