diff --git a/anchor/logging/src/format.rs b/anchor/logging/src/format.rs index 3f43ff367..bc0e19e11 100644 --- a/anchor/logging/src/format.rs +++ b/anchor/logging/src/format.rs @@ -7,9 +7,10 @@ use std::fmt; use nu_ansi_term::{Color, Style}; use tracing_core::{Event, Level, Subscriber}; use tracing_subscriber::{ + field::MakeVisitor, fmt::{ FmtContext, FormattedFields, - format::{FormatEvent, FormatFields, Writer}, + format::{self, FormatEvent, FormatFields, Writer}, time::{FormatTime, SystemTime}, }, registry::LookupSpan, @@ -208,3 +209,144 @@ where writeln!(writer) } } + +/// Field formatter for the file logging layer. +/// +/// This type exists solely to give the file layer a separate +/// `FormattedFields` cache slot in the span extensions type-map, +/// distinct from the console layer's default `FormattedFields`. +/// Without this, the console layer (ANSI-enabled) caches span fields first, +/// and the file layer reuses those ANSI-contaminated fields. +pub struct FileFields; + +impl<'writer> MakeVisitor> for FileFields { + type Visitor = format::DefaultVisitor<'writer>; + + fn make_visitor(&self, target: Writer<'writer>) -> Self::Visitor { + format::DefaultFields::new().make_visitor(target) + } +} + +#[cfg(test)] +mod tests { + use std::sync::{Arc, Mutex}; + + use tracing_subscriber::{fmt, layer::SubscriberExt}; + + use super::*; + + /// ANSI escape sequence prefix. Any output destined for a plain-text file + /// must never contain this byte sequence. + const ANSI_ESCAPE: &[u8] = b"\x1b["; + + /// Returns true if the byte slice contains an ANSI escape sequence. + fn contains_ansi(bytes: &[u8]) -> bool { + bytes + .windows(ANSI_ESCAPE.len()) + .any(|window| window == ANSI_ESCAPE) + } + + /// Helper: build a shared in-memory buffer suitable as a `MakeWriter`. + fn shared_buffer() -> Arc>> { + Arc::new(Mutex::new(Vec::new())) + } + + /// Verifies that the `FileFields` fix prevents ANSI escape sequences from + /// leaking into file layer output when two layers share a registry. + /// + /// Setup mirrors production: a console layer (ANSI-enabled, `DefaultFields`) + /// and a file layer (ANSI-disabled, `FileFields`). Both are attached to the + /// same `Registry`. Because `FileFields` has a distinct `TypeId` from + /// `DefaultFields`, each layer gets its own `FormattedFields<_>` cache slot + /// in the span extensions. The file layer therefore never reads the + /// console layer's ANSI-contaminated cached fields. + /// + /// This test PASSES with the fix (`FileFields`) in place. + #[test] + fn test_file_fields_no_ansi_leak_in_span_fields() { + // Arrange + let console_buf = shared_buffer(); + let file_buf = shared_buffer(); + + let console_writer = console_buf.clone(); + let file_writer = file_buf.clone(); + + // Console layer: ANSI enabled, uses default DefaultFields (implicit). + let console_layer = + fmt::layer() + .with_ansi(true) + .with_writer(move || -> Box { + Box::new(MockWriter(console_writer.clone())) + }); + + // File layer: ANSI disabled, uses FileFields for a distinct cache slot. + let file_layer = fmt::layer() + .with_ansi(false) + .fmt_fields(FileFields) + .with_writer(move || -> Box { + Box::new(MockWriter(file_writer.clone())) + }); + + let subscriber = tracing_subscriber::registry() + .with(console_layer) + .with(file_layer); + + // Act + tracing::subscriber::with_default(subscriber, || { + let span = tracing::info_span!("test_span", some_field = "hello_world"); + let _guard = span.enter(); + tracing::info!("message inside span"); + }); + + // Assert -- file buffer must not contain ANSI escape sequences + let file_output = file_buf.lock().unwrap(); + let file_str = String::from_utf8_lossy(&file_output); + + assert!( + !file_output.is_empty(), + "File layer should have captured output" + ); + assert!( + !contains_ansi(&file_output), + "File layer output must not contain ANSI escape sequences.\n\ + File output was:\n{file_str}" + ); + + // The file output should contain the span field value in plain text + assert!( + file_str.contains("some_field"), + "File layer output should contain the span field name 'some_field'.\n\ + File output was:\n{file_str}" + ); + + // Assert -- console buffer SHOULD contain ANSI (confirms both layers work) + let console_output = console_buf.lock().unwrap(); + assert!( + !console_output.is_empty(), + "Console layer should have captured output" + ); + assert!( + contains_ansi(&console_output), + "Console layer output should contain ANSI escape sequences, \ + confirming the console layer is ANSI-enabled." + ); + } + + // ==================== Test helpers ==================== + + /// A writer that appends to a shared `Vec` buffer. + /// Implements `std::io::Write` so it can be used with `fmt::layer().with_writer()`. + struct MockWriter(Arc>>); + + impl std::io::Write for MockWriter { + fn write(&mut self, buf: &[u8]) -> std::io::Result { + let mut lock = self.0.lock().unwrap(); + lock.extend_from_slice(buf); + Ok(buf.len()) + } + + fn flush(&mut self) -> std::io::Result<()> { + Ok(()) + } + } +} diff --git a/anchor/logging/src/lib.rs b/anchor/logging/src/lib.rs index 942c06526..d6826ede2 100644 --- a/anchor/logging/src/lib.rs +++ b/anchor/logging/src/lib.rs @@ -5,4 +5,4 @@ pub mod utils; pub use count_layer::CountLayer; pub use logging::*; pub mod format; -pub use format::AnchorFormatter; +pub use format::{AnchorFormatter, FileFields}; diff --git a/anchor/src/main.rs b/anchor/src/main.rs index e78a723c2..5da296218 100644 --- a/anchor/src/main.rs +++ b/anchor/src/main.rs @@ -11,7 +11,7 @@ use global_config::{GlobalConfig, GlobalFlags}; use keygen::Keygen; use keysplit::Keysplit; use logging::{ - AnchorFormatter, CountLayer, FileLoggingFlags, create_libp2p_discv5_tracing_layer, + AnchorFormatter, CountLayer, FileFields, FileLoggingFlags, create_libp2p_discv5_tracing_layer, init_file_logging, utils::build_workspace_filter, }; use task_executor::ShutdownReason; @@ -282,6 +282,7 @@ pub fn enable_logging( logging_layers.push( fmt::layer() .event_format(anchor_formatter_log) + .fmt_fields(FileFields) .with_writer(file_logging_layer.non_blocking_writer) .with_ansi(file_logging_flags.logfile_color) .with_filter(