cu29_log/

lib.rs

#![cfg_attr(not(feature = "std"), no_std)]
#[cfg(not(feature = "std"))]
extern crate alloc;
extern crate core;

use bincode::{Decode, Encode};
use cu29_clock::CuTime;
use cu29_value::Value;
use serde::{Deserialize, Serialize};
use smallvec::SmallVec;

#[cfg(not(feature = "std"))]
mod imp {
    pub use core::fmt::Display;
    pub use core::fmt::Formatter;
    pub use core::fmt::Result as FmtResult;
}

#[cfg(feature = "defmt")]
extern crate defmt;

#[cfg(feature = "std")]
mod imp {
    pub use core::fmt::Display;
    pub use cu29_traits::CuResult;
    // strfmt forces hashmap from std
    pub use std::collections::HashMap;
    pub use std::fmt::Formatter;
    pub use std::fmt::Result as FmtResult;
    // This is a blocker for no_std, so no live logging in no_std for now.
    pub use strfmt::strfmt;
}

use imp::*;

/// Log levels for Copper.
#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Serialize, Deserialize)]
pub enum CuLogLevel {
    /// Detailed information useful during development
    Debug = 0,
    /// General information about system operation
    Info = 1,
    /// Indication of potential issues that don't prevent normal operation
    Warning = 2,
    /// Issues that might disrupt normal operation but don't cause system failure
    Error = 3,
    /// Critical errors requiring immediate attention, usually resulting in system failure
    Critical = 4,
}

impl CuLogLevel {
    /// Returns true if this log level is enabled for the given max level
    ///
    /// The log level is enabled if it is greater than or equal to the max level.
    /// For example, if max_level is Info, then Info, Warning, Error and Critical are enabled,
    /// but Debug is not.
    #[inline]
    pub const fn enabled(self, max_level: CuLogLevel) -> bool {
        self as u8 >= max_level as u8
    }
}

#[allow(dead_code)]
pub const ANONYMOUS: u32 = 0;

pub const MAX_LOG_PARAMS_ON_STACK: usize = 10;

/// Runtime origin metadata attached to a structured log entry when available.
#[derive(Debug, Clone, Copy, Default, Serialize, Deserialize, PartialEq, Eq, Encode, Decode)]
pub struct CuLogOrigin {
    /// CopperList id of the callback that emitted this log line.
    pub culistid: Option<u64>,
    /// Runtime component id recorded for the active callback.
    pub component_id: Option<u32>,
    /// Current task index when the emitting callback belongs to a task.
    pub task_index: Option<u32>,
}

/// This is the basic structure for a log entry in Copper.
#[derive(Debug, Clone, Serialize, Deserialize, PartialEq)]
pub struct CuLogEntry {
    // Approximate time when the log entry was created.
    pub time: CuTime,

    // Log level of this entry
    pub level: CuLogLevel,

    // Runtime origin metadata when the log was emitted from a Copper callback.
    pub origin: CuLogOrigin,

    // interned index of the message
    pub msg_index: u32,

    // interned indexes of the parameter names
    pub paramname_indexes: SmallVec<[u32; MAX_LOG_PARAMS_ON_STACK]>,

    // Serializable values for the parameters (Values are acting like an Any Value).
    pub params: SmallVec<[Value; MAX_LOG_PARAMS_ON_STACK]>,
}

impl Encode for CuLogEntry {
    fn encode<E: bincode::enc::Encoder>(
        &self,
        encoder: &mut E,
    ) -> Result<(), bincode::error::EncodeError> {
        self.time.encode(encoder)?;
        (self.level as u8).encode(encoder)?;
        self.origin.encode(encoder)?;
        self.msg_index.encode(encoder)?;

        (self.paramname_indexes.len() as u64).encode(encoder)?;
        for &index in &self.paramname_indexes {
            index.encode(encoder)?;
        }

        (self.params.len() as u64).encode(encoder)?;
        for param in &self.params {
            param.encode(encoder)?;
        }

        Ok(())
    }
}

impl<Context> Decode<Context> for CuLogEntry {
    fn decode<D: bincode::de::Decoder>(
        decoder: &mut D,
    ) -> Result<Self, bincode::error::DecodeError> {
        let time = CuTime::decode(decoder)?;
        let level_raw = u8::decode(decoder)?;
        let level = match level_raw {
            0 => CuLogLevel::Debug,
            1 => CuLogLevel::Info,
            2 => CuLogLevel::Warning,
            3 => CuLogLevel::Error,
            4 => CuLogLevel::Critical,
            _ => CuLogLevel::Debug, // Fallback for malformed data
        };
        let origin = CuLogOrigin::decode(decoder)?;
        let msg_index = u32::decode(decoder)?;

        let paramname_len = u64::decode(decoder)? as usize;
        let mut paramname_indexes = SmallVec::with_capacity(paramname_len);
        for _ in 0..paramname_len {
            paramname_indexes.push(u32::decode(decoder)?);
        }

        let params_len = u64::decode(decoder)? as usize;
        let mut params = SmallVec::with_capacity(params_len);
        for _ in 0..params_len {
            params.push(Value::decode(decoder)?);
        }

        Ok(CuLogEntry {
            time,
            level,
            origin,
            msg_index,
            paramname_indexes,
            params,
        })
    }
}

// This is for internal debug purposes.
impl Display for CuLogEntry {
    fn fmt(&self, f: &mut Formatter<'_>) -> FmtResult {
        write!(
            f,
            "CuLogEntry {{ level: {:?}, origin: {:?}, msg_index: {}, paramname_indexes: {:?}, params: {:?} }}",
            self.level, self.origin, self.msg_index, self.paramname_indexes, self.params
        )
    }
}

impl CuLogEntry {
    /// msg_index is the interned index of the message.
    pub fn new(msg_index: u32, level: CuLogLevel) -> Self {
        CuLogEntry {
            time: 0.into(), // We have no clock at that point it is called from random places
            // the clock will be set at actual log time from clock source provided
            level,
            origin: CuLogOrigin::default(),
            msg_index,
            paramname_indexes: SmallVec::new(),
            params: SmallVec::new(),
        }
    }

    /// Attach runtime origin metadata to this log entry.
    pub fn set_origin(
        &mut self,
        culistid: Option<u64>,
        component_id: Option<u32>,
        task_index: Option<u32>,
    ) {
        self.origin = CuLogOrigin {
            culistid,
            component_id,
            task_index,
        };
    }

    /// Add a parameter to the log entry.
    /// paramname_index is the interned index of the parameter name.
    pub fn add_param(&mut self, paramname_index: u32, param: Value) {
        self.paramname_indexes.push(paramname_index);
        self.params.push(param);
    }
}

/// Text log line formatter.
/// Only available on std. TODO(gbin): Maybe reconsider that at some point
#[inline]
#[cfg(feature = "std")]
pub fn format_logline(
    time: CuTime,
    level: CuLogLevel,
    format_str: &str,
    params: &[String],
    named_params: &HashMap<String, String>,
) -> CuResult<String> {
    // If the format string uses positional placeholders (`{}`), fill them in order using the
    // anonymous params first, then any named params (sorted for determinism) if needed.
    if format_str.contains("{}") {
        let mut formatted = format_str.to_string();
        for param in params.iter() {
            if !formatted.contains("{}") {
                break;
            }
            formatted = formatted.replacen("{}", param, 1);
        }
        if !named_params.is_empty() {
            let mut named = named_params.iter().collect::<Vec<_>>();
            named.sort_by(|a, b| a.0.cmp(b.0));
            for (name, value) in named {
                if formatted.contains("{}") {
                    formatted = formatted.replacen("{}", value, 1);
                }
                formatted = formatted.replace(&format!("{{{name}}}"), value);
            }
        }
        return Ok(format!("{time} [{level:?}]: {formatted}"));
    }

    // Otherwise rely on named formatting.
    let logline = strfmt(format_str, named_params).map_err(|e| {
        cu29_traits::CuError::new_with_cause(
            format!("Failed to format log line: {format_str:?} with variables [{named_params:?}]")
                .as_str(),
            e,
        )
    })?;
    Ok(format!("{time} [{level:?}]: {logline}"))
}

/// Rebuild a log line from the interned strings and the CuLogEntry.
/// This basically translates the world of copper logs to text logs.
#[cfg(feature = "std")]
pub fn rebuild_logline(all_interned_strings: &[String], entry: &CuLogEntry) -> CuResult<String> {
    let format_string = all_interned_strings
        .get(entry.msg_index as usize)
        .ok_or_else(|| {
            cu29_traits::CuError::from(format!(
                "Invalid message index {} (interned strings length {})",
                entry.msg_index,
                all_interned_strings.len()
            ))
        })?;
    if entry.paramname_indexes.len() != entry.params.len() {
        return Err(cu29_traits::CuError::from(format!(
            "Mismatched parameter metadata: {} names for {} params",
            entry.paramname_indexes.len(),
            entry.params.len()
        )));
    }

    let mut anon_params = Vec::with_capacity(entry.params.len());
    let mut named_params = HashMap::with_capacity(entry.params.len());

    for (i, param) in entry.params.iter().enumerate() {
        let param_as_string = format!("{param}");
        if entry.paramname_indexes[i] == 0 {
            // Anonymous parameter
            anon_params.push(param_as_string);
        } else {
            // Named parameter
            let name = all_interned_strings
                .get(entry.paramname_indexes[i] as usize)
                .ok_or_else(|| {
                    cu29_traits::CuError::from(format!(
                        "Invalid parameter name index {} (interned strings length {})",
                        entry.paramname_indexes[i],
                        all_interned_strings.len()
                    ))
                })?
                .clone();
            named_params.insert(name, param_as_string);
        }
    }
    format_logline(
        entry.time,
        entry.level,
        format_string,
        &anon_params,
        &named_params,
    )
}

// ---- defmt shims, selected at cu29-log compile time ----
#[cfg(all(feature = "defmt", not(feature = "std")))]
#[macro_export]
macro_rules! __cu29_defmt_debug {
    ($fmt:literal $(, $arg:expr)* $(,)?) => {
        ::defmt::debug!($fmt $(, $arg)*);
    }
}
#[cfg(not(all(feature = "defmt", not(feature = "std"))))]
#[macro_export]
macro_rules! __cu29_defmt_debug {
    ($($tt:tt)*) => {{}};
}

#[cfg(all(feature = "defmt", not(feature = "std")))]
#[macro_export]
macro_rules! __cu29_defmt_info {
    ($fmt:literal $(, $arg:expr)* $(,)?) => {
        ::defmt::info!($fmt $(, $arg)*);
    }
}
#[cfg(not(all(feature = "defmt", not(feature = "std"))))]
#[macro_export]
macro_rules! __cu29_defmt_info {
    ($($tt:tt)*) => {{}};
}

#[cfg(all(feature = "defmt", not(feature = "std")))]
#[macro_export]
macro_rules! __cu29_defmt_warn {
    ($fmt:literal $(, $arg:expr)* $(,)?) => {
        ::defmt::warn!($fmt $(, $arg)*);
    }
}
#[cfg(not(all(feature = "defmt", not(feature = "std"))))]
#[macro_export]
macro_rules! __cu29_defmt_warn {
    ($($tt:tt)*) => {{}};
}

#[cfg(all(feature = "defmt", not(feature = "std")))]
#[macro_export]
macro_rules! __cu29_defmt_error {
    ($fmt:literal $(, $arg:expr)* $(,)?) => {
        ::defmt::error!($fmt $(, $arg)*);
    }
}
#[cfg(not(all(feature = "defmt", not(feature = "std"))))]
#[macro_export]
macro_rules! __cu29_defmt_error {
    ($($tt:tt)*) => {{}};
}

#[macro_export]
macro_rules! defmt_debug {
    ($($tt:tt)*) => { $crate::__cu29_defmt_debug!($($tt)*) };
}

#[macro_export]
macro_rules! defmt_info {
    ($($tt:tt)*) => { $crate::__cu29_defmt_info!($($tt)*) };
}

#[macro_export]
macro_rules! defmt_warn {
    ($($tt:tt)*) => { $crate::__cu29_defmt_warn!($($tt)*) };
}

#[macro_export]
macro_rules! defmt_error {
    ($($tt:tt)*) => { $crate::__cu29_defmt_error!($($tt)*) };
}

#[cfg(test)]
mod tests {
    use super::*;

    #[test]
    fn test_log_level_ordering() {
        assert!(CuLogLevel::Critical > CuLogLevel::Error);
        assert!(CuLogLevel::Error > CuLogLevel::Warning);
        assert!(CuLogLevel::Warning > CuLogLevel::Info);
        assert!(CuLogLevel::Info > CuLogLevel::Debug);

        assert!(CuLogLevel::Debug < CuLogLevel::Info);
        assert!(CuLogLevel::Info < CuLogLevel::Warning);
        assert!(CuLogLevel::Warning < CuLogLevel::Error);
        assert!(CuLogLevel::Error < CuLogLevel::Critical);
    }

    #[test]
    fn test_log_level_enabled() {
        // When min level is Debug (0), all logs are enabled
        assert!(CuLogLevel::Debug.enabled(CuLogLevel::Debug));
        assert!(CuLogLevel::Info.enabled(CuLogLevel::Debug));
        assert!(CuLogLevel::Warning.enabled(CuLogLevel::Debug));
        assert!(CuLogLevel::Error.enabled(CuLogLevel::Debug));
        assert!(CuLogLevel::Critical.enabled(CuLogLevel::Debug));

        // When min level is Info (1), only Info and above are enabled
        assert!(!CuLogLevel::Debug.enabled(CuLogLevel::Info));
        assert!(CuLogLevel::Info.enabled(CuLogLevel::Info));
        assert!(CuLogLevel::Warning.enabled(CuLogLevel::Info));
        assert!(CuLogLevel::Error.enabled(CuLogLevel::Info));
        assert!(CuLogLevel::Critical.enabled(CuLogLevel::Info));

        // When min level is Warning (2), only Warning and above are enabled
        assert!(!CuLogLevel::Debug.enabled(CuLogLevel::Warning));
        assert!(!CuLogLevel::Info.enabled(CuLogLevel::Warning));
        assert!(CuLogLevel::Warning.enabled(CuLogLevel::Warning));
        assert!(CuLogLevel::Error.enabled(CuLogLevel::Warning));
        assert!(CuLogLevel::Critical.enabled(CuLogLevel::Warning));

        // When min level is Error (3), only Error and above are enabled
        assert!(!CuLogLevel::Debug.enabled(CuLogLevel::Error));
        assert!(!CuLogLevel::Info.enabled(CuLogLevel::Error));
        assert!(!CuLogLevel::Warning.enabled(CuLogLevel::Error));
        assert!(CuLogLevel::Error.enabled(CuLogLevel::Error));
        assert!(CuLogLevel::Critical.enabled(CuLogLevel::Error));

        // When min level is Critical (4), only Critical is enabled
        assert!(!CuLogLevel::Debug.enabled(CuLogLevel::Critical));
        assert!(!CuLogLevel::Info.enabled(CuLogLevel::Critical));
        assert!(!CuLogLevel::Warning.enabled(CuLogLevel::Critical));
        assert!(!CuLogLevel::Error.enabled(CuLogLevel::Critical));
        assert!(CuLogLevel::Critical.enabled(CuLogLevel::Critical));
    }

    #[test]
    fn test_cu_log_entry_with_level() {
        let entry = CuLogEntry::new(42, CuLogLevel::Warning);
        assert_eq!(entry.level, CuLogLevel::Warning);
        assert_eq!(entry.origin, CuLogOrigin::default());
        assert_eq!(entry.msg_index, 42);
    }

    #[cfg(feature = "std")]
    #[test]
    fn test_rebuild_logline_mixes_named_and_positional_placeholders() {
        let all_interned_strings = vec![
            "File closed after hash was calculated Hash: {hash}, size: {size};\n{}".to_string(),
            "hash".to_string(),
            "size".to_string(),
        ];
        let mut entry = CuLogEntry::new(0, CuLogLevel::Debug);
        entry.add_param(ANONYMOUS, Value::String("event payload".to_string()));
        entry.add_param(1, Value::String("0x000000000".to_string()));
        entry.add_param(2, Value::U64(420));

        let line = rebuild_logline(&all_interned_strings, &entry).unwrap();

        assert_eq!(
            line,
            "0 ns [Debug]: File closed after hash was calculated Hash: 0x000000000, size: 420;\nevent payload"
        );
    }
}