diff --git a/core/logger/Cargo.toml b/core/logger/Cargo.toml index 52a6b20..9de50e7 100644 --- a/core/logger/Cargo.toml +++ b/core/logger/Cargo.toml @@ -9,7 +9,7 @@ authors = ["Hero Team"] tracing = "0.1" tracing-subscriber = { version = "0.3", features = ["env-filter", "json", "registry", "fmt"] } tracing-appender = "0.2" -tokio = { version = "1", features = ["fs", "time", "rt"] } +tokio = { version = "1", features = ["fs", "time", "rt", "rt-multi-thread", "macros"] } chrono = { version = "0.4", features = ["serde"] } serde = { version = "1.0", features = ["derive"] } serde_json = "1.0" diff --git a/core/logger/README.md b/core/logger/README.md index 0c3880f..fef42af 100644 --- a/core/logger/README.md +++ b/core/logger/README.md @@ -7,11 +7,39 @@ A hierarchical logging system for the Hero project that provides system-level an - **Hierarchical Organization**: Physical separation of logs by component and job - **System Logger**: Global logging for all non-job-specific events - **Per-Job Logger**: Isolated logging for individual job execution +- **Custom Log Format**: Readable format with precise formatting rules - **Hourly Rotation**: Automatic log file rotation every hour - **Rhai Integration**: Capture Rhai script `print()` and `debug()` calls - **High Performance**: Async logging with efficient filtering - **Structured Logging**: Rich context and metadata support +## Custom Log Format + +Hero Logger uses a custom format designed for readability and consistency: + +``` +21:23:42 + system - This is a normal log message + system - This is a multi-line message + second line with proper indentation + third line maintaining alignment +E error_cat - This is an error message +E second line of error +E third line of error +``` + +### Format Rules + +- **Time stamps (HH:MM:SS)** are written once per second when the log time changes +- **Categories** are: + - Limited to 10 characters maximum + - Padded with spaces to exactly 10 characters + - Any `-` in category names are converted to `_` +- **Each line starts with either:** + - ` ` (space) for normal logs (INFO, WARN, DEBUG, TRACE) + - `E` for error logs +- **Multi-line messages** maintain consistent indentation (14 spaces after the prefix) + ## Architecture The logging system uses a hybrid approach with two main components: @@ -188,6 +216,11 @@ The system supports standard tracing log levels: cargo run --example logging_demo ``` +### Custom Format Demo +```bash +cargo run --example custom_format_demo +``` + ### Integration with Actor System ```rust // In your actor implementation diff --git a/core/logger/src/custom_formatter.rs b/core/logger/src/custom_formatter.rs new file mode 100644 index 0000000..7b48846 --- /dev/null +++ b/core/logger/src/custom_formatter.rs @@ -0,0 +1,234 @@ +//! Custom Hero Logger Formatter +//! +//! This module implements a custom formatter for the Hero logging system that provides: +//! - Time stamps (HH:MM:SS) written once per second when the log time changes +//! - Categories limited to 10 characters maximum, padded with spaces, dashes converted to underscores +//! - Each line starts with either space (normal logs) or E (error logs) +//! - Multi-line messages maintain consistent indentation (14 spaces after the prefix) + +use std::fmt; +use std::io::{self, Write}; +use std::sync::{Arc, Mutex}; +use tracing::{Event, Level, Subscriber}; +use tracing_subscriber::fmt::{format::Writer, FmtContext, FormatEvent, FormatFields}; +use tracing_subscriber::registry::LookupSpan; +use chrono::{DateTime, Local}; + +/// Custom formatter for Hero logging system +pub struct HeroFormatter { + /// Tracks the last written timestamp to avoid duplicate timestamps + last_timestamp: Arc>>, +} + +impl HeroFormatter { + /// Create a new Hero formatter + pub fn new() -> Self { + Self { + last_timestamp: Arc::new(Mutex::new(None)), + } + } + + /// Format a category name according to Hero rules: + /// - Convert dashes to underscores + /// - Limit to 10 characters maximum + /// - Pad with spaces to exactly 10 characters + fn format_category(&self, target: &str) -> String { + let processed = target.replace('-', "_"); + let truncated = if processed.len() > 10 { + &processed[..10] + } else { + &processed + }; + format!("{:<10}", truncated) + } + + /// Get the log level prefix (space for normal, E for error) + fn get_level_prefix(&self, level: &Level) -> char { + match *level { + Level::ERROR => 'E', + _ => ' ', + } + } + + /// Get current timestamp in HH:MM:SS format + fn get_current_timestamp(&self) -> String { + let now: DateTime = Local::now(); + now.format("%H:%M:%S").to_string() + } + + /// Check if we need to write a timestamp and update the last timestamp + fn should_write_timestamp(&self, current_timestamp: &str) -> bool { + let mut last_ts = self.last_timestamp.lock().unwrap(); + match last_ts.as_ref() { + Some(last) if last == current_timestamp => false, + _ => { + *last_ts = Some(current_timestamp.to_string()); + true + } + } + } + + /// Format a multi-line message with proper indentation + fn format_message(&self, prefix: char, category: &str, message: &str) -> String { + let lines: Vec<&str> = message.lines().collect(); + if lines.is_empty() { + return format!("{} {} - \n", prefix, category); + } + + let mut result = String::new(); + + // First line: prefix + category + " - " + message + result.push_str(&format!("{} {} - {}\n", prefix, category, lines[0])); + + // Subsequent lines: prefix + 14 spaces + message + for line in lines.iter().skip(1) { + result.push_str(&format!("{} {}\n", prefix, line)); + } + + result + } +} + +impl Default for HeroFormatter { + fn default() -> Self { + Self::new() + } +} + +impl FormatEvent for HeroFormatter +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, +{ + fn format_event( + &self, + _ctx: &FmtContext<'_, S, N>, + mut writer: Writer<'_>, + event: &Event<'_>, + ) -> fmt::Result { + // Get current timestamp + let current_timestamp = self.get_current_timestamp(); + + // Write timestamp if it has changed + if self.should_write_timestamp(¤t_timestamp) { + writeln!(writer, "{}", current_timestamp)?; + } + + // Get event metadata + let metadata = event.metadata(); + let level = metadata.level(); + let target = metadata.target(); + + // Format category and get prefix + let category = self.format_category(target); + let prefix = self.get_level_prefix(level); + + // Capture the message + let mut message_visitor = MessageVisitor::new(); + event.record(&mut message_visitor); + let message = message_visitor.message; + + // Format and write the message + let formatted = self.format_message(prefix, &category, &message); + write!(writer, "{}", formatted)?; + + Ok(()) + } +} + +/// Visitor to extract the message from tracing events +struct MessageVisitor { + message: String, +} + +impl MessageVisitor { + fn new() -> Self { + Self { + message: String::new(), + } + } +} + +impl tracing::field::Visit for MessageVisitor { + fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn fmt::Debug) { + if field.name() == "message" { + self.message = format!("{:?}", value); + // Remove surrounding quotes if present + if self.message.starts_with('"') && self.message.ends_with('"') { + self.message = self.message[1..self.message.len()-1].to_string(); + } + } + } + + fn record_str(&mut self, field: &tracing::field::Field, value: &str) { + if field.name() == "message" { + self.message = value.to_string(); + } + } +} + +#[cfg(test)] +mod tests { + use super::*; + use tracing::{info, error}; + use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt}; + use std::sync::{Arc, Mutex}; + use std::io::Cursor; + + #[test] + fn test_format_category() { + let formatter = HeroFormatter::new(); + + // Test normal category + assert_eq!(formatter.format_category("system"), "system "); + + // Test category with dashes + assert_eq!(formatter.format_category("osis-actor"), "osis_actor"); + + // Test long category (truncation) + assert_eq!(formatter.format_category("very-long-category-name"), "very_long_"); + + // Test exact 10 characters + assert_eq!(formatter.format_category("exactly10c"), "exactly10c"); + } + + #[test] + fn test_get_level_prefix() { + let formatter = HeroFormatter::new(); + + assert_eq!(formatter.get_level_prefix(&Level::ERROR), 'E'); + assert_eq!(formatter.get_level_prefix(&Level::WARN), ' '); + assert_eq!(formatter.get_level_prefix(&Level::INFO), ' '); + assert_eq!(formatter.get_level_prefix(&Level::DEBUG), ' '); + assert_eq!(formatter.get_level_prefix(&Level::TRACE), ' '); + } + + #[test] + fn test_format_message() { + let formatter = HeroFormatter::new(); + + // Test single line message + let result = formatter.format_message(' ', "system ", "Hello world"); + assert_eq!(result, " system - Hello world\n"); + + // Test multi-line message + let result = formatter.format_message('E', "error_cat ", "Line 1\nLine 2\nLine 3"); + let expected = "E error_cat - Line 1\nE Line 2\nE Line 3\n"; + assert_eq!(result, expected); + } + + #[test] + fn test_timestamp_tracking() { + let formatter = HeroFormatter::new(); + let timestamp = "12:34:56"; + + // First call should return true (write timestamp) + assert!(formatter.should_write_timestamp(timestamp)); + + // Second call with same timestamp should return false + assert!(!formatter.should_write_timestamp(timestamp)); + + // Call with different timestamp should return true + assert!(formatter.should_write_timestamp("12:34:57")); + } +} \ No newline at end of file diff --git a/core/logger/src/job_logger.rs b/core/logger/src/job_logger.rs index 6941544..2dd7eda 100644 --- a/core/logger/src/job_logger.rs +++ b/core/logger/src/job_logger.rs @@ -3,7 +3,7 @@ //! This module implements the per-job logging functionality that creates //! temporary, isolated loggers for individual job execution. -use crate::{LoggerError, Result}; +use crate::{LoggerError, Result, custom_formatter::HeroFormatter}; use std::path::{Path, PathBuf}; use tracing_subscriber::{ filter::{EnvFilter, LevelFilter}, @@ -70,13 +70,10 @@ pub fn create_job_logger_with_guard>( let file_appender = rolling::hourly(&job_dir, "log"); let (non_blocking, guard) = tracing_appender::non_blocking(file_appender); - // Create a formatted layer for the job + // Create a formatted layer for the job with custom Hero formatter let layer = fmt::layer() .with_writer(non_blocking) - .with_target(true) - .with_thread_ids(true) - .with_file(true) - .with_line_number(true) + .event_format(HeroFormatter::new()) .with_ansi(false) // No ANSI colors in log files .with_filter( EnvFilter::new("trace") // Capture all logs within the job context @@ -127,13 +124,10 @@ pub fn create_job_logger_with_config>( let (non_blocking, guard) = tracing_appender::non_blocking(file_appender); - // Create layer with custom configuration + // Create layer with custom configuration and Hero formatter let mut layer = fmt::layer() .with_writer(non_blocking) - .with_target(config.include_target) - .with_thread_ids(config.include_thread_ids) - .with_file(config.include_file_location) - .with_line_number(config.include_line_numbers) + .event_format(HeroFormatter::new()) .with_ansi(false); // Apply level filter diff --git a/core/logger/src/lib.rs b/core/logger/src/lib.rs index 70d500e..2937ba5 100644 --- a/core/logger/src/lib.rs +++ b/core/logger/src/lib.rs @@ -39,6 +39,7 @@ mod system_logger; mod job_logger; mod file_appender; mod utils; +mod custom_formatter; pub mod rhai_integration; pub use system_logger::*; diff --git a/core/logger/src/system_logger.rs b/core/logger/src/system_logger.rs index d836b9a..c3f2403 100644 --- a/core/logger/src/system_logger.rs +++ b/core/logger/src/system_logger.rs @@ -3,7 +3,7 @@ //! This module implements the system-wide logging functionality that captures //! all non-job-specific logs from every component with target-based filtering. -use crate::{LoggerError, Result}; +use crate::{LoggerError, Result, custom_formatter::HeroFormatter}; use std::path::{Path, PathBuf}; use tracing_subscriber::{ filter::{EnvFilter, LevelFilter}, @@ -82,13 +82,10 @@ fn create_component_layer>( let file_appender = rolling::hourly(&log_dir, "log"); let (non_blocking, guard) = tracing_appender::non_blocking(file_appender); - // Create a formatted layer with target filtering + // Create a formatted layer with custom Hero formatter and target filtering let layer = fmt::layer() .with_writer(non_blocking) - .with_target(true) - .with_thread_ids(true) - .with_file(true) - .with_line_number(true) + .event_format(HeroFormatter::new()) .with_ansi(false) // No ANSI colors in log files .with_filter( EnvFilter::new(format!("{}=trace", component))