From ddf241704aafcdc0ad77030f482c341d3eaf14f8 Mon Sep 17 00:00:00 2001 From: Itay Tsabary Date: Thu, 28 Nov 2024 13:59:38 +0200 Subject: [PATCH] chore(starknet_sequencer_infra): add tracing test commit-id:76d16e9a --- Cargo.lock | 1 + crates/infra_utils/Cargo.toml | 1 + crates/infra_utils/src/tracing.rs | 3 + crates/infra_utils/src/tracing_test.rs | 159 +++++++++++++++++++++++++ 4 files changed, 164 insertions(+) create mode 100644 crates/infra_utils/src/tracing_test.rs diff --git a/Cargo.lock b/Cargo.lock index 54ec752004a..6c72df7b372 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5246,6 +5246,7 @@ dependencies = [ "rstest", "tokio", "tracing", + "tracing-subscriber", ] [[package]] diff --git a/crates/infra_utils/Cargo.toml b/crates/infra_utils/Cargo.toml index fe814eec397..72261392cbc 100644 --- a/crates/infra_utils/Cargo.toml +++ b/crates/infra_utils/Cargo.toml @@ -16,3 +16,4 @@ tracing.workspace = true [dev-dependencies] rstest.workspace = true tokio = { workspace = true, features = ["macros", "rt"] } +tracing-subscriber = { workspace = true, features = ["env-filter"] } diff --git a/crates/infra_utils/src/tracing.rs b/crates/infra_utils/src/tracing.rs index 6afb1db18a3..77fcfab3711 100644 --- a/crates/infra_utils/src/tracing.rs +++ b/crates/infra_utils/src/tracing.rs @@ -1,5 +1,8 @@ use tracing::{debug, error, info, trace, warn}; +#[cfg(test)] +#[path = "tracing_test.rs"] +mod tracing_test; /// Dynamically set tracing level of a message. pub struct DynamicLogger { level: TraceLevel, diff --git a/crates/infra_utils/src/tracing_test.rs b/crates/infra_utils/src/tracing_test.rs new file mode 100644 index 00000000000..50628159612 --- /dev/null +++ b/crates/infra_utils/src/tracing_test.rs @@ -0,0 +1,159 @@ +use std::fmt::Debug; +use std::sync::{Arc, Mutex}; + +use tracing::field::{Field, Visit}; +use tracing::span::{Attributes, Id, Record}; +use tracing::subscriber::with_default; +use tracing::{Event, Metadata, Subscriber}; + +use crate::tracing::{DynamicLogger, TraceLevel}; + +#[test] +fn test_dynamic_logger_without_base_message() { + let subscriber = TestSubscriber::new(); + + with_default(subscriber.clone(), || { + let logger = DynamicLogger::new(TraceLevel::Info, None); + logger.log_message("Test message"); + }); + + let messages = subscriber.messages(); + assert_eq!(messages.len(), 1); + assert!(messages[0].contains("Test message")); + assert!(messages[0].contains("INFO")); +} + +#[test] +fn test_dynamic_logger_with_base_message() { + let subscriber = TestSubscriber::new(); + + with_default(subscriber.clone(), || { + let logger = DynamicLogger::new(TraceLevel::Debug, Some("BaseMessage".to_string())); + logger.log_message("Test message"); + }); + + let messages = subscriber.messages(); + assert_eq!(messages.len(), 1); + assert!(messages[0].contains("BaseMessage: Test message")); + assert!(messages[0].contains("DEBUG")); +} + +#[test] +fn test_all_trace_levels() { + let subscriber = TestSubscriber::new(); + + let test_cases = [ + (TraceLevel::Trace, "TRACE"), + (TraceLevel::Debug, "DEBUG"), + (TraceLevel::Info, "INFO"), + (TraceLevel::Warn, "WARN"), + (TraceLevel::Error, "ERROR"), + ]; + + with_default(subscriber.clone(), || { + for (level, expected_level_str) in test_cases { + subscriber.clear(); + let logger = DynamicLogger::new(level, None); + logger.log_message("Test message"); + + let messages = subscriber.messages(); + assert_eq!(messages.len(), 1); + assert!(messages[0].contains(expected_level_str)); + assert!(messages[0].contains("Test message")); + } + }); +} + +#[test] +fn test_message_formatting() { + let subscriber = TestSubscriber::new(); + + with_default(subscriber.clone(), || { + let base_message = Some("Component".to_string()); + let logger = DynamicLogger::new(TraceLevel::Info, base_message); + logger.log_message("Operation completed"); + }); + + let messages = subscriber.messages(); + assert_eq!(messages.len(), 1); + assert!(messages[0].contains("Component: Operation completed")); + assert!(messages[0].contains("INFO")); +} + +#[test] +fn test_empty_message() { + let subscriber = TestSubscriber::new(); + + with_default(subscriber.clone(), || { + let logger = DynamicLogger::new(TraceLevel::Warn, None); + logger.log_message(""); + }); + + let messages = subscriber.messages(); + assert_eq!(messages.len(), 1); + assert!(messages[0].contains("WARN")); +} + +// Custom visitor to capture event fields +struct MessageVisitor<'a> { + message: &'a mut String, +} + +impl<'a> Visit for MessageVisitor<'a> { + fn record_debug(&mut self, field: &Field, value: &dyn Debug) { + if field.name() == "message" { + self.message.push_str(&format!("{:?}", value)); + } + } +} + +// Custom subscriber to capture log output +#[derive(Default, Clone)] +struct TestSubscriber { + messages: Arc>>, +} + +impl TestSubscriber { + fn new() -> Self { + Self { messages: Arc::new(Mutex::new(Vec::new())) } + } + + fn messages(&self) -> Vec { + self.messages.lock().unwrap().clone() + } + + fn clear(&self) { + self.messages.lock().unwrap().clear(); + } +} + +impl Subscriber for TestSubscriber { + fn enabled(&self, _metadata: &Metadata<'_>) -> bool { + true + } + + fn event(&self, event: &Event<'_>) { + let mut message = String::new(); + let metadata = event.metadata(); + + // Add level prefix + message.push_str(&format!("{}: ", metadata.level())); + + // Capture the message field + let mut visitor = MessageVisitor { message: &mut message }; + event.record(&mut visitor); + + self.messages.lock().unwrap().push(message); + } + + fn enter(&self, _span: &Id) {} + fn exit(&self, _span: &Id) {} + + fn new_span(&self, _span: &Attributes<'_>) -> Id { + Id::from_u64(0) + } + + fn record(&self, _span: &Id, _values: &Record<'_>) {} + + fn record_follows_from(&self, _span: &Id, _follows: &Id) {} +}