nautilus_common/python/

logging.rs

// -------------------------------------------------------------------------------------------------
//  Copyright (C) 2015-2026 Nautech Systems Pty Ltd. All rights reserved.
//  https://nautechsystems.io
//
//  Licensed under the GNU Lesser General Public License Version 3.0 (the "License");
//  You may not use this file except in compliance with the License.
//  You may obtain a copy of the License at https://www.gnu.org/licenses/lgpl-3.0.en.html
//
//  Unless required by applicable law or agreed to in writing, software
//  distributed under the License is distributed on an "AS IS" BASIS,
//  WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
//  See the License for the specific language governing permissions and
//  limitations under the License.
// -------------------------------------------------------------------------------------------------

use std::collections::HashMap;

use ahash::AHashMap;
use log::LevelFilter;
use nautilus_core::{UUID4, python::to_pyvalue_err};
use nautilus_model::identifiers::TraderId;
use pyo3::prelude::*;
use ustr::Ustr;

use crate::{
    enums::{LogColor, LogLevel},
    logging::{
        self, headers,
        logger::{self, LogGuard, LoggerConfig},
        logging_clock_set_realtime_mode, logging_clock_set_static_mode,
        logging_clock_set_static_time, logging_set_bypass, map_log_level_to_filter,
        parse_level_filter_str,
        writer::FileWriterConfig,
    },
    python::config_error_to_pyvalue_err,
};

#[pyo3_stub_gen::derive::gen_stub_pymethods]
#[pymethods]
impl LoggerConfig {
    /// Configuration for the Nautilus logger.
    #[new]
    #[pyo3(signature = (
        stdout_level=None,
        fileout_level=None,
        component_levels=None,
        is_colored=None,
        print_config=None,
        bypass_logging=None,
        log_components_only=None,
        file_config=None,
        clear_log_file=None,
        fileout_sync_on_flush=None,
        buffered_stdout=None,
    ))]
    #[expect(
        clippy::too_many_arguments,
        reason = "PyO3 constructor mirrors LoggerConfig keyword arguments"
    )]
    fn py_new(
        stdout_level: Option<LogLevel>,
        fileout_level: Option<LogLevel>,
        component_levels: Option<std::collections::HashMap<String, String>>,
        is_colored: Option<bool>,
        print_config: Option<bool>,
        bypass_logging: Option<bool>,
        log_components_only: Option<bool>,
        file_config: Option<FileWriterConfig>,
        clear_log_file: Option<bool>,
        fileout_sync_on_flush: Option<bool>,
        buffered_stdout: Option<bool>,
    ) -> PyResult<Self> {
        let component_levels = parse_component_levels(component_levels).map_err(to_pyvalue_err)?;
        let mut config = Self::new(
            stdout_level.map_or(LevelFilter::Info, map_log_level_to_filter),
            fileout_level.map_or(LevelFilter::Off, map_log_level_to_filter),
            component_levels,
            AHashMap::new(),
            log_components_only.unwrap_or(false),
            is_colored.unwrap_or(true),
            print_config.unwrap_or(false),
            false,
            bypass_logging.unwrap_or(false),
            file_config,
            clear_log_file.unwrap_or(false),
        );
        config.fileout_sync_on_flush = fileout_sync_on_flush.unwrap_or(true);
        config.buffered_stdout = buffered_stdout.unwrap_or(false);
        config.validate().map_err(config_error_to_pyvalue_err)?;
        Ok(config)
    }

    #[getter]
    #[pyo3(name = "stdout_level")]
    fn py_stdout_level(&self) -> LogLevel {
        level_filter_to_log_level(self.stdout_level)
    }

    #[getter]
    #[pyo3(name = "fileout_level")]
    fn py_fileout_level(&self) -> LogLevel {
        level_filter_to_log_level(self.fileout_level)
    }

    #[getter]
    #[pyo3(name = "component_levels")]
    fn py_component_levels(&self) -> HashMap<String, String> {
        self.component_level
            .iter()
            .map(|(component, level)| (component.to_string(), level.to_string()))
            .collect()
    }

    #[getter]
    #[pyo3(name = "is_colored")]
    const fn py_is_colored(&self) -> bool {
        self.is_colored
    }

    #[getter]
    #[pyo3(name = "print_config")]
    const fn py_print_config(&self) -> bool {
        self.print_config
    }

    #[getter]
    #[pyo3(name = "bypass_logging")]
    const fn py_bypass_logging(&self) -> bool {
        self.bypass_logging
    }

    #[getter]
    #[pyo3(name = "log_components_only")]
    const fn py_log_components_only(&self) -> bool {
        self.log_components_only
    }

    #[getter]
    #[pyo3(name = "file_config")]
    fn py_file_config(&self) -> Option<FileWriterConfig> {
        self.file_config.clone()
    }

    #[getter]
    #[pyo3(name = "clear_log_file")]
    const fn py_clear_log_file(&self) -> bool {
        self.clear_log_file
    }

    #[getter]
    #[pyo3(name = "fileout_sync_on_flush")]
    const fn py_fileout_sync_on_flush(&self) -> bool {
        self.fileout_sync_on_flush
    }

    #[getter]
    #[pyo3(name = "buffered_stdout")]
    const fn py_buffered_stdout(&self) -> bool {
        self.buffered_stdout
    }

    /// Parses a configuration from a spec string.
    ///
    /// # Format
    ///
    /// Semicolon-separated key-value pairs or bare flags:
    /// ```text
    /// stdout=Info;fileout=Debug;RiskEngine=Error;my_crate::module=Debug;is_colored
    /// ```
    ///
    /// # Errors
    ///
    /// Returns an error if the spec string contains invalid syntax or log levels.
    #[staticmethod]
    #[pyo3(name = "from_spec")]
    pub fn py_from_spec(spec: &str) -> PyResult<Self> {
        Self::from_spec(spec).map_err(to_pyvalue_err)
    }
}

#[pyo3_stub_gen::derive::gen_stub_pymethods]
#[pymethods]
impl FileWriterConfig {
    /// Configures file log output.
    #[new]
    #[pyo3(signature = (directory=None, file_name=None, file_format=None, file_rotate=None))]
    #[must_use]
    pub fn py_new(
        directory: Option<String>,
        file_name: Option<String>,
        file_format: Option<String>,
        file_rotate: Option<(u64, u32)>,
    ) -> Self {
        Self::new(directory, file_name, file_format, file_rotate)
    }

    #[getter]
    #[pyo3(name = "directory")]
    fn py_directory(&self) -> Option<&str> {
        self.directory.as_deref()
    }

    #[getter]
    #[pyo3(name = "file_name")]
    fn py_file_name(&self) -> Option<&str> {
        self.file_name.as_deref()
    }

    #[getter]
    #[pyo3(name = "file_format")]
    fn py_file_format(&self) -> Option<&str> {
        self.file_format.as_deref()
    }

    #[getter]
    #[pyo3(name = "file_rotate")]
    fn py_file_rotate(&self) -> Option<(u64, u32)> {
        self.file_rotate
            .as_ref()
            .map(|rotate| (rotate.max_file_size, rotate.max_backup_count))
    }
}

/// Initialize logging.
///
/// Logging should be used for Python and sync Rust logic which is most of
/// the components in the [nautilus_trader](https://pypi.org/project/nautilus_trader) package.
/// Logging can be configured to filter components and write up to a specific level only
/// by passing a configuration using the `NAUTILUS_LOG` environment variable.
///
/// Should only be called once during an applications run, ideally at the
/// beginning of the run.
///
/// # Errors
///
/// Returns an error if the logging subsystem fails to initialize.
#[pyfunction]
#[pyo3_stub_gen::derive::gen_stub_pyfunction(module = "nautilus_trader.common")]
#[pyo3(name = "init_logging")]
#[expect(clippy::too_many_arguments)]
#[pyo3(signature = (trader_id, instance_id, level_stdout, level_file=None, component_levels=None, directory=None, file_name=None, file_format=None, file_rotate=None, is_colored=None, is_bypassed=None, print_config=None, log_components_only=None, fileout_sync_on_flush=None, buffered_stdout=None))]
pub fn py_init_logging(
    trader_id: TraderId,
    instance_id: UUID4,
    level_stdout: LogLevel,
    level_file: Option<LogLevel>,
    component_levels: Option<std::collections::HashMap<String, String>>,
    directory: Option<String>,
    file_name: Option<String>,
    file_format: Option<String>,
    file_rotate: Option<(u64, u32)>,
    is_colored: Option<bool>,
    is_bypassed: Option<bool>,
    print_config: Option<bool>,
    log_components_only: Option<bool>,
    fileout_sync_on_flush: Option<bool>,
    buffered_stdout: Option<bool>,
) -> PyResult<LogGuard> {
    let level_file = level_file.map_or(LevelFilter::Off, map_log_level_to_filter);

    let component_levels = parse_component_levels(component_levels).map_err(to_pyvalue_err)?;

    let file_config = FileWriterConfig::new(directory, file_name, file_format, file_rotate);
    file_config
        .validate()
        .map_err(config_error_to_pyvalue_err)?;

    let mut config = LoggerConfig::new(
        map_log_level_to_filter(level_stdout),
        level_file,
        component_levels,
        AHashMap::new(), // module_level - not exposed to Python
        log_components_only.unwrap_or(false),
        is_colored.unwrap_or(true),
        print_config.unwrap_or(false),
        false,                        // use_tracing - Python handles this separately in kernel
        is_bypassed.unwrap_or(false), // bypass_logging
        None,                         // file_config - passed separately to init_logging
        false,                        // clear_log_file
    );
    config.fileout_sync_on_flush = fileout_sync_on_flush.unwrap_or(true);
    config.buffered_stdout = buffered_stdout.unwrap_or(false);

    let is_bypassed = config.bypass_logging;
    let guard = logging::init_logging(trader_id, instance_id, config, file_config)
        .map_err(to_pyvalue_err)?;

    // Set after init succeeds so a failed attempt leaves no global bypass behind
    if is_bypassed {
        logging_set_bypass();
    }

    Ok(guard)
}

#[pyfunction()]
#[pyo3_stub_gen::derive::gen_stub_pyfunction(module = "nautilus_trader.common")]
#[pyo3(name = "logger_flush")]
pub fn py_logger_flush() {
    log::logger().flush();
}

/// Flushes and syncs file logs to disk.
///
/// This is a no-op when logging is not initialized or file logging is disabled.
///
/// # Errors
///
/// Returns an error if the sync request cannot be delivered or acknowledged.
#[pyfunction()]
#[pyo3_stub_gen::derive::gen_stub_pyfunction(module = "nautilus_trader.common")]
#[pyo3(name = "logging_sync_to_disk")]
pub fn py_logging_sync_to_disk() -> PyResult<bool> {
    logging::logging_sync_to_disk()
        .map(|()| true)
        .map_err(to_pyvalue_err)
}

fn parse_component_levels(
    original_map: Option<std::collections::HashMap<String, String>>,
) -> anyhow::Result<AHashMap<Ustr, LevelFilter>> {
    match original_map {
        Some(map) => {
            let mut new_map = AHashMap::new();

            for (key, value) in map {
                let ustr_key = Ustr::from(&key);
                let level = parse_level_filter_str(&value)?;
                new_map.insert(ustr_key, level);
            }
            Ok(new_map)
        }
        None => Ok(AHashMap::new()),
    }
}

const fn level_filter_to_log_level(level: LevelFilter) -> LogLevel {
    match level {
        LevelFilter::Off => LogLevel::Off,
        LevelFilter::Error => LogLevel::Error,
        LevelFilter::Warn => LogLevel::Warning,
        LevelFilter::Info => LogLevel::Info,
        LevelFilter::Debug => LogLevel::Debug,
        LevelFilter::Trace => LogLevel::Trace,
    }
}

/// Create a new log event.
#[pyfunction]
#[pyo3_stub_gen::derive::gen_stub_pyfunction(module = "nautilus_trader.common")]
#[pyo3(name = "logger_log")]
pub fn py_logger_log(level: LogLevel, color: LogColor, component: &str, message: &str) {
    logger::log(level, color, Ustr::from(component), message);
}

/// Logs the Nautilus startup header with system, identifier, and version details.
#[pyfunction]
#[pyo3_stub_gen::derive::gen_stub_pyfunction(module = "nautilus_trader.common")]
#[pyo3(name = "log_header")]
pub fn py_log_header(trader_id: TraderId, machine_id: &str, instance_id: UUID4, component: &str) {
    headers::log_header(trader_id, machine_id, instance_id, Ustr::from(component));
}

/// Logs current memory and swap usage.
#[pyfunction]
#[pyo3_stub_gen::derive::gen_stub_pyfunction(module = "nautilus_trader.common")]
#[pyo3(name = "log_sysinfo")]
pub fn py_log_sysinfo(component: &str) {
    headers::log_sysinfo(Ustr::from(component));
}

/// Sets the global logging clock to static mode.
#[pyfunction]
#[pyo3_stub_gen::derive::gen_stub_pyfunction(module = "nautilus_trader.common")]
#[pyo3(name = "logging_clock_set_static_mode")]
pub fn py_logging_clock_set_static_mode() {
    logging_clock_set_static_mode();
}

/// Sets the global logging clock to real-time mode.
#[pyfunction]
#[pyo3_stub_gen::derive::gen_stub_pyfunction(module = "nautilus_trader.common")]
#[pyo3(name = "logging_clock_set_realtime_mode")]
pub fn py_logging_clock_set_realtime_mode() {
    logging_clock_set_realtime_mode();
}

/// Sets the global logging clock static time with the given UNIX timestamp (nanoseconds).
#[pyfunction]
#[pyo3_stub_gen::derive::gen_stub_pyfunction(module = "nautilus_trader.common")]
#[pyo3(name = "logging_clock_set_static_time")]
pub fn py_logging_clock_set_static_time(time_ns: u64) {
    logging_clock_set_static_time(time_ns);
}

/// Returns whether the tracing subscriber has been initialized.
#[cfg(feature = "tracing-bridge")]
#[pyfunction]
#[pyo3_stub_gen::derive::gen_stub_pyfunction(module = "nautilus_trader.common")]
#[pyo3(name = "tracing_is_initialized")]
#[must_use]
pub fn py_tracing_is_initialized() -> bool {
    crate::logging::bridge::tracing_is_initialized()
}

/// Initializes a tracing subscriber for external Rust crate logging.
///
/// This sets up a standard tracing subscriber that outputs to stdout with
/// the format controlled by `RUST_LOG` environment variable. The output
/// format uses nanosecond timestamps to align with Nautilus logging.
///
/// # Environment Variables
///
/// - `RUST_LOG`: Controls which modules emit tracing events and at what level.
///   - Example: `RUST_LOG=hyper=debug,tokio=warn`.
///   - Default: `warn` (if not set).
///
/// # Errors
///
/// Returns an error if the tracing subscriber has already been initialized.
#[cfg(feature = "tracing-bridge")]
#[pyfunction]
#[pyo3_stub_gen::derive::gen_stub_pyfunction(module = "nautilus_trader.common")]
#[pyo3(name = "init_tracing")]
pub fn py_init_tracing() -> PyResult<()> {
    crate::logging::bridge::init_tracing().map_err(to_pyvalue_err)
}

/// Python wrapper around the global Rust logger.
///
/// It mirrors the familiar Python `logging` interface while forwarding
/// all records through the Nautilus logging infrastructure so that log levels
/// and formatting remain consistent across Rust and Python.
#[pyclass(
    module = "nautilus_trader.common",
    name = "Logger",
    unsendable,
    from_py_object
)]
#[pyo3_stub_gen::derive::gen_stub_pyclass(module = "nautilus_trader.common")]
#[derive(Debug, Clone)]
pub struct PyLogger {
    name: Ustr,
}

impl PyLogger {
    pub fn new(name: &str) -> Self {
        Self {
            name: Ustr::from(name),
        }
    }

    /// Logs a failed Python callback with its traceback and component identity.
    pub fn log_callback_error(&self, method: &str, result: PyResult<()>) {
        if let Err(e) = result {
            let exception = format_exception(&e);
            self.log_message(
                LogLevel::Error,
                Some(LogColor::Red),
                &format!("Python {method} failed:\n{exception}"),
            );
        }
    }

    fn log_message(&self, level: LogLevel, color: Option<LogColor>, message: &str) {
        let color = color.unwrap_or(LogColor::Normal);
        logger::log(level, color, self.name, message);
    }
}

#[pymethods]
#[pyo3_stub_gen::derive::gen_stub_pymethods]
impl PyLogger {
    /// Create a new `Logger` instance.
    #[new]
    #[pyo3(signature = (name="Python"))]
    fn py_new(name: &str) -> Self {
        Self::new(name)
    }

    /// The component identifier carried by this logger.
    #[getter]
    fn name(&self) -> &str {
        &self.name
    }

    /// Emit a TRACE level record.
    #[pyo3(name = "trace")]
    #[pyo3(signature = (message, color=None))]
    fn py_trace(&self, message: &str, color: Option<LogColor>) {
        self.log_message(LogLevel::Trace, color, message);
    }

    /// Emit a DEBUG level record.
    #[pyo3(name = "debug")]
    #[pyo3(signature = (message, color=None))]
    fn py_debug(&self, message: &str, color: Option<LogColor>) {
        self.log_message(LogLevel::Debug, color, message);
    }

    /// Emit an INFO level record.
    #[pyo3(name = "info")]
    #[pyo3(signature = (message, color=None))]
    fn py_info(&self, message: &str, color: Option<LogColor>) {
        self.log_message(LogLevel::Info, color, message);
    }

    /// Emit a WARNING level record.
    #[pyo3(name = "warning")]
    #[pyo3(signature = (message, color=None))]
    fn py_warning(&self, message: &str, color: Option<LogColor>) {
        self.log_message(LogLevel::Warning, color, message);
    }

    /// Emit an ERROR level record.
    #[pyo3(name = "error")]
    #[pyo3(signature = (message, color=None))]
    fn py_error(&self, message: &str, color: Option<LogColor>) {
        self.log_message(LogLevel::Error, color, message);
    }

    /// Emit an ERROR level record with the active Python exception info.
    #[pyo3(name = "exception")]
    #[pyo3(signature = (message="", color=None))]
    fn py_exception(&self, py: Python, message: &str, color: Option<LogColor>) {
        let mut full_msg = message.to_owned();

        if pyo3::PyErr::occurred(py) {
            let err = PyErr::fetch(py);
            let err_str = err.to_string();

            if full_msg.is_empty() {
                full_msg = err_str;
            } else {
                full_msg = format!("{full_msg}: {err_str}");
            }
        }

        self.log_message(LogLevel::Error, color, &full_msg);
    }

    /// Flush buffered log records.
    #[pyo3(name = "flush")]
    fn py_flush(&self) {
        log::logger().flush();
    }

    /// Emits a log record at the given level for Python callers.
    #[pyo3(name = "_log")]
    #[pyo3(signature = (level, color=None, message=""))]
    fn py_log(&self, level: LogLevel, color: Option<LogColor>, message: &str) {
        self.log_message(level, color, message);
    }
}

/// Formats a Python exception, including its traceback and chained exceptions.
///
/// Falls back to the exception type and message if traceback formatting fails.
#[must_use]
pub fn format_exception(e: &PyErr) -> String {
    Python::attach(|py| {
        py.import("traceback")
            .and_then(|module| {
                module.call_method1(
                    "format_exception",
                    (e.get_type(py), e.value(py), e.traceback(py)),
                )
            })
            .and_then(|lines| lines.extract::<Vec<String>>())
            .map_or_else(|_| e.to_string(), |lines| lines.concat())
    })
}

#[cfg(test)]
mod tests {
    use nautilus_core::python::to_pyruntime_err;
    use pyo3::ffi::c_str;
    use rstest::rstest;

    use super::*;

    // Uses the process-global logger, so it relies on nextest running each test in its own process
    #[rstest]
    fn test_init_logging_failure_leaves_no_bypass_for_retry() {
        let temp_dir = tempfile::tempdir().unwrap();
        let blocking_file = temp_dir.path().join("not_a_directory");
        std::fs::write(&blocking_file, "").unwrap();

        let init = |directory: &std::path::Path, is_bypassed: bool| {
            py_init_logging(
                TraderId::from("TRADER-001"),
                UUID4::new(),
                LogLevel::Off,
                Some(LogLevel::Info),
                None,
                Some(directory.to_str().unwrap().to_string()),
                None,
                None,
                None,
                None,
                Some(is_bypassed),
                None,
                None,
                None,
                None,
            )
        };

        let failed = init(&blocking_file, true);
        let guard = init(temp_dir.path(), false).unwrap();
        log::info!(component = "BypassTest"; "logged after retry");
        crate::logging::logging_sync_to_disk().unwrap();

        assert!(failed.is_err());
        let log_path = std::fs::read_dir(temp_dir.path())
            .unwrap()
            .map(|entry| entry.unwrap().path())
            .find(|path| path.extension().is_some_and(|extension| extension == "log"))
            .unwrap();
        let contents = std::fs::read_to_string(log_path).unwrap();
        assert!(
            contents.contains("logged after retry"),
            "log file: {contents:?}"
        );
        drop(guard);
    }

    #[rstest]
    fn test_format_exception_traceback_and_cause() {
        Python::initialize();
        Python::attach(|py| {
            let module = PyModule::from_code(
                py,
                c_str!(
                    r#"
def callback():
    try:
        fail()
    except ValueError as e:
        raise RuntimeError("callback failure") from e

def fail():
    raise ValueError("original failure")
"#
                ),
                c_str!("strategy_callback.py"),
                c_str!("strategy_callback"),
            )
            .unwrap();
            let e = module.call_method0("callback").unwrap_err();
            let formatted = format_exception(&e);

            assert!(formatted.contains("File \"strategy_callback.py\", line 9, in fail"));
            assert!(formatted.contains("File \"strategy_callback.py\", line 6, in callback"));
            assert!(formatted.contains("ValueError: original failure"));
            assert!(formatted.contains("The above exception was the direct cause"));
            assert!(formatted.ends_with("RuntimeError: callback failure\n"));
        });
    }

    #[rstest]
    fn test_format_exception_without_traceback() {
        Python::initialize();
        let e = to_pyruntime_err("callback failure");
        assert_eq!(format_exception(&e), "RuntimeError: callback failure\n");
    }

    #[rstest]
    fn test_format_exception_fallback() {
        Python::initialize();
        Python::attach(|py| {
            let traceback = py.import("traceback").unwrap();
            let original = traceback.getattr("format_exception").unwrap();
            traceback.setattr("format_exception", py.None()).unwrap();
            let e = to_pyruntime_err("callback failure");
            let formatted = format_exception(&e);
            traceback.setattr("format_exception", original).unwrap();

            assert_eq!(formatted, "RuntimeError: callback failure");
        });
    }
}