openzeppelin_relayer/logging/
mod.rs

1//! ## Sets up logging by reading configuration from environment variables.
2//!
3//! Environment variables used:
4//! - LOG_MODE: "stdout" (default) or "file"
5//! - LOG_LEVEL: log level ("trace", "debug", "info", "warn", "error"); default is "info"
6//! - LOG_FORMAT: output format ("compact" (default), "pretty", "json")
7//! - LOG_DATA_DIR: when using file mode, the path of the log file (default "logs/relayer.log")
8
9use chrono::Utc;
10use std::{
11    env,
12    fs::{create_dir_all, metadata, File, OpenOptions},
13    path::Path,
14};
15use tracing::{info, subscriber::Interest, Metadata};
16use tracing_appender::non_blocking;
17use tracing_error::ErrorLayer;
18use tracing_subscriber::{
19    filter::LevelFilter,
20    fmt,
21    layer::{Context, Layer},
22    prelude::*,
23    EnvFilter,
24};
25
26use crate::constants::{
27    DEFAULT_LOG_DIR, DEFAULT_LOG_FORMAT, DEFAULT_LOG_LEVEL, DEFAULT_LOG_MODE,
28    DEFAULT_MAX_LOG_FILE_SIZE, DOCKER_LOG_DIR, LOG_FILE_NAME,
29};
30
31/// Computes the path of the rolled log file given the base file path and the date string.
32pub fn compute_rolled_file_path(base_file_path: &str, date_str: &str, index: u32) -> String {
33    if base_file_path.ends_with(".log") {
34        let trimmed = base_file_path.strip_suffix(".log").unwrap();
35        format!("{trimmed}-{date_str}.{index}.log")
36    } else {
37        format!("{base_file_path}-{date_str}.{index}.log")
38    }
39}
40
41/// Generates a time-based log file name.
42/// This is simply a wrapper around `compute_rolled_file_path` for clarity.
43pub fn time_based_rolling(base_file_path: &str, date_str: &str, index: u32) -> String {
44    compute_rolled_file_path(base_file_path, date_str, index)
45}
46
47/// Checks if the given log file exceeds the maximum allowed size (in bytes).
48/// If so, it appends a sequence number to generate a new file name.
49/// Returns the final log file path to use.
50/// - `file_path`: the initial time-based log file path.
51/// - `base_file_path`: the original base log file path.
52/// - `date_str`: the current date string.
53/// - `max_size`: maximum file size in bytes (e.g., 1GB).
54pub fn space_based_rolling(
55    file_path: &str,
56    base_file_path: &str,
57    date_str: &str,
58    max_size: u64,
59) -> String {
60    let mut final_path = file_path.to_string();
61    let mut index = 1;
62    while let Ok(metadata) = metadata(&final_path) {
63        if metadata.len() > max_size {
64            final_path = compute_rolled_file_path(base_file_path, date_str, index);
65            index += 1;
66        } else {
67            break;
68        }
69    }
70    final_path
71}
72
73/// Converts a log level string to a LevelFilter.
74/// Falls back to INFO if the level string is invalid.
75fn parse_level_filter(level: &str) -> LevelFilter {
76    match level.to_lowercase().as_str() {
77        "trace" => LevelFilter::TRACE,
78        "debug" => LevelFilter::DEBUG,
79        "info" => LevelFilter::INFO,
80        "warn" => LevelFilter::WARN,
81        "error" => LevelFilter::ERROR,
82        "off" => LevelFilter::OFF,
83        _ => {
84            tracing::warn!("Invalid log level '{level}', falling back to INFO");
85            LevelFilter::INFO
86        }
87    }
88}
89
90/// Keeps span contexts enabled at all levels regardless of output log filtering.
91#[derive(Default)]
92struct SpanKeepaliveLayer;
93
94impl<S> Layer<S> for SpanKeepaliveLayer
95where
96    S: tracing::Subscriber,
97{
98    fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest {
99        if metadata.is_span() {
100            // Force-enable spans so context can be constructed even when event output is filtered.
101            Interest::always()
102        } else {
103            // Let event filtering be handled by output layers/filters.
104            Interest::sometimes()
105        }
106    }
107
108    fn enabled(&self, _metadata: &Metadata<'_>, _ctx: Context<'_, S>) -> bool {
109        // Do not suppress events here; output layers still decide via their own filters.
110        true
111    }
112}
113
114/// Builds filter directives string by combining user configuration with default suppressions
115/// for noisy crates. Only adds suppressions for crates not explicitly configured by the user.
116fn build_filter_directives() -> String {
117    const NOISY_CRATES: &[&str] = &[
118        "reqwest",
119        "hyper",
120        "rustls",
121        "h2",
122        "alloy_transport_http",
123        "aws_sdk_kms",
124        "solana_client",
125        "solana_program",
126    ];
127
128    let rust_log = env::var("RUST_LOG").unwrap_or_else(|_| DEFAULT_LOG_LEVEL.to_string());
129
130    let suppressions: Vec<String> = NOISY_CRATES
131        .iter()
132        .filter(|&crate_name| !rust_log.contains(crate_name))
133        .map(|name| format!("{name}=warn"))
134        .collect();
135
136    let mut directives = suppressions;
137    directives.push(rust_log);
138    directives.join(",")
139}
140
141fn build_env_filter(default_level: LevelFilter, directives: &str) -> EnvFilter {
142    EnvFilter::builder()
143        .with_default_directive(default_level.into())
144        .parse_lossy(directives)
145}
146
147/// Sets up logging by reading configuration from environment variables.
148pub fn setup_logging() {
149    // Set RUST_LOG from LOG_LEVEL if RUST_LOG is not already set
150    if std::env::var_os("RUST_LOG").is_none() {
151        if let Ok(level) = env::var("LOG_LEVEL") {
152            std::env::set_var("RUST_LOG", level);
153        }
154    }
155
156    // Configure filter, format, and mode from environment
157    // Suppress noisy HTTP/TLS debug logs by default unless explicitly configured
158    let default_level = parse_level_filter(DEFAULT_LOG_LEVEL);
159    let filter_directives = build_filter_directives();
160
161    let format = env::var("LOG_FORMAT").unwrap_or_else(|_| DEFAULT_LOG_FORMAT.to_string());
162    let log_mode = env::var("LOG_MODE").unwrap_or_else(|_| DEFAULT_LOG_MODE.to_string());
163
164    // Set up logging based on mode
165    if log_mode.eq_ignore_ascii_case("file") {
166        // File logging setup
167        let log_dir = if env::var("IN_DOCKER").ok().as_deref() == Some("true") {
168            DOCKER_LOG_DIR.to_string()
169        } else {
170            env::var("LOG_DATA_DIR").unwrap_or_else(|_| DEFAULT_LOG_DIR.to_string())
171        };
172        let log_dir = format!("{}/", log_dir.trim_end_matches('/'));
173
174        let now = Utc::now();
175        let date_str = now.format("%Y-%m-%d").to_string();
176        let base_file_path = format!("{log_dir}{LOG_FILE_NAME}");
177
178        if let Some(parent) = Path::new(&base_file_path).parent() {
179            create_dir_all(parent).expect("Failed to create log directory");
180        }
181
182        let time_based_path = time_based_rolling(&base_file_path, &date_str, 1);
183        let max_size = match env::var("LOG_MAX_SIZE") {
184            Ok(value) => value.parse().unwrap_or_else(|_| {
185                panic!("LOG_MAX_SIZE must be a valid u64 if set");
186            }),
187            Err(_) => DEFAULT_MAX_LOG_FILE_SIZE,
188        };
189        let final_path =
190            space_based_rolling(&time_based_path, &base_file_path, &date_str, max_size);
191
192        let file = if Path::new(&final_path).exists() {
193            OpenOptions::new()
194                .append(true)
195                .open(&final_path)
196                .expect("Failed to open log file")
197        } else {
198            File::create(&final_path).expect("Failed to create log file")
199        };
200
201        let (non_blocking_writer, guard) = non_blocking(file);
202        Box::leak(Box::new(guard)); // Keep guard alive for the lifetime of the program
203
204        match format.as_str() {
205            "pretty" => {
206                tracing_subscriber::registry()
207                    .with(SpanKeepaliveLayer)
208                    .with(ErrorLayer::default())
209                    .with(
210                        fmt::layer()
211                            .with_writer(non_blocking_writer)
212                            .with_ansi(false)
213                            .pretty()
214                            .with_thread_ids(true)
215                            .with_file(true)
216                            .with_line_number(true)
217                            .with_filter(build_env_filter(default_level, &filter_directives)),
218                    )
219                    .init();
220            }
221            "json" => {
222                tracing_subscriber::registry()
223                    .with(SpanKeepaliveLayer)
224                    .with(ErrorLayer::default())
225                    .with(
226                        fmt::layer()
227                            .with_writer(non_blocking_writer)
228                            .with_ansi(false)
229                            .json()
230                            .with_current_span(true)
231                            .with_span_list(true)
232                            .with_thread_ids(true)
233                            .with_file(true)
234                            .with_line_number(true)
235                            .with_filter(build_env_filter(default_level, &filter_directives)),
236                    )
237                    .init();
238            }
239            _ => {
240                // compact is default
241                tracing_subscriber::registry()
242                    .with(SpanKeepaliveLayer)
243                    .with(ErrorLayer::default())
244                    .with(
245                        fmt::layer()
246                            .with_writer(non_blocking_writer)
247                            .with_ansi(false)
248                            .compact()
249                            .with_target(false)
250                            .with_filter(build_env_filter(default_level, &filter_directives)),
251                    )
252                    .init();
253            }
254        }
255    } else {
256        // Stdout logging
257        match format.as_str() {
258            "pretty" => {
259                tracing_subscriber::registry()
260                    .with(SpanKeepaliveLayer)
261                    .with(ErrorLayer::default())
262                    .with(
263                        fmt::layer()
264                            .pretty()
265                            .with_thread_ids(true)
266                            .with_file(true)
267                            .with_line_number(true)
268                            .with_filter(build_env_filter(default_level, &filter_directives)),
269                    )
270                    .init();
271            }
272            "json" => {
273                tracing_subscriber::registry()
274                    .with(SpanKeepaliveLayer)
275                    .with(ErrorLayer::default())
276                    .with(
277                        fmt::layer()
278                            .json()
279                            .with_current_span(true)
280                            .with_span_list(true)
281                            .with_thread_ids(true)
282                            .with_file(true)
283                            .with_line_number(true)
284                            .with_filter(build_env_filter(default_level, &filter_directives)),
285                    )
286                    .init();
287            }
288            _ => {
289                // compact is default
290                tracing_subscriber::registry()
291                    .with(SpanKeepaliveLayer)
292                    .with(ErrorLayer::default())
293                    .with(
294                        fmt::layer()
295                            .compact()
296                            .with_target(false)
297                            .with_filter(build_env_filter(default_level, &filter_directives)),
298                    )
299                    .init();
300            }
301        }
302    }
303
304    info!(mode=%log_mode, format=%format, "logging configured");
305}
306
307#[cfg(test)]
308mod tests {
309    use super::*;
310    use std::fs::File;
311    use std::io::Write;
312    use std::sync::Mutex as StdMutex;
313    use std::sync::{Arc, Mutex, Once};
314    use tempfile::tempdir;
315    use tracing_subscriber::fmt::MakeWriter;
316
317    // Use this to ensure logger is only initialized once across all tests
318    static INIT_LOGGER: Once = Once::new();
319
320    // Mutex to serialize tests that modify environment variables
321    // This prevents test interference when running in parallel
322    static ENV_MUTEX: Mutex<()> = Mutex::new(());
323
324    // Test helper infrastructure for capturing log output
325    mod test_helpers {
326        use super::*;
327
328        /// Custom writer that writes to an in-memory buffer
329        pub struct TestWriter(pub Arc<StdMutex<Vec<u8>>>);
330
331        impl std::io::Write for TestWriter {
332            fn write(&mut self, buf: &[u8]) -> std::io::Result<usize> {
333                self.0.lock().unwrap().write(buf)
334            }
335            fn flush(&mut self) -> std::io::Result<()> {
336                self.0.lock().unwrap().flush()
337            }
338        }
339
340        /// Newtype wrapper to implement MakeWriter trait
341        /// This is needed to avoid the orphan rule when implementing MakeWriter for Arc<Mutex<Vec<u8>>>
342        pub struct TestMakeWriter(pub Arc<StdMutex<Vec<u8>>>);
343
344        impl<'a> MakeWriter<'a> for TestMakeWriter {
345            type Writer = TestWriter;
346            fn make_writer(&'a self) -> Self::Writer {
347                TestWriter(self.0.clone())
348            }
349        }
350
351        /// Creates a test subscriber with the given filter that captures output to a buffer
352        /// Returns (subscriber_guard, buffer) where:
353        /// - subscriber_guard: Must be kept alive for the duration of the test
354        /// - buffer: The buffer where log output is captured
355        pub fn create_test_subscriber(
356            filter: EnvFilter,
357        ) -> (tracing::subscriber::DefaultGuard, Arc<StdMutex<Vec<u8>>>) {
358            let buffer = Arc::new(StdMutex::new(Vec::new()));
359            let buffer_clone = buffer.clone();
360
361            let subscriber = tracing_subscriber::fmt()
362                .with_env_filter(filter)
363                .with_writer(TestMakeWriter(buffer_clone))
364                .with_ansi(false)
365                .finish();
366
367            let guard = tracing::subscriber::set_default(subscriber);
368            (guard, buffer)
369        }
370
371        /// Helper to get the captured output as a String
372        pub fn get_output(buffer: &Arc<StdMutex<Vec<u8>>>) -> String {
373            String::from_utf8(buffer.lock().unwrap().clone()).unwrap()
374        }
375    }
376
377    #[test]
378    fn test_compute_rolled_file_path() {
379        // Test with .log extension
380        let result = compute_rolled_file_path("app.log", "2023-01-01", 1);
381        assert_eq!(result, "app-2023-01-01.1.log");
382
383        // Test without .log extension
384        let result = compute_rolled_file_path("app", "2023-01-01", 2);
385        assert_eq!(result, "app-2023-01-01.2.log");
386
387        // Test with path
388        let result = compute_rolled_file_path("logs/app.log", "2023-01-01", 3);
389        assert_eq!(result, "logs/app-2023-01-01.3.log");
390    }
391
392    #[test]
393    fn test_time_based_rolling() {
394        // This is just a wrapper around compute_rolled_file_path
395        let result = time_based_rolling("app.log", "2023-01-01", 1);
396        assert_eq!(result, "app-2023-01-01.1.log");
397    }
398
399    #[test]
400    fn test_space_based_rolling() {
401        // Create a temporary directory for testing
402        let temp_dir = tempdir().expect("Failed to create temp directory");
403        let base_path = temp_dir
404            .path()
405            .join("test.log")
406            .to_str()
407            .unwrap()
408            .to_string();
409
410        // Test when file doesn't exist
411        let result = space_based_rolling(&base_path, &base_path, "2023-01-01", 100);
412        assert_eq!(result, base_path);
413
414        // Create a file larger than max_size
415        {
416            let mut file = File::create(&base_path).expect("Failed to create test file");
417            file.write_all(&[0; 200])
418                .expect("Failed to write to test file");
419        }
420
421        // Test when file exists and is larger than max_size
422        let expected_path = compute_rolled_file_path(&base_path, "2023-01-01", 1);
423        let result = space_based_rolling(&base_path, &base_path, "2023-01-01", 100);
424        assert_eq!(result, expected_path);
425
426        // Create multiple files to test sequential numbering
427        {
428            let mut file = File::create(&expected_path).expect("Failed to create test file");
429            file.write_all(&[0; 200])
430                .expect("Failed to write to test file");
431        }
432
433        // Test sequential numbering
434        let expected_path2 = compute_rolled_file_path(&base_path, "2023-01-01", 2);
435        let result = space_based_rolling(&base_path, &base_path, "2023-01-01", 100);
436        assert_eq!(result, expected_path2);
437    }
438
439    #[test]
440    fn test_logging_configuration() {
441        // Lock mutex to prevent test interference
442        let _guard = ENV_MUTEX.lock().unwrap();
443
444        // We'll test both configurations in a single test to avoid multiple logger initializations
445
446        // First test stdout configuration
447        {
448            // Set environment variables for testing
449            env::set_var("LOG_MODE", "stdout");
450            env::set_var("LOG_LEVEL", "debug");
451
452            // Initialize logger only once across all tests
453            INIT_LOGGER.call_once(|| {
454                setup_logging();
455            });
456
457            // Clean up
458            env::remove_var("LOG_MODE");
459            env::remove_var("LOG_LEVEL");
460        }
461
462        // Now test file configuration without reinitializing the logger
463        {
464            // Create a temporary directory for testing
465            let temp_dir = tempdir().expect("Failed to create temp directory");
466            let log_path = temp_dir
467                .path()
468                .join("test_logs")
469                .to_str()
470                .unwrap()
471                .to_string();
472
473            // Set environment variables for testing
474            env::set_var("LOG_MODE", "file");
475            env::set_var("LOG_LEVEL", "info");
476            env::set_var("LOG_DATA_DIR", &log_path);
477            env::set_var("LOG_MAX_SIZE", "1024"); // 1KB for testing
478
479            // We don't call setup_logging() again, but we can test the directory creation logic
480            if let Some(parent) = Path::new(&format!("{log_path}/relayer.log")).parent() {
481                create_dir_all(parent).expect("Failed to create log directory");
482            }
483
484            // Verify the log directory was created
485            assert!(Path::new(&log_path).exists());
486
487            // Clean up
488            env::remove_var("LOG_MODE");
489            env::remove_var("LOG_LEVEL");
490            env::remove_var("LOG_DATA_DIR");
491            env::remove_var("LOG_MAX_SIZE");
492        }
493    }
494
495    #[test]
496    fn test_env_filter_with_no_rust_log() {
497        // Lock mutex to prevent test interference
498        let _guard = ENV_MUTEX.lock().unwrap();
499
500        // Save original RUST_LOG if it exists
501        let original_rust_log = env::var("RUST_LOG").ok();
502
503        // Remove RUST_LOG to test default behavior
504        env::remove_var("RUST_LOG");
505
506        // Create the filter that would be used by setup_logging
507        let default_level = parse_level_filter(DEFAULT_LOG_LEVEL);
508        let filter = EnvFilter::builder()
509            .with_default_directive(default_level.into())
510            .parse_lossy(build_filter_directives());
511
512        // Create test subscriber and capture buffer
513        let (_subscriber_guard, buffer) = test_helpers::create_test_subscriber(filter);
514
515        // Emit test logs
516        tracing::info!(target: "openzeppelin_relayer", "app info message");
517        tracing::debug!(target: "openzeppelin_relayer", "app debug - should be suppressed (default is info)");
518        tracing::debug!(target: "reqwest", "reqwest debug - should be suppressed");
519        tracing::warn!(target: "reqwest", "reqwest warn - should be visible");
520        tracing::debug!(target: "hyper", "hyper debug - should be suppressed");
521        tracing::warn!(target: "hyper", "hyper warn - should be visible");
522
523        // Get the captured output
524        let output = test_helpers::get_output(&buffer);
525
526        // Verify filtering worked correctly
527        // Default level is "info", so app debug logs should be suppressed
528        assert!(
529            output.contains("app info message"),
530            "App info logs should be captured (default level is info)"
531        );
532        assert!(
533            !output.contains("app debug"),
534            "App debug logs should be suppressed (default level is info)"
535        );
536
537        // HTTP/TLS crates should have debug/info suppressed, only warn+ visible
538        assert!(
539            !output.contains("reqwest debug"),
540            "Reqwest debug logs should be suppressed"
541        );
542        assert!(
543            output.contains("reqwest warn"),
544            "Reqwest warn logs should be visible"
545        );
546        assert!(
547            !output.contains("hyper debug"),
548            "Hyper debug logs should be suppressed"
549        );
550        assert!(
551            output.contains("hyper warn"),
552            "Hyper warn logs should be visible"
553        );
554
555        // Restore original RUST_LOG
556        if let Some(val) = original_rust_log {
557            env::set_var("RUST_LOG", val);
558        }
559    }
560
561    #[test]
562    fn test_env_filter_with_rust_log_set() {
563        // Lock mutex to prevent test interference
564        let _guard = ENV_MUTEX.lock().unwrap();
565
566        // Save original RUST_LOG if it exists
567        let original_rust_log = env::var("RUST_LOG").ok();
568
569        // Set RUST_LOG to info level (without HTTP/TLS crate configs)
570        env::set_var("RUST_LOG", "info");
571
572        // Create filter using the same logic as setup_logging
573        let default_level = parse_level_filter(DEFAULT_LOG_LEVEL);
574        let filter = EnvFilter::builder()
575            .with_default_directive(default_level.into())
576            .parse_lossy(build_filter_directives());
577
578        // Create test subscriber and capture buffer
579        let (_subscriber_guard, buffer) = test_helpers::create_test_subscriber(filter);
580
581        // Emit test logs
582        tracing::info!(target: "openzeppelin_relayer", "test app info");
583        tracing::debug!(target: "openzeppelin_relayer", "test app debug - should be suppressed");
584        tracing::debug!(target: "hyper", "test hyper debug - should be suppressed");
585        tracing::info!(target: "hyper", "test hyper info - should be suppressed");
586        tracing::warn!(target: "hyper", "test hyper warn - should be visible");
587
588        // Get the captured output
589        let output = test_helpers::get_output(&buffer);
590
591        // Verify filtering worked correctly
592        assert!(
593            output.contains("test app info"),
594            "App info logs should be captured (RUST_LOG=info)"
595        );
596        assert!(
597            !output.contains("test app debug"),
598            "App debug logs should be suppressed (RUST_LOG=info)"
599        );
600        assert!(
601            !output.contains("test hyper debug"),
602            "Hyper debug logs should be suppressed"
603        );
604        assert!(
605            !output.contains("test hyper info"),
606            "Hyper info logs should be suppressed (hyper=warn)"
607        );
608        assert!(
609            output.contains("test hyper warn"),
610            "Hyper warn logs should be visible"
611        );
612
613        // Restore original RUST_LOG
614        env::remove_var("RUST_LOG");
615        if let Some(val) = original_rust_log {
616            env::set_var("RUST_LOG", val);
617        }
618    }
619
620    #[test]
621    fn test_env_filter_with_explicit_reqwest_config() {
622        // Lock mutex to prevent test interference
623        let _guard = ENV_MUTEX.lock().unwrap();
624
625        // Save original RUST_LOG if it exists
626        let original_rust_log = env::var("RUST_LOG").ok();
627
628        // Set RUST_LOG with explicit reqwest=debug (user wants to see reqwest debug logs)
629        env::set_var("RUST_LOG", "info,reqwest=debug");
630
631        // Create filter using the same logic as setup_logging
632        let default_level = parse_level_filter(DEFAULT_LOG_LEVEL);
633        let filter = EnvFilter::builder()
634            .with_default_directive(default_level.into())
635            .parse_lossy(build_filter_directives());
636
637        // Create test subscriber and capture buffer
638        let (_subscriber_guard, buffer) = test_helpers::create_test_subscriber(filter);
639
640        // Emit test logs
641        tracing::debug!(target: "reqwest", "reqwest debug - user override");
642        tracing::debug!(target: "hyper", "hyper debug - should be suppressed");
643        tracing::warn!(target: "hyper", "hyper warn - should be visible");
644
645        // Get the captured output
646        let output = test_helpers::get_output(&buffer);
647
648        // Verify user's explicit reqwest=debug is honored
649        assert!(
650            output.contains("reqwest debug"),
651            "User's explicit reqwest=debug should allow debug logs"
652        );
653
654        // Verify other crates are still suppressed
655        assert!(
656            !output.contains("hyper debug"),
657            "Hyper debug logs should still be suppressed"
658        );
659        assert!(
660            output.contains("hyper warn"),
661            "Hyper warn logs should be visible"
662        );
663
664        // Restore original RUST_LOG
665        env::remove_var("RUST_LOG");
666        if let Some(val) = original_rust_log {
667            env::set_var("RUST_LOG", val);
668        }
669    }
670
671    #[test]
672    fn test_env_filter_respects_user_overrides() {
673        // Lock mutex to prevent test interference
674        let _guard = ENV_MUTEX.lock().unwrap();
675
676        // Save original RUST_LOG if it exists
677        let original_rust_log = env::var("RUST_LOG").ok();
678
679        // Set RUST_LOG with user wanting to see ALL hyper logs (even trace level)
680        env::set_var("RUST_LOG", "info,hyper=trace");
681
682        // Create filter using the same logic as setup_logging
683        let default_level = parse_level_filter(DEFAULT_LOG_LEVEL);
684        let filter = EnvFilter::builder()
685            .with_default_directive(default_level.into())
686            .parse_lossy(build_filter_directives());
687
688        // Create test subscriber and capture buffer
689        let (_subscriber_guard, buffer) = test_helpers::create_test_subscriber(filter);
690
691        // Emit test logs
692        tracing::trace!(target: "hyper", "test hyper trace - user override");
693        tracing::debug!(target: "hyper", "test hyper debug - user override");
694        tracing::debug!(target: "reqwest", "test reqwest debug - should be suppressed");
695        tracing::info!(target: "reqwest", "test reqwest info - should be suppressed");
696        tracing::warn!(target: "reqwest", "test reqwest warn - should be visible");
697
698        // Get the captured output
699        let output = test_helpers::get_output(&buffer);
700
701        // Verify user's explicit hyper=trace is honored
702        assert!(
703            output.contains("test hyper trace"),
704            "User's explicit hyper=trace should allow trace logs"
705        );
706        assert!(
707            output.contains("test hyper debug"),
708            "User's explicit hyper=trace should allow debug logs"
709        );
710
711        // Verify reqwest is still suppressed (no user override)
712        assert!(
713            !output.contains("test reqwest debug"),
714            "Reqwest debug logs should be suppressed"
715        );
716        assert!(
717            !output.contains("test reqwest info"),
718            "Reqwest info logs should be suppressed"
719        );
720        assert!(
721            output.contains("test reqwest warn"),
722            "Reqwest warn logs should be visible"
723        );
724
725        // Restore original RUST_LOG
726        env::remove_var("RUST_LOG");
727        if let Some(val) = original_rust_log {
728            env::set_var("RUST_LOG", val);
729        }
730    }
731
732    #[test]
733    fn test_env_filter_mixed_user_and_default_suppressions() {
734        // Lock mutex to prevent test interference
735        let _guard = ENV_MUTEX.lock().unwrap();
736
737        // Save original RUST_LOG if it exists
738        let original_rust_log = env::var("RUST_LOG").ok();
739
740        // User configures some crates explicitly, others should get defaults
741        env::set_var("RUST_LOG", "debug,reqwest=error,rustls=info");
742
743        // Create filter using the same logic as setup_logging
744        let default_level = parse_level_filter(DEFAULT_LOG_LEVEL);
745        let filter = EnvFilter::builder()
746            .with_default_directive(default_level.into())
747            .parse_lossy(build_filter_directives());
748
749        // Create test subscriber and capture buffer
750        let (_subscriber_guard, buffer) = test_helpers::create_test_subscriber(filter);
751
752        // Emit test logs
753        tracing::warn!(target: "reqwest", "test reqwest warn - user set error");
754        tracing::error!(target: "reqwest", "test reqwest error - should be visible");
755        tracing::debug!(target: "rustls", "test rustls debug - user set info");
756        tracing::info!(target: "rustls", "test rustls info - should be visible");
757        tracing::debug!(target: "hyper", "test hyper debug - should be suppressed");
758        tracing::info!(target: "hyper", "test hyper info - should be suppressed");
759        tracing::warn!(target: "hyper", "test hyper warn - should be visible");
760        tracing::debug!(target: "h2", "test h2 debug - should be suppressed");
761        tracing::warn!(target: "h2", "test h2 warn - should be visible");
762
763        // Get the captured output
764        let output = test_helpers::get_output(&buffer);
765
766        // Verify user's explicit reqwest=error (only errors, not warnings)
767        assert!(
768            !output.contains("test reqwest warn"),
769            "User's reqwest=error should reject warn logs"
770        );
771        assert!(
772            output.contains("test reqwest error"),
773            "User's reqwest=error should accept error logs"
774        );
775
776        // Verify user's explicit rustls=info
777        assert!(
778            !output.contains("test rustls debug"),
779            "User's rustls=info should reject debug logs"
780        );
781        assert!(
782            output.contains("test rustls info"),
783            "User's rustls=info should accept info logs"
784        );
785
786        // Verify default hyper=warn suppression (user didn't configure it)
787        assert!(
788            !output.contains("test hyper debug"),
789            "Default hyper=warn should reject debug logs"
790        );
791        assert!(
792            !output.contains("test hyper info"),
793            "Default hyper=warn should reject info logs"
794        );
795        assert!(
796            output.contains("test hyper warn"),
797            "Default hyper=warn should accept warn logs"
798        );
799
800        // Verify default h2=warn suppression
801        assert!(
802            !output.contains("test h2 debug"),
803            "Default h2=warn should reject debug logs"
804        );
805        assert!(
806            output.contains("test h2 warn"),
807            "Default h2=warn should accept warn logs"
808        );
809
810        // Restore original RUST_LOG
811        env::remove_var("RUST_LOG");
812        if let Some(val) = original_rust_log {
813            env::set_var("RUST_LOG", val);
814        }
815    }
816
817    #[test]
818    fn test_directive_parsing() {
819        // Test that all our directives can be parsed successfully
820        assert!("reqwest=warn"
821            .parse::<tracing_subscriber::filter::Directive>()
822            .is_ok());
823        assert!("hyper=warn"
824            .parse::<tracing_subscriber::filter::Directive>()
825            .is_ok());
826        assert!("rustls=warn"
827            .parse::<tracing_subscriber::filter::Directive>()
828            .is_ok());
829        assert!("h2=warn"
830            .parse::<tracing_subscriber::filter::Directive>()
831            .is_ok());
832        assert!("alloy_transport_http=warn"
833            .parse::<tracing_subscriber::filter::Directive>()
834            .is_ok());
835        assert!("aws_sdk_kms=warn"
836            .parse::<tracing_subscriber::filter::Directive>()
837            .is_ok());
838        assert!("solana_client=warn"
839            .parse::<tracing_subscriber::filter::Directive>()
840            .is_ok());
841        assert!("solana_program=warn"
842            .parse::<tracing_subscriber::filter::Directive>()
843            .is_ok());
844    }
845
846    #[test]
847    fn test_parse_level_filter() {
848        // Test all valid log levels
849        assert_eq!(parse_level_filter("trace"), LevelFilter::TRACE);
850        assert_eq!(parse_level_filter("debug"), LevelFilter::DEBUG);
851        assert_eq!(parse_level_filter("info"), LevelFilter::INFO);
852        assert_eq!(parse_level_filter("warn"), LevelFilter::WARN);
853        assert_eq!(parse_level_filter("error"), LevelFilter::ERROR);
854        assert_eq!(parse_level_filter("off"), LevelFilter::OFF);
855
856        // Test case insensitivity
857        assert_eq!(parse_level_filter("TRACE"), LevelFilter::TRACE);
858        assert_eq!(parse_level_filter("Debug"), LevelFilter::DEBUG);
859        assert_eq!(parse_level_filter("INFO"), LevelFilter::INFO);
860        assert_eq!(parse_level_filter("WaRn"), LevelFilter::WARN);
861
862        // Test invalid levels fall back to INFO
863        assert_eq!(parse_level_filter("invalid"), LevelFilter::INFO);
864        assert_eq!(parse_level_filter(""), LevelFilter::INFO);
865        assert_eq!(parse_level_filter("warning"), LevelFilter::INFO);
866    }
867
868    #[test]
869    fn test_keepalive_layer_preserves_debug_span_context_at_warn_output() {
870        let _subscriber_guard = tracing::subscriber::set_default(
871            tracing_subscriber::registry()
872                .with(SpanKeepaliveLayer)
873                .with(
874                    fmt::layer()
875                        .with_writer(std::io::sink)
876                        .with_filter(EnvFilter::new("warn")),
877                ),
878        );
879
880        let span = tracing::debug_span!("debug_ctx");
881        let _guard = span.enter();
882
883        crate::observability::request_id::set_request_id("keepalive-request-id");
884        assert_eq!(
885            crate::observability::request_id::get_request_id().as_deref(),
886            Some("keepalive-request-id")
887        );
888    }
889
890    #[test]
891    fn test_keepalive_layer_does_not_suppress_warn_events() {
892        let buffer = Arc::new(StdMutex::new(Vec::new()));
893        let subscriber = tracing_subscriber::registry()
894            .with(SpanKeepaliveLayer)
895            .with(
896                fmt::layer()
897                    .with_writer(test_helpers::TestMakeWriter(buffer.clone()))
898                    .with_ansi(false)
899                    .with_filter(EnvFilter::new("warn")),
900            );
901        let _subscriber_guard = tracing::subscriber::set_default(subscriber);
902
903        tracing::warn!(target: "openzeppelin_relayer", "keepalive warn event");
904        let output = test_helpers::get_output(&buffer);
905        assert!(
906            output.contains("keepalive warn event"),
907            "Warn event should be captured when keepalive layer is used"
908        );
909    }
910
911    #[test]
912    fn test_build_filter_directives_no_rust_log() {
913        // Lock mutex to prevent test interference
914        let _guard = ENV_MUTEX.lock().unwrap();
915
916        // Save original RUST_LOG
917        let original_rust_log = env::var("RUST_LOG").ok();
918
919        // Remove RUST_LOG to test default behavior
920        env::remove_var("RUST_LOG");
921
922        let result = build_filter_directives();
923
924        // Should contain all noisy crate suppressions
925        assert!(result.contains("reqwest=warn"));
926        assert!(result.contains("hyper=warn"));
927        assert!(result.contains("rustls=warn"));
928        assert!(result.contains("h2=warn"));
929        assert!(result.contains("alloy_transport_http=warn"));
930        assert!(result.contains("aws_sdk_kms=warn"));
931        assert!(result.contains("solana_client=warn"));
932        assert!(result.contains("solana_program=warn"));
933
934        // Should end with the default level
935        assert!(result.ends_with(DEFAULT_LOG_LEVEL));
936
937        // Restore original RUST_LOG
938        env::remove_var("RUST_LOG");
939        if let Some(val) = original_rust_log {
940            env::set_var("RUST_LOG", val);
941        }
942    }
943
944    #[test]
945    fn test_build_filter_directives_with_rust_log() {
946        // Lock mutex to prevent test interference
947        let _guard = ENV_MUTEX.lock().unwrap();
948
949        // Save original RUST_LOG
950        let original_rust_log = env::var("RUST_LOG").ok();
951
952        // Set RUST_LOG to a custom value
953        env::set_var("RUST_LOG", "debug");
954
955        let result = build_filter_directives();
956
957        // Should contain all noisy crate suppressions
958        assert!(result.contains("reqwest=warn"));
959        assert!(result.contains("hyper=warn"));
960
961        // Should end with the user's RUST_LOG value
962        assert!(result.ends_with("debug"));
963
964        // Restore original RUST_LOG
965        env::remove_var("RUST_LOG");
966        if let Some(val) = original_rust_log {
967            env::set_var("RUST_LOG", val);
968        }
969    }
970
971    #[test]
972    fn test_build_filter_directives_respects_user_overrides() {
973        // Lock mutex to prevent test interference
974        let _guard = ENV_MUTEX.lock().unwrap();
975
976        // Save original RUST_LOG
977        let original_rust_log = env::var("RUST_LOG").ok();
978
979        // Set RUST_LOG with explicit reqwest configuration
980        env::set_var("RUST_LOG", "info,reqwest=debug");
981
982        let result = build_filter_directives();
983
984        // Should NOT contain reqwest=warn since user configured it
985        assert!(
986            !result.contains("reqwest=warn"),
987            "Should not add reqwest=warn when user configured reqwest. Result: {result}"
988        );
989
990        // Should still contain other suppressions
991        assert!(result.contains("hyper=warn"));
992        assert!(result.contains("rustls=warn"));
993
994        // Should contain the user's RUST_LOG value
995        assert!(result.contains("info,reqwest=debug"));
996
997        // Restore original RUST_LOG
998        env::remove_var("RUST_LOG");
999        if let Some(val) = original_rust_log {
1000            env::set_var("RUST_LOG", val);
1001        }
1002    }
1003
1004    #[test]
1005    fn test_build_filter_directives_multiple_user_overrides() {
1006        // Lock mutex to prevent test interference
1007        let _guard = ENV_MUTEX.lock().unwrap();
1008
1009        // Save original RUST_LOG
1010        let original_rust_log = env::var("RUST_LOG").ok();
1011
1012        // Set RUST_LOG with multiple explicit configurations
1013        env::set_var("RUST_LOG", "debug,reqwest=error,hyper=trace,rustls=info");
1014
1015        let result = build_filter_directives();
1016
1017        // Should NOT contain suppressions for user-configured crates
1018        assert!(
1019            !result.contains("reqwest=warn"),
1020            "Should not add reqwest=warn when user configured it"
1021        );
1022        assert!(
1023            !result.contains("hyper=warn"),
1024            "Should not add hyper=warn when user configured it"
1025        );
1026        assert!(
1027            !result.contains("rustls=warn"),
1028            "Should not add rustls=warn when user configured it"
1029        );
1030
1031        // Should still contain suppressions for non-configured crates
1032        assert!(result.contains("h2=warn"));
1033        assert!(result.contains("alloy_transport_http=warn"));
1034        assert!(result.contains("aws_sdk_kms=warn"));
1035        assert!(result.contains("solana_client=warn"));
1036        assert!(result.contains("solana_program=warn"));
1037
1038        // Should contain the user's RUST_LOG value
1039        assert!(result.contains("debug,reqwest=error,hyper=trace,rustls=info"));
1040
1041        // Restore original RUST_LOG
1042        env::remove_var("RUST_LOG");
1043        if let Some(val) = original_rust_log {
1044            env::set_var("RUST_LOG", val);
1045        }
1046    }
1047
1048    #[test]
1049    fn test_build_filter_directives_format() {
1050        // Lock mutex to prevent test interference
1051        let _guard = ENV_MUTEX.lock().unwrap();
1052
1053        // Save original RUST_LOG
1054        let original_rust_log = env::var("RUST_LOG").ok();
1055
1056        // Remove RUST_LOG
1057        env::remove_var("RUST_LOG");
1058
1059        let result = build_filter_directives();
1060
1061        // Should be a valid comma-separated list
1062        let parts: Vec<&str> = result.split(',').collect();
1063        assert!(
1064            parts.len() >= 8,
1065            "Should have at least 8 parts (suppressions)"
1066        );
1067
1068        // Should not have empty parts
1069        for part in &parts {
1070            assert!(!part.is_empty(), "Should not have empty parts");
1071        }
1072
1073        // Should not start or end with comma
1074        assert!(!result.starts_with(','));
1075        assert!(!result.ends_with(','));
1076
1077        // Restore original RUST_LOG
1078        env::remove_var("RUST_LOG");
1079        if let Some(val) = original_rust_log {
1080            env::set_var("RUST_LOG", val);
1081        }
1082    }
1083}
openzeppelin_relayer/logging/mod.rs

openzeppelin_relayer/logging/
mod.rs
