Logging and tracing implementation (#1431)

Co-authored-by: Chris Sellers <[email protected]>

examples/backtest/crypto_ema_cross_ethusdt_trade_ticks.py

@@ -30,6 +30,7 @@
 from nautilus_trader.model.data import BarType
 from nautilus_trader.model.enums import AccountType
 from nautilus_trader.model.enums import OmsType
+from nautilus_trader.model.identifiers import TraderId
 from nautilus_trader.model.identifiers import Venue
 from nautilus_trader.model.objects import Money
 from nautilus_trader.persistence.wranglers import TradeTickDataWrangler
@@ -40,7 +41,7 @@
 if __name__ == "__main__":
     # Configure backtest engine
     config = BacktestEngineConfig(
-        trader_id="BACKTESTER-001",
+        trader_id=TraderId("BACKTESTER-001"),
         logging=LoggingConfig(
             log_level="INFO",
             log_colors=True,

examples/live/binance/binance_futures_testnet_market_maker.py

@@ -47,7 +47,6 @@
         # log_file_format="json",
         log_colors=True,
     ),
-    # tracing=TracingConfig(stdout_level="DEBUG"),
     exec_engine=LiveExecEngineConfig(
         reconciliation=True,
         reconciliation_lookback_mins=1440,

examples/live/binance/binance_futures_testnet_orderbook_imbalance.py

@@ -45,7 +45,6 @@
         # log_level_file="DEBUG",
         # log_file_format="json",
     ),
-    # tracing=TracingConfig(stdout_level="DEBUG"),
     exec_engine=LiveExecEngineConfig(
         reconciliation=True,
         reconciliation_lookback_mins=1440,

examples/live/binance/binance_spot_market_maker.py

@@ -40,7 +40,11 @@
 # Configure the trading node
 config_node = TradingNodeConfig(
     trader_id=TraderId("TESTER-001"),
-    logging=LoggingConfig(log_level="INFO"),
+    logging=LoggingConfig(
+        log_level="INFO",
+        # log_level_file="DEBUG",
+        # log_colors=False,
+    ),
     exec_engine=LiveExecEngineConfig(
         reconciliation=True,
         reconciliation_lookback_mins=1440,

nautilus_core/common/Cargo.toml

@@ -23,8 +23,9 @@ serde_json = { workspace = true }
 strum = { workspace = true }
 ustr = { workspace = true }
 tracing = { workspace = true }
-tracing-appender = "0.2.3"
-tracing-subscriber = { version = "0.3.18", features = ["env-filter"] }
+# Disable default feature "tracing-log" since it interferes with custom logging
+tracing-subscriber = { version = "0.3.18", default-features = false, features = ["smallvec", "fmt", "ansi", "std", "env-filter"] }
+log = { version = "0.4.20", features = ["std", "kv_unstable", "serde", "release_max_level_debug"] }
 
 [dev-dependencies]
 tempfile = { workspace = true }

nautilus_core/common/src/clock.rs

@@ -17,7 +17,7 @@ use std::{collections::HashMap, ops::Deref};
 
 use nautilus_core::{
     correctness::check_valid_string,
-    time::{AtomicTime, ClockMode, UnixNanos},
+    time::{get_atomic_clock_realtime, AtomicTime, UnixNanos},
 };
 use ustr::Ustr;
 
@@ -67,10 +67,6 @@ pub trait Clock {
     fn cancel_timers(&mut self);
 }
 
-#[cfg_attr(
-    feature = "python",
-    pyo3::pyclass(module = "nautilus_trader.core.nautilus_pyo3.common")
-)]
 pub struct TestClock {
     time: AtomicTime,
     timers: HashMap<Ustr, TestTimer>,
@@ -82,17 +78,13 @@ impl TestClock {
     #[must_use]
     pub fn new() -> Self {
         Self {
-            time: AtomicTime::new(ClockMode::STATIC, 0),
+            time: AtomicTime::new(false, 0),
             timers: HashMap::new(),
             default_callback: None,
             callbacks: HashMap::new(),
         }
     }
 
-    pub fn get_time_clone(&self) -> AtomicTime {
-        self.time.clone()
-    }
-
     #[must_use]
     pub fn get_timers(&self) -> &HashMap<Ustr, TestTimer> {
         &self.timers
@@ -102,7 +94,7 @@ impl TestClock {
         // Time should increase monotonically
         assert!(
             to_time_ns >= self.time.get_time_ns(),
-            "`to_time_ns` was < `self._time_ns`"
+            "`to_time_ns` was < `self.time.get_time_ns()`"
         );
 
         if set_time {
@@ -247,12 +239,8 @@ impl Clock for TestClock {
     }
 }
 
-#[cfg_attr(
-    feature = "python",
-    pyo3::pyclass(module = "nautilus_trader.core.nautilus_pyo3.common")
-)]
 pub struct LiveClock {
-    internal: AtomicTime,
+    time: &'static AtomicTime,
     timers: HashMap<Ustr, TestTimer>,
     default_callback: Option<EventHandler>,
     callbacks: HashMap<Ustr, EventHandler>,
@@ -262,7 +250,7 @@ impl LiveClock {
     #[must_use]
     pub fn new() -> Self {
         Self {
-            internal: AtomicTime::new(ClockMode::LIVE, 0),
+            time: get_atomic_clock_realtime(),
             timers: HashMap::new(),
             default_callback: None,
             callbacks: HashMap::new(),
@@ -280,7 +268,7 @@ impl Deref for LiveClock {
     type Target = AtomicTime;
 
     fn deref(&self) -> &Self::Target {
-        &self.internal
+        self.time
     }
 }
 

nautilus_core/common/src/enums.rs

@@ -171,10 +171,6 @@ pub enum LogLevel {
     #[strum(serialize = "ERR", serialize = "ERROR")]
     #[serde(rename = "ERROR")]
     Error = 40,
-    /// The **CRT** critical log level.
-    #[strum(serialize = "CRT", serialize = "CRITICAL")]
-    #[serde(rename = "CRITICAL")]
-    Critical = 50,
 }
 
 // Override `strum` implementation
@@ -185,7 +181,6 @@ impl std::fmt::Display for LogLevel {
             Self::Info => "INF",
             Self::Warning => "WRN",
             Self::Error => "ERR",
-            Self::Critical => "CRT",
         };
         write!(f, "{display}")
     }
@@ -234,11 +229,25 @@ pub enum LogColor {
     /// The yellow log color, typically used with [`LogLevel::Warning`] log levels.
     #[strum(serialize = "\x1b[1;33m")]
     Yellow = 5,
-    /// The red log color, typically used with [`LogLevel::Error`] or [`LogLevel::Critical`] log levels.
+    /// The red log color, typically used with [`LogLevel::Error`] level.
     #[strum(serialize = "\x1b[1;31m")]
     Red = 6,
 }
 
+impl From<u8> for LogColor {
+    fn from(value: u8) -> Self {
+        match value {
+            1 => Self::Green,
+            2 => Self::Blue,
+            3 => Self::Magenta,
+            4 => Self::Cyan,
+            5 => Self::Yellow,
+            6 => Self::Red,
+            _ => Self::Normal,
+        }
+    }
+}
+
 /// An ANSI log line format specifier.
 /// This is used for formatting log messages with ANSI escape codes.
 #[repr(C)]

nautilus_core/common/src/factories.rs

@@ -34,39 +34,39 @@ use crate::generators::{
 
 #[repr(C)]
 pub struct OrderFactory {
+    clock: &'static AtomicTime,
     trader_id: TraderId,
     strategy_id: StrategyId,
     order_id_generator: ClientOrderIdGenerator,
     order_list_id_generator: OrderListIdGenerator,
-    clock: AtomicTime,
 }
 
 impl OrderFactory {
     pub fn new(
         trader_id: TraderId,
         strategy_id: StrategyId,
-        clock: AtomicTime,
         init_order_id_count: Option<usize>,
         init_order_list_id_count: Option<usize>,
+        clock: &'static AtomicTime,
     ) -> Self {
         let order_id_generator = ClientOrderIdGenerator::new(
             trader_id,
             strategy_id,
-            clock.clone(),
             init_order_id_count.unwrap_or(0),
+            clock,
         );
         let order_list_id_generator = OrderListIdGenerator::new(
             trader_id,
             strategy_id,
-            clock.clone(),
             init_order_list_id_count.unwrap_or(0),
+            clock,
         );
         Self {
+            clock,
             trader_id,
             strategy_id,
             order_id_generator,
             order_list_id_generator,
-            clock,
         }
     }
 
@@ -222,8 +222,8 @@ pub mod tests {
         assert_eq!(market_order.side, OrderSide::Buy);
         assert_eq!(market_order.quantity, 100.into());
         assert_eq!(market_order.time_in_force, TimeInForce::Gtc);
-        assert_eq!(market_order.is_reduce_only, false);
-        assert_eq!(market_order.is_quote_quantity, false);
+        assert!(!market_order.is_reduce_only);
+        assert!(!market_order.is_quote_quantity);
         assert_eq!(market_order.exec_algorithm_id, None);
         assert_eq!(market_order.exec_algorithm_params, None);
         assert_eq!(market_order.exec_spawn_id, None);