rex_logger/memory_logger/

handler.rs

//! Script log handler implementation for capturing and storing Rhai script logs.
//!
//! This module provides the core functionality for capturing log events from Rhai scripts
//! and storing them in memory for later retrieval. It implements a tracing layer that
//! filters for script-specific log events and converts them into structured log entries.
use crate::memory_logger::config::{
    DEFAULT_LOG_ENTRIES_LIMIT, DEFAULT_MESSAGE_LENGTH_LIMIT, LogEntry, RhaiContext,
};
use crate::tracing_logger::level::log_level;
use crate::{RUNNER_AND_SYSLOG_TARGET, RUNNER_TARGET, RUNNER_TARGET_FOR_SCRIPT_LOGS};
use bounded_vec_deque::BoundedVecDeque;
use chrono::Utc;
use std::fmt::Debug;
use std::sync::atomic::{AtomicBool, Ordering};
use std::sync::{Arc, Mutex, OnceLock};
use tracing::field::{Field, Visit};
use tracing::{Event, Subscriber};
use tracing_subscriber::Layer;
use tracing_subscriber::layer::Context;
use tracing_subscriber::registry::LookupSpan;

/// Handle for accessing and managing script logs captured during execution.
///
/// This structure provides a thread-safe interface for storing and retrieving
/// log entries generated by Rhai scripts. It implements the tracing `Layer` trait
/// to automatically capture relevant log events.
#[derive(Debug, Clone)]
pub struct ScriptLogHandle {
    logs: Arc<Mutex<BoundedVecDeque<LogEntry>>>,
    rhai_context_stack: Arc<Mutex<Vec<RhaiContext>>>,
    max_script_log_message_length: usize,
    max_limit_applied: Arc<AtomicBool>,
}

/// Resource Acquisition Is Initialization (RAII) guard for automatic Rhai context cleanup.
///
/// This guard ensures that Rhai execution contexts are automatically removed
/// from the stack when they go out of scope, providing exception-safe context
/// management even if panics occur during script execution.
#[derive(Debug)]
pub struct RhaiContextGuard;

impl Drop for RhaiContextGuard {
    /// Automatically pops the Rhai context from the stack when the guard is dropped.
    fn drop(&mut self) {
        pop_current_rhai_context();
    }
}

/// Global singleton instance of the script log handle.
pub static SCRIPT_HANDLE: OnceLock<ScriptLogHandle> = OnceLock::new();

/// Retrieves the global script log handle instance.
///
/// This function provides access to the singleton `ScriptLogHandle` instance.
/// Returns `None` if the handle has not been initialized yet.
///
/// # Returns
///
/// * `Some(&ScriptLogHandle)` - Reference to the global handle if initialized
/// * `None` - If the handle has not been initialized
pub fn get_script_handle() -> Option<&'static ScriptLogHandle> {
    SCRIPT_HANDLE.get()
}

/// Pushes a new Rhai execution context onto the stack and returns a guard for automatic cleanup.
///
/// This function creates a new `RhaiContext` with the provided function name and line number,
/// then pushes it onto the global context stack.
///
/// # Examples
///
/// ```
/// use rex_logger::memory_logger::handler::push_rhai_context_with_guard;
/// let guard = push_rhai_context_with_guard(Some("my_function"), 42);
/// ```
pub fn push_rhai_context_with_guard(
    rhai_api_name: Option<&str>,
    line_number: u32,
) -> RhaiContextGuard {
    if let Some(handle) = SCRIPT_HANDLE.get() {
        handle.push_rhai_context(RhaiContext {
            rhai_api_name: rhai_api_name.map(str::to_string),
            line_number,
        });
    }

    RhaiContextGuard
}

/// Retrieves the current Rhai execution context from the top of the stack.
///
/// This function returns the most recently pushed context without removing it from
/// the stack, following Last-In-First-Out (LIFO) semantics.
///
/// # Examples
///
/// ```
/// use rex_logger::memory_logger::handler::{push_rhai_context_with_guard, get_current_rhai_context};
/// let guard = push_rhai_context_with_guard(Some("test_function"), 10);
///
/// if let Some(context) = get_current_rhai_context() {
///     println!("Currently executing: {:?} at line {}",
///              context.rhai_api_name, context.line_number);
/// }
/// ```
pub fn get_current_rhai_context() -> Option<RhaiContext> {
    SCRIPT_HANDLE
        .get()
        .and_then(ScriptLogHandle::get_current_rhai_context)
}

/// Pops and returns the current Rhai execution context from the stack.
///
/// This function removes the most recently pushed context from the stack and returns it,
/// following Last-In-First-Out (LIFO) semantics.
///
/// # Examples
///
/// ```
/// use rex_logger::memory_logger::handler::{push_rhai_context_with_guard, get_current_rhai_context, pop_current_rhai_context};
/// let guard = push_rhai_context_with_guard(Some("test_function"), 10);
///
///
/// if let Some(context) = pop_current_rhai_context() {
///     println!("Popped context: {:?} at line {}",
///              context.rhai_api_name, context.line_number);
/// }
///
/// // Stack is now empty
/// assert!(get_current_rhai_context().is_none());
/// ```
pub fn pop_current_rhai_context() -> Option<RhaiContext> {
    SCRIPT_HANDLE
        .get()
        .and_then(ScriptLogHandle::pop_rhai_context)
}

impl Default for ScriptLogHandle {
    fn default() -> Self {
        Self::new(DEFAULT_MESSAGE_LENGTH_LIMIT, DEFAULT_LOG_ENTRIES_LIMIT)
    }
}

impl ScriptLogHandle {
    /// Creates a new `ScriptLogHandle` with specified message length and max log entries limits
    pub fn new(max_script_log_message_length: usize, max_log_entries: usize) -> Self {
        Self {
            logs: Arc::new(Mutex::new(BoundedVecDeque::new(max_log_entries))),
            rhai_context_stack: Arc::new(Mutex::new(Vec::new())),
            max_script_log_message_length,
            max_limit_applied: Arc::new(AtomicBool::new(false)),
        }
    }

    /// Truncates the message if it exceeds the configured length limit.
    fn truncate_message(&self, message: String) -> String {
        if message.len() > self.max_script_log_message_length {
            let truncate_suffix = "...[truncate]";
            let available_chars = self
                .max_script_log_message_length
                .saturating_sub(truncate_suffix.len());
            format!("{}{}", &message[..available_chars], truncate_suffix)
        } else {
            message
        }
    }

    /// Converts a tracing event into a structured log entry.
    #[allow(clippy::unused_self)]
    fn convert_event_to_log_entry(&self, event: &Event<'_>) -> LogEntry {
        let mut message = String::new();
        let mut visitor = MessageVisitor(&mut message);
        event.record(&mut visitor);

        LogEntry {
            timestamp: Utc::now(),
            line_number: get_current_rhai_context().map_or_else(|| 0, |ctx| ctx.line_number),
            level: event.metadata().level().to_string(),
            message: self.truncate_message(message),
            rhai_api_name: get_current_rhai_context().and_then(|ctx| ctx.rhai_api_name),
        }
    }

    /// Retrieves all captured script log entries.
    ///
    /// This method returns a clone of all log entries that have been captured
    /// since the handle was created or last cleared. The returned vector
    /// contains entries in the order they were captured.
    ///
    /// # Returns
    ///
    /// A `Vec<LogEntry>` containing all captured log entries. Returns an empty
    /// vector if no logs have been captured or if there was an error accessing
    /// the internal log storage.
    pub fn get_logs(&self) -> Vec<LogEntry> {
        self.logs
            .lock()
            .map(|guard| guard.iter().cloned().collect())
            .unwrap_or_default()
    }

    /// Returns whether the maximum limit was applied and elements were removed.
    ///
    /// This method checks if the bounded deque ever reached capacity and had to
    /// evict older entries to make room for new ones.
    ///
    /// # Returns
    ///
    /// `true` if the limit was applied at least once, `false` otherwise.
    pub fn was_max_limit_applied(&self) -> bool {
        self.max_limit_applied.load(Ordering::Relaxed)
    }

    fn add_log_entry(&self, log_entry: LogEntry) {
        if let Ok(mut logs) = self.logs.lock() {
            let displaced_entry = logs.push_back(log_entry);
            if displaced_entry.is_some() {
                self.max_limit_applied.store(true, Ordering::Relaxed);
            }
        }
    }

    // Push the current Rhai execution context
    fn push_rhai_context(&self, context: RhaiContext) {
        if let Ok(mut stack) = self.rhai_context_stack.lock() {
            stack.push(context);
        }
    }

    // Clear the current Rhai execution context
    fn pop_rhai_context(&self) -> Option<RhaiContext> {
        self.rhai_context_stack
            .lock()
            .ok()
            .and_then(|mut stack| stack.pop())
    }

    // Get the current Rhai execution context
    fn get_current_rhai_context(&self) -> Option<RhaiContext> {
        self.rhai_context_stack
            .lock()
            .ok()
            .and_then(|stack| stack.last().cloned())
    }
}

/// Implementation of the tracing `Layer` trait for `ScriptLogHandle`.
///
/// This implementation allows the script log handle to be used as a tracing layer,
/// automatically capturing events that match the script log target and converting
/// them into structured log entries.
impl<S> Layer<S> for ScriptLogHandle
where
    S: Subscriber + for<'lookup> LookupSpan<'lookup>,
{
    /// Processes tracing events and captures those matching the script log target.
    fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) {
        if event.metadata().target() == RUNNER_AND_SYSLOG_TARGET
            || event.metadata().target() == RUNNER_TARGET
            || event.metadata().target() == RUNNER_TARGET_FOR_SCRIPT_LOGS
        {
            if event.metadata().target() == RUNNER_TARGET && get_current_rhai_context().is_none() {
                return;
            }

            let current_level_filter = log_level();
            if current_level_filter >= *event.metadata().level() {
                let log_entry = self.convert_event_to_log_entry(event);
                self.add_log_entry(log_entry);
            }
        }
    }
}

/// Visitor implementation for extracting message content from tracing events.
///
/// This internal structure implements the `Visit` trait to extract the "message"
/// field from tracing events. It's used by the `convert_event_to_log_entry` method
/// to build the log message content.
struct MessageVisitor<'a>(&'a mut String);

impl Visit for MessageVisitor<'_> {
    /// Records debug-formatted field values.
    ///
    /// This method is called for fields that implement `Debug`. If the field
    /// name is "message", it formats the value using debug formatting and
    /// stores it in the internal string buffer.
    ///
    /// # Arguments
    ///
    /// * `field` - The field being visited
    /// * `value` - The debug-formattable value
    fn record_debug(&mut self, field: &Field, value: &dyn Debug) {
        if field.name() == "message" {
            *self.0 = format!("{value:?}");
        }
    }

    /// Records string field values.
    ///
    /// This method is called for string fields. If the field name is "message",
    /// it directly stores the string value in the internal buffer. This method
    /// takes precedence over `record_debug` for string values.
    ///
    /// # Arguments
    ///
    /// * `field` - The field being visited
    /// * `value` - The string value
    fn record_str(&mut self, field: &Field, value: &str) {
        if field.name() == "message" {
            *self.0 = value.to_string();
        }
    }
}

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

    /// Given: ScriptLogHandle implements Default
    /// When: Default::default() is called
    /// Then: It should create a handle with no logs
    #[test]
    fn test_default_implementation() {
        let handle = ScriptLogHandle::default();
        let logs = handle.get_logs();
        assert!(logs.is_empty());
        assert_eq!(logs.len(), 0);
    }

    // Given: Various message lengths and limits with expected truncation behavior
    /// When: truncate_message is called
    /// Then: Messages should be handled correctly based on the should_truncate flag
    #[rstest]
    #[case(
        50,
        "This is a very long message that definitely exceeds the limit",
        true
    )]
    #[case(30, "Short message that fits", false)]
    #[case(100, "Medium length message for testing purposes", false)]
    #[case(20, "This message is way too long for the limit", true)]
    fn test_truncate_message_dynamic(
        #[case] max_length: usize,
        #[case] input: &str,
        #[case] should_truncate: bool,
    ) {
        let handler = ScriptLogHandle::new(max_length, DEFAULT_LOG_ENTRIES_LIMIT);
        let result = handler.truncate_message(input.to_string());

        if should_truncate {
            assert_eq!(result.len(), max_length);
            assert!(result.ends_with("...[truncate]"));
            let expected_prefix_len = max_length - "...[truncate]".len();
            assert_eq!(
                &result[..expected_prefix_len],
                &input[..expected_prefix_len]
            );
        } else {
            assert_eq!(result, input);
        }
    }

    /// Given: ScriptLogHandle with a limit of 10 log entries
    /// When: 10 log entries are added, then an 11th entry is added
    /// Then: The first 10 entries should be retained, flag should be false initially, then true after exceeding limit, and oldest entry should be evicted
    #[test]
    fn test_bounded_log_entries() {
        let handle = ScriptLogHandle::new(1000, 10);
        let mut all_messages = Vec::new();
        assert!(!handle.was_max_limit_applied());

        for i in 0..10 {
            let log_entry = LogEntry {
                timestamp: Utc::now(),
                line_number: i + 1,
                level: "INFO".to_string(),
                message: format!("Test message {}", i + 1),
                rhai_api_name: None,
            };
            all_messages.push(log_entry.clone());
            handle.add_log_entry(log_entry);
        }

        assert!(!handle.was_max_limit_applied());
        let logs = handle.get_logs();
        assert_eq!(logs.len(), 10);

        for (i, log) in logs.iter().enumerate() {
            assert_eq!(log.message, all_messages[i].message);
        }

        let log_entry_11 = LogEntry {
            timestamp: Utc::now(),
            line_number: 11,
            level: "INFO".to_string(),
            message: "Test message 11".to_string(),
            rhai_api_name: None,
        };
        all_messages.push(log_entry_11.clone());
        handle.add_log_entry(log_entry_11);

        assert!(handle.was_max_limit_applied());
        let logs = handle.get_logs();
        assert_eq!(logs.len(), 10);

        for (i, log) in logs.iter().enumerate() {
            let expected_index = i + 1; // Messages 2-11 correspond to indices 1-10 in all_messages
            assert_eq!(log.message, all_messages[expected_index].message);
            assert_eq!(log.line_number, all_messages[expected_index].line_number);
        }
    }
}