From daa53e516849379cfba3fffc2bf5fad24e44934d Mon Sep 17 00:00:00 2001 From: Luna Yao <40349250+ZnqbuZ@users.noreply.github.com> Date: Sun, 12 Apr 2026 07:04:21 +0200 Subject: [PATCH] log: auto-init log for tests (#2073) --- easytier/Cargo.toml | 1 + easytier/src/common/log.rs | 306 ++++++++++++++++++----------- easytier/src/gateway/quic_proxy.rs | 6 - easytier/src/tests/mod.rs | 17 -- easytier/src/tunnel/common.rs | 12 -- 5 files changed, 197 insertions(+), 145 deletions(-) diff --git a/easytier/Cargo.toml b/easytier/Cargo.toml index b7e53f6f..4d254fbd 100644 --- a/easytier/Cargo.toml +++ b/easytier/Cargo.toml @@ -347,6 +347,7 @@ rstest = "0.25.0" futures-util = "0.3.31" maplit = "1.0.2" tempfile = "3.22.0" +ctor = "0.8.0" [target.'cfg(target_os = "linux")'.dev-dependencies] defguard_wireguard_rs = "0.4.2" diff --git a/easytier/src/common/log.rs b/easytier/src/common/log.rs index 9dad049a..19eccc03 100644 --- a/easytier/src/common/log.rs +++ b/easytier/src/common/log.rs @@ -1,16 +1,18 @@ use std::io::IsTerminal as _; -use crate::common::config::LoggingConfigLoader; +use crate::common::config::{FileLoggerConfig, LoggingConfigLoader}; use crate::common::get_logger_timer_rfc3339; use crate::common::tracing_rolling_appender::{FileAppenderWrapper, RollingFileAppenderBase}; use crate::rpc_service::logger::{CURRENT_LOG_LEVEL, LOGGER_LEVEL_SENDER}; use anyhow::Context; +use cfg_if::cfg_if; use paste::paste; use regex::Regex; use tracing::level_filters::LevelFilter; use tracing::{Level, Metadata}; use tracing_subscriber::Registry; use tracing_subscriber::filter::{FilterExt, filter_fn}; +use tracing_subscriber::fmt::format::FmtSpan; use tracing_subscriber::fmt::layer; use tracing_subscriber::layer::SubscriberExt; use tracing_subscriber::util::SubscriberInitExt; @@ -86,127 +88,70 @@ macro_rules! log_layer { pub fn init( config: impl LoggingConfigLoader, - need_reload: bool, + reload: bool, ) -> Result, anyhow::Error> { let mut layers = Vec::new(); - let file_config = config.get_file_logger_config(); - let file_level = file_config - .level - .map(|s| s.parse().unwrap()) - .unwrap_or(LevelFilter::OFF); + let console_layers = console_layers( + config + .get_console_logger_config() + .level + .map(|s| s.parse().unwrap()) + .unwrap_or(LevelFilter::OFF), + )?; + layers.extend(console_layers); - let mut ret_sender: Option = None; + let sender = if cfg!(not(test)) { + let (file_layers, sender) = file_layers(config.get_file_logger_config(), reload)?; + layers.extend(file_layers); + sender + } else { + None + }; - // logger to a rolling file - if file_level != LevelFilter::OFF || need_reload { - let dir = file_config.dir.as_deref().unwrap_or("."); - let file = file_config.file.as_deref().unwrap_or("easytier.log"); - let path = std::path::Path::new(dir).join(file); - let path_str = path.to_string_lossy().into_owned(); + Registry::default() + .with(layers) + .try_init() + .map(|_| sender) + .map_err(Into::into) +} - let builder = RollingFileAppenderBase::builder(); - let file_appender = builder - .filename(path_str) - .condition_daily() - .max_filecount(file_config.count.unwrap_or(10)) - .condition_max_file_size(file_config.size_mb.unwrap_or(100) * 1024 * 1024) - .build() - .unwrap(); +type BoxLayer = Box + Send + Sync>; - // Create a simple wrapper that implements MakeWriter - let wrapper = FileAppenderWrapper::new(file_appender); +fn console_layers(default_level: LevelFilter) -> anyhow::Result> { + let mut layers = Vec::new(); + if default_level == LevelFilter::OFF { + return Ok(layers); + } - let (file_filter, file_filter_reloader) = - tracing_subscriber::reload::Layer::<_, Registry>::new(parse_env_filter(file_level)?); + let (console_filter, _) = + tracing_subscriber::reload::Layer::new(parse_env_filter(default_level)?); - let layer = |wrapper| { - layer() - .with_ansi(false) - .with_writer(wrapper) - .with_timer(get_logger_timer_rfc3339()) - }; - - layers.push( - vec![ - tracing_layer!(layer(wrapper.clone())), - log_layer!(layer(wrapper.clone())), - ] - .with_filter(file_filter) - .boxed(), - ); - - if need_reload { - let (sender, recver) = std::sync::mpsc::channel(); - ret_sender = Some(sender.clone()); - - // 初始化全局状态 - let _ = LOGGER_LEVEL_SENDER.set(std::sync::Mutex::new(sender)); - let _ = CURRENT_LOG_LEVEL.set(std::sync::Mutex::new(file_level.to_string())); - - std::thread::spawn(move || { - while let Ok(lf) = recver.recv() { - let parsed_level = match lf.parse::() { - Ok(level) => level, - Err(e) => { - error!("Failed to parse new log level {:?}: {}", lf, e); - continue; - } - }; - - let mut new_filter = match EnvFilter::builder() - .with_default_directive(parsed_level.into()) - .from_env() - .with_context(|| "failed to create file filter") - { - Ok(filter) => Some(filter), - Err(e) => { - error!("Failed to build new log filter for {:?}: {:?}", lf, e); - continue; - } - }; - - match file_filter_reloader.modify(|f| { - *f = new_filter - .take() - .expect("log filter reloader only applies one filter per reload"); - }) { - Ok(()) => { - info!("Reload log filter succeed, new filter level: {:?}", lf); - } - Err(e) => { - error!("Failed to reload log filter: {:?}", e); - } - } - } - info!("Stop log filter reloader"); - }); + cfg_if! { + if #[cfg(test)] { + let w = tracing_subscriber::fmt::TestWriter::new; + let (stdout, stderr) = (w, w); + } else { + let (stdout, stderr) = (std::io::stdout, std::io::stderr); } } - // logger to console - let console_config = config.get_console_logger_config(); - let console_level = console_config - .level - .map(|s| s.parse().unwrap()) - .unwrap_or(LevelFilter::OFF); - - let (console_filter, _) = - tracing_subscriber::reload::Layer::new(parse_env_filter(console_level)?); + let ansi = std::io::stderr().is_terminal() || cfg!(test); let layer = || { layer() .compact() - .with_ansi(std::io::stderr().is_terminal()) .with_timer(get_logger_timer_rfc3339()) - .with_writer(std::io::stderr) + .with_ansi(ansi) + .with_span_events(FmtSpan::NEW | FmtSpan::CLOSE) + .with_writer(stderr) }; layers.push( vec![ tracing_layer!(layer()), log_layer!(layer()).with_filter(LevelFilter::WARN).boxed(), - log_layer!(layer().with_writer(std::io::stdout)) + log_layer!(layer().with_writer(stdout)) .with_filter(filter_fn(|metadata| *metadata.level() > Level::WARN)) .boxed(), ] @@ -219,23 +164,164 @@ pub fn init( layers.push(console_subscriber::ConsoleLayer::builder().spawn().boxed()); } - Registry::default().with(layers).init(); + Ok(layers) +} - Ok(ret_sender) +fn file_layers( + config: FileLoggerConfig, + reload: bool, +) -> anyhow::Result<(Vec, Option)> { + let mut layers = Vec::new(); + + let level = config + .level + .map(|s| s.parse().unwrap()) + .unwrap_or(LevelFilter::OFF); + + if level == LevelFilter::OFF && !reload { + return Ok((layers, None)); + } + + let path = { + let dir = config.dir.as_deref().unwrap_or("."); + let file = config.file.as_deref().unwrap_or("easytier.log"); + let path = std::path::Path::new(dir).join(file); + path.to_string_lossy().into_owned() + }; + + let builder = RollingFileAppenderBase::builder(); + let file_appender = builder + .filename(path) + .condition_daily() + .max_filecount(config.count.unwrap_or(10)) + .condition_max_file_size(config.size_mb.unwrap_or(100) * 1024 * 1024) + .build() + .unwrap(); + + // Create a simple wrapper that implements MakeWriter + let wrapper = FileAppenderWrapper::new(file_appender); + + let (file_filter, file_filter_reloader) = + tracing_subscriber::reload::Layer::<_, Registry>::new(parse_env_filter(level)?); + + let layer = |wrapper| { + layer() + .with_ansi(false) + .with_writer(wrapper) + .with_timer(get_logger_timer_rfc3339()) + }; + + layers.push( + vec![ + tracing_layer!(layer(wrapper.clone())), + log_layer!(layer(wrapper.clone())), + ] + .with_filter(file_filter) + .boxed(), + ); + + if !reload { + return Ok((layers, None)); + } + + let (tx, rx) = std::sync::mpsc::channel(); + + // 初始化全局状态 + let _ = LOGGER_LEVEL_SENDER.set(std::sync::Mutex::new(tx.clone())); + let _ = CURRENT_LOG_LEVEL.set(std::sync::Mutex::new(level.to_string())); + + std::thread::spawn(move || { + while let Ok(lf) = rx.recv() { + let parsed_level = match lf.parse::() { + Ok(level) => level, + Err(e) => { + error!("Failed to parse new log level {:?}: {}", lf, e); + continue; + } + }; + + let mut new_filter = match EnvFilter::builder() + .with_default_directive(parsed_level.into()) + .from_env() + .with_context(|| "failed to create file filter") + { + Ok(filter) => Some(filter), + Err(e) => { + error!("Failed to build new log filter for {:?}: {:?}", lf, e); + continue; + } + }; + + match file_filter_reloader.modify(|f| { + *f = new_filter + .take() + .expect("log filter reloader only applies one filter per reload"); + }) { + Ok(()) => { + info!("Reload log filter succeed, new filter level: {:?}", lf); + } + Err(e) => { + error!("Failed to reload log filter: {:?}", e); + } + } + } + info!("Stop log filter reloader"); + }); + + Ok((layers, Some(tx))) } #[cfg(test)] mod tests { use super::*; - use crate::common::config::{self}; + use crate::common::config::FileLoggerConfig; - async fn test_logger_reload() { - println!("current working dir: {:?}", std::env::current_dir()); - let config = config::LoggingConfigBuilder::default().build().unwrap(); - let s = init(&config, true).unwrap(); - tracing::debug!("test not display debug"); - s.unwrap().send(LevelFilter::DEBUG.to_string()).unwrap(); - tokio::time::sleep(tokio::time::Duration::from_secs(1)).await; - tracing::debug!("test display debug"); + #[ctor::ctor] + fn init() { + let _ = Registry::default() + .with(console_layers(LevelFilter::DEBUG).unwrap()) + .try_init(); + } + + #[test] + fn test_logger_reload() { + let temp_dir = tempfile::tempdir().unwrap(); + let log_file_name = "reload-test.log".to_string(); + let log_path = temp_dir.path().join(&log_file_name); + + let cfg = FileLoggerConfig { + level: Some(LevelFilter::INFO.to_string()), + file: Some(log_file_name), + dir: Some(temp_dir.path().to_string_lossy().to_string()), + size_mb: Some(10), + count: Some(1), + }; + + let (layers, sender) = file_layers(cfg, true).unwrap(); + let sender = sender.expect("reload=true should return a sender"); + + let before_marker = "reload-before-debug-marker"; + let after_marker = "reload-after-debug-marker"; + let subscriber = Registry::default().with(layers); + + tracing::subscriber::with_default(subscriber, || { + tracing::debug!("{}", before_marker); + + sender.send(LevelFilter::DEBUG.to_string()).unwrap(); + std::thread::sleep(std::time::Duration::from_millis(300)); + + tracing::debug!("{}", after_marker); + std::thread::sleep(std::time::Duration::from_millis(300)); + }); + + let content = std::fs::read_to_string(&log_path).unwrap_or_default(); + assert!( + !content.contains(before_marker), + "debug log should be filtered before reload" + ); + assert!( + content.contains(after_marker), + "debug log should be visible after reload" + ); } } diff --git a/easytier/src/gateway/quic_proxy.rs b/easytier/src/gateway/quic_proxy.rs index c959efc8..dfd88d95 100644 --- a/easytier/src/gateway/quic_proxy.rs +++ b/easytier/src/gateway/quic_proxy.rs @@ -965,12 +965,6 @@ mod tests { use super::*; use bytes::Buf; - fn init() { - let _ = tracing_subscriber::fmt() - .with_env_filter("debug") - .try_init(); - } - /// Helper function: Create a pair of interconnected QuicSockets. /// Data sent by socket_a will enter socket_b's rx, and vice versa. fn make_socket_pair() -> (QuicSocket, QuicSocket) { diff --git a/easytier/src/tests/mod.rs b/easytier/src/tests/mod.rs index 7f48a63b..4c983252 100644 --- a/easytier/src/tests/mod.rs +++ b/easytier/src/tests/mod.rs @@ -6,8 +6,6 @@ mod ipv6_test; #[cfg(target_os = "linux")] mod credential_tests; -use std::io::IsTerminal as _; - use crate::common::PeerId; use crate::peers::peer_manager::PeerManager; @@ -133,21 +131,6 @@ pub fn add_ns_to_bridge(br_name: &str, ns_name: &str) { .unwrap(); } -pub fn enable_log() { - let filter = tracing_subscriber::EnvFilter::builder() - .with_default_directive(tracing::level_filters::LevelFilter::TRACE.into()) - .from_env() - .unwrap() - .add_directive("tarpc=error".parse().unwrap()); - let use_ansi = std::io::stderr().is_terminal(); - tracing_subscriber::fmt::fmt() - .pretty() - .with_ansi(use_ansi) - .with_env_filter(filter) - .with_writer(std::io::stderr) - .init(); -} - fn check_route(ipv4: &str, dst_peer_id: PeerId, routes: Vec) { let mut found = false; for r in routes.iter() { diff --git a/easytier/src/tunnel/common.rs b/easytier/src/tunnel/common.rs index 92766a29..05938d58 100644 --- a/easytier/src/tunnel/common.rs +++ b/easytier/src/tunnel/common.rs @@ -691,18 +691,6 @@ pub mod tests { bps as usize } - pub fn enable_log() { - let filter = tracing_subscriber::EnvFilter::builder() - .with_default_directive(tracing::level_filters::LevelFilter::TRACE.into()) - .from_env() - .unwrap() - .add_directive("tarpc=error".parse().unwrap()); - tracing_subscriber::fmt::fmt() - .pretty() - .with_env_filter(filter) - .init(); - } - pub async fn wait_for_condition(mut condition: F, timeout: std::time::Duration) where F: FnMut() -> FRet + Send,