From 5f31583a84cca6975ffd5735247fba87065dd028 Mon Sep 17 00:00:00 2001 From: Luna Yao <40349250+ZnqbuZ@users.noreply.github.com> Date: Wed, 4 Mar 2026 02:52:23 +0100 Subject: [PATCH] =?UTF-8?q?refactor:=20=E4=BD=BF=E7=94=A8=20tracing=20?= =?UTF-8?q?=E8=BE=93=E5=87=BA=E6=97=A5=E5=BF=97=20(#1856)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * change all println to tracing --- Cargo.lock | 11 + easytier-contrib/easytier-ohrs/Cargo.lock | 11 + easytier-contrib/easytier-uptime/src/main.rs | 4 +- easytier-gui/src-tauri/src/lib.rs | 7 +- easytier-web/src/main.rs | 5 +- easytier/Cargo.toml | 3 + easytier/src/common/log.rs | 219 ++++++++++++++++++ easytier/src/common/mod.rs | 1 + .../common/tracing_rolling_appender/mod.rs | 2 + easytier/src/connector/dns_connector.rs | 3 +- easytier/src/core.rs | 67 +++--- easytier/src/gateway/tcp_proxy.rs | 8 +- easytier/src/instance/virtual_nic.rs | 90 +++---- easytier/src/instance_manager.rs | 209 ++++++++--------- easytier/src/peers/encrypt/mod.rs | 7 +- easytier/src/service_manager/mod.rs | 8 +- easytier/src/utils.rs | 203 +++------------- easytier/src/web_client/mod.rs | 14 +- 18 files changed, 488 insertions(+), 384 deletions(-) create mode 100644 easytier/src/common/log.rs diff --git a/Cargo.lock b/Cargo.lock index fde69166..b27a6825 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2207,6 +2207,7 @@ dependencies = [ "humansize", "humantime-serde", "idna 1.0.3", + "indoc", "kcp-sys", "machine-uid", "maplit", @@ -2222,6 +2223,7 @@ dependencies = [ "openssl", "ordered_hash_map", "parking_lot", + "paste", "percent-encoding", "petgraph 0.8.1", "pin-project-lite", @@ -4163,6 +4165,15 @@ dependencies = [ "serde", ] +[[package]] +name = "indoc" +version = "2.0.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "79cf5c93f93228cf8efb3ba362535fb11199ac548a09ce117c9b1adc3030d706" +dependencies = [ + "rustversion", +] + [[package]] name = "infer" version = "0.19.0" diff --git a/easytier-contrib/easytier-ohrs/Cargo.lock b/easytier-contrib/easytier-ohrs/Cargo.lock index d8ba3bde..7976151f 100644 --- a/easytier-contrib/easytier-ohrs/Cargo.lock +++ b/easytier-contrib/easytier-ohrs/Cargo.lock @@ -1130,6 +1130,7 @@ dependencies = [ "humansize", "humantime-serde", "idna", + "indoc", "kcp-sys", "machine-uid", "multimap", @@ -1142,6 +1143,7 @@ dependencies = [ "once_cell", "ordered_hash_map", "parking_lot", + "paste", "percent-encoding", "petgraph 0.8.2", "pin-project-lite", @@ -2197,6 +2199,15 @@ dependencies = [ "hashbrown 0.16.0", ] +[[package]] +name = "indoc" +version = "2.0.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "79cf5c93f93228cf8efb3ba362535fb11199ac548a09ce117c9b1adc3030d706" +dependencies = [ + "rustversion", +] + [[package]] name = "inout" version = "0.1.4" diff --git a/easytier-contrib/easytier-uptime/src/main.rs b/easytier-contrib/easytier-uptime/src/main.rs index b1767dc8..34749641 100644 --- a/easytier-contrib/easytier-uptime/src/main.rs +++ b/easytier-contrib/easytier-uptime/src/main.rs @@ -11,7 +11,7 @@ use api::routes::create_routes; use clap::Parser; use config::AppConfig; use db::{operations::NodeOperations, Db}; -use easytier::utils::init_logger; +use easytier::common::log; use health_checker::HealthChecker; use health_checker_manager::HealthCheckerManager; use std::env; @@ -42,7 +42,7 @@ async fn main() -> anyhow::Result<()> { let config = AppConfig::default(); // 初始化日志 - let _ = init_logger(&config.logging, false); + let _ = log::init(&config.logging, false); // 解析命令行参数 let args = Args::parse(); diff --git a/easytier-gui/src-tauri/src/lib.rs b/easytier-gui/src-tauri/src/lib.rs index 24f093d2..354bce90 100644 --- a/easytier-gui/src-tauri/src/lib.rs +++ b/easytier-gui/src-tauri/src/lib.rs @@ -14,7 +14,10 @@ use easytier::rpc_service::remote_client::{ }; use easytier::web_client::{self, WebClient}; use easytier::{ - common::config::{ConfigLoader, FileLoggerConfig, LoggingConfigBuilder, TomlConfigLoader}, + common::{ + config::{ConfigLoader, FileLoggerConfig, LoggingConfigBuilder, TomlConfigLoader}, + log, + }, instance_manager::NetworkInstanceManager, launcher::NetworkConfig, rpc_service::ApiRpcServer, @@ -1119,7 +1122,7 @@ pub fn run_gui() -> std::process::ExitCode { }) .build() .map_err(|e| e.to_string())?; - let Ok(_) = utils::init_logger(&config, true) else { + let Ok(_) = log::init(&config, true) else { return Ok(()); }; diff --git a/easytier-web/src/main.rs b/easytier-web/src/main.rs index 0c2eb67e..31666883 100644 --- a/easytier-web/src/main.rs +++ b/easytier-web/src/main.rs @@ -13,10 +13,11 @@ use easytier::{ config::{ConsoleLoggerConfig, FileLoggerConfig, LoggingConfigLoader}, constants::EASYTIER_VERSION, error::Error, + log, network::{local_ipv4, local_ipv6}, }, tunnel::{tcp::TcpTunnelListener, udp::UdpTunnelListener, TunnelListener}, - utils::{init_logger, setup_panic_handler}, + utils::setup_panic_handler, }; use mimalloc::MiMalloc; @@ -205,7 +206,7 @@ async fn main() { setup_panic_handler(); let cli = Cli::parse(); - init_logger(&cli, false).unwrap(); + log::init(&cli, false).unwrap(); // Validate OIDC configuration: check split-deploy specific requirements // Basic OIDC parameter validation is handled in OidcConfig::from_params diff --git a/easytier/Cargo.toml b/easytier/Cargo.toml index ba80ebf2..0fc57154 100644 --- a/easytier/Cargo.toml +++ b/easytier/Cargo.toml @@ -39,6 +39,9 @@ tracing-subscriber = { version = "0.3", features = [ derivative = "2.2.0" derive_more = {version = "2.1.1", features = ["full"]} console-subscriber = { version = "0.4.1", optional = true } +indoc = "2.0.7" +regex = "1.8" +paste = "1.0" thiserror = "1.0" auto_impl = "1.1.0" crossbeam = "0.8.4" diff --git a/easytier/src/common/log.rs b/easytier/src/common/log.rs new file mode 100644 index 00000000..a9e4d205 --- /dev/null +++ b/easytier/src/common/log.rs @@ -0,0 +1,219 @@ +use crate::common::config::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 paste::paste; +use regex::Regex; +use tracing::level_filters::LevelFilter; +use tracing::{Level, Metadata}; +use tracing_subscriber::filter::{filter_fn, FilterExt}; +use tracing_subscriber::fmt::layer; +use tracing_subscriber::layer::SubscriberExt; +use tracing_subscriber::util::SubscriberInitExt; +use tracing_subscriber::Registry; +use tracing_subscriber::{EnvFilter, Layer}; + +macro_rules! __log__ { + (const $var:ident = $target:expr) => { + const $var: &'static str = $target; + __log__!(@impl $target, $); + }; + + (@impl $target:expr, $_:tt) => { + __log__!(@impl $_, $target, error, warn, info, debug, trace); + }; + + (@impl $_:tt, $target:expr, $($lvl:ident),+) => { + paste! { + $( + macro_rules! [< __ $lvl __ >] { + (category: $cat:expr, $_ ($arg:tt)+) => { + tracing::$lvl!(target: concat!($target, "::", $cat), $_ ($arg)+) + }; + ($_ ($arg:tt)+) => { + tracing::$lvl!(target: $target, $_ ($arg)+) + }; + } + + #[allow(unused_imports)] + pub(crate) use [< __ $lvl __ >] as $lvl; + )+ + } + }; +} + +__log__!(const LOG_TARGET = "CORE"); + +fn parse_env_filter(default_level: LevelFilter) -> Result { + let mut filter = EnvFilter::builder() + .with_default_directive(default_level.into()) + .from_env() + .with_context(|| "failed to create env filter")?; + + let pattern = Regex::new(&format!(r"(^|,){}\s*=", regex::escape(LOG_TARGET)))?; + if !pattern.is_match(&filter.to_string()) { + filter = filter.add_directive(format!("{LOG_TARGET}=info").parse()?); + } + + Ok(filter) +} + +fn is_log(meta: &Metadata) -> bool { + meta.target() == LOG_TARGET || meta.target().starts_with(&format!("{LOG_TARGET}::")) +} + +pub type NewFilterSender = std::sync::mpsc::Sender; + +macro_rules! tracing_layer { + ($layer:expr) => { + $layer.with_filter(filter_fn(is_log).not()).boxed() + }; +} + +macro_rules! log_layer { + ($layer:expr) => { + $layer + .with_file(false) + .with_line_number(false) + .with_ansi(true) + .with_filter(filter_fn(is_log)) + .boxed() + }; +} + +pub fn init( + config: impl LoggingConfigLoader, + need_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 mut ret_sender: Option = 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(); + + 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(); + + // 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(file_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 e = file_filter_reloader.modify(|f| { + if let Ok(nf) = EnvFilter::builder() + .with_default_directive(lf.parse::().unwrap().into()) + .from_env() + .with_context(|| "failed to create file filter") + { + info!("Reload log filter succeed, new filter level: {:?}", lf); + *f = nf; + } + }); + if e.is_err() { + error!("Failed to reload log filter: {:?}", e); + } + } + info!("Stop log filter reloader"); + }); + } + } + + // 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 layer = || { + layer() + .pretty() + .with_timer(get_logger_timer_rfc3339()) + .with_writer(std::io::stderr) + }; + + layers.push( + vec![ + tracing_layer!(layer()), + log_layer!(layer()).with_filter(LevelFilter::WARN).boxed(), + log_layer!(layer().with_writer(std::io::stdout)) + .with_filter(filter_fn(|metadata| *metadata.level() > Level::WARN)) + .boxed(), + ] + .with_filter(console_filter) + .boxed(), + ); + + #[cfg(feature = "tracing")] + { + layers.push(console_subscriber::ConsoleLayer::builder().spawn().boxed()); + } + + Registry::default().with(layers).init(); + + Ok(ret_sender) +} + +#[cfg(test)] +mod tests { + use super::*; + use crate::common::config::{self}; + + 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"); + } +} diff --git a/easytier/src/common/mod.rs b/easytier/src/common/mod.rs index 8f7fbd2e..73be1ba1 100644 --- a/easytier/src/common/mod.rs +++ b/easytier/src/common/mod.rs @@ -21,6 +21,7 @@ pub mod error; pub mod global_ctx; pub mod idn; pub mod ifcfg; +pub mod log; pub mod netns; pub mod network; pub mod scoped_task; diff --git a/easytier/src/common/tracing_rolling_appender/mod.rs b/easytier/src/common/tracing_rolling_appender/mod.rs index 5520891d..bf674d3b 100644 --- a/easytier/src/common/tracing_rolling_appender/mod.rs +++ b/easytier/src/common/tracing_rolling_appender/mod.rs @@ -184,6 +184,7 @@ where } } +#[derive(Debug, Clone)] pub struct FileAppenderWrapper { appender: std::sync::Arc>, } @@ -206,6 +207,7 @@ impl FileAppenderWrapper { } } +#[derive(Debug, Clone)] pub struct FileAppenderWriter { appender: std::sync::Arc>, } diff --git a/easytier/src/connector/dns_connector.rs b/easytier/src/connector/dns_connector.rs index 6a7f8051..4bbc04ae 100644 --- a/easytier/src/connector/dns_connector.rs +++ b/easytier/src/connector/dns_connector.rs @@ -5,6 +5,7 @@ use crate::{ dns::{resolve_txt_record, RESOLVER}, error::Error, global_ctx::ArcGlobalCtx, + log, }, tunnel::{IpVersion, Tunnel, TunnelConnector, TunnelError, PROTO_PORT_OFFSET}, }; @@ -131,7 +132,7 @@ impl DNSTunnelConnector { let parsed_record = Self::handle_one_srv_record(record, protocol); tracing::info!(?parsed_record, ?srv_domain, "parsed_record"); if let Err(e) = &parsed_record { - eprintln!("got invalid srv record {:?}", e); + log::warn!("got invalid srv record {:?}", e); continue; } responses.insert(parsed_record.unwrap()); diff --git a/easytier/src/core.rs b/easytier/src/core.rs index fc11b7e0..488348bc 100644 --- a/easytier/src/core.rs +++ b/easytier/src/core.rs @@ -15,6 +15,7 @@ use crate::{ PeerConfig, PortForwardConfig, TomlConfigLoader, VpnPortalConfig, }, constants::EASYTIER_VERSION, + log, }, defer, instance_manager::NetworkInstanceManager, @@ -22,7 +23,7 @@ use crate::{ proto::common::{CompressionAlgoPb, SecureModeConfig}, rpc_service::ApiRpcServer, tunnel::PROTO_PORT_OFFSET, - utils::{init_logger, setup_panic_handler}, + utils::setup_panic_handler, web_client, ShellType, }; use anyhow::Context; @@ -1163,7 +1164,7 @@ fn win_service_event_loop( } Err(e) => { status_handle.set_service_status(error_status).unwrap(); - eprintln!("error: {}", e); + log::error!("{}", e); } } }, @@ -1231,7 +1232,7 @@ fn win_service_main(arg: Vec) { async fn run_main(cli: Cli) -> anyhow::Result<()> { defer!(dump_profile(0);); - init_logger(&cli.logging_options, true)?; + log::init(&cli.logging_options, true)?; let manager = Arc::new(NetworkInstanceManager::new().with_config_path(cli.config_dir.clone())); @@ -1253,12 +1254,12 @@ async fn run_main(cli: Cli) -> anyhow::Result<()> { ) .await .inspect(|_| { - println!( - "Web client started successfully...\nserver: {}", - config_server_url_s, + log::info!( + server = config_server_url_s, + "Web client started successfully...", ); - println!("Official config website: https://easytier.cn/web"); + log::info!("Official config website: https://easytier.cn/web"); })?; Some(wc) @@ -1324,13 +1325,17 @@ async fn run_main(cli: Cli) -> anyhow::Result<()> { control.set_no_delete(true); } - println!( - "Starting easytier from config file {:?}({:?}) with config:", - config_file, control.permission + log::info!( + "\ + Starting easytier from config file {:?}({:?}) with config:\n\ + ############### TOML ###############\n\ + {}\n\ + -----------------------------------\n\ + ", + config_file, + control.permission, + cfg.dump() ); - println!("############### TOML ###############\n"); - println!("{}", cfg.dump()); - println!("-----------------------------------"); manager.run_network_instance(cfg, true, control)?; } @@ -1339,10 +1344,15 @@ async fn run_main(cli: Cli) -> anyhow::Result<()> { cli.network_options .merge_into(&cfg) .with_context(|| "failed to create config from cli".to_string())?; - println!("Starting easytier from cli with config:"); - println!("############### TOML ###############\n"); - println!("{}", cfg.dump()); - println!("-----------------------------------"); + log::info!( + "\ + Starting easytier from cli with config:\n\ + ############### TOML ###############\n\ + {}\n\ + -----------------------------------\n\ + ", + cfg.dump() + ); manager.run_network_instance(cfg, true, ConfigFileControl::STATIC_CONFIG)?; } @@ -1363,11 +1373,11 @@ async fn run_main(cli: Cli) -> anyhow::Result<()> { } } _ = tokio::signal::ctrl_c() => { - println!("ctrl-c received, exiting..."); + log::info!("ctrl-c received, exiting..."); } _ = sigterm, if cfg!(unix) => { - println!("terminate signal received, exiting..."); + log::warn!("terminate signal received, exiting..."); } } Ok(()) @@ -1384,11 +1394,7 @@ fn memory_monitor(_force_dump: Arc) { e.advance().unwrap(); let new_heap_size = allocated_stats.read().unwrap(); - println!( - "heap size: {} bytes, time: {}", - new_heap_size, - chrono::Local::now().format("%Y-%m-%d %H:%M:%S") - ); + log::debug!("heap size: {} bytes", new_heap_size); // dump every 75MB if (last_peak_size > 0 @@ -1396,10 +1402,9 @@ fn memory_monitor(_force_dump: Arc) { && new_heap_size - last_peak_size > 10 * 1024 * 1024) || _force_dump.load(std::sync::atomic::Ordering::Relaxed) { - println!( - "heap size increased: {} bytes, time: {}", + log::debug!( + "heap size increased: {} bytes", new_heap_size - last_peak_size, - chrono::Local::now().format("%Y-%m-%d %H:%M:%S") ); dump_profile(new_heap_size); last_peak_size = new_heap_size; @@ -1475,7 +1480,7 @@ pub async fn main() -> ExitCode { // Verify configurations if cli.check_config { if let Err(e) = validate_config(&cli).await { - eprintln!("Config validation failed: {:?}", e); + log::error!("Config validation failed: {:?}", e); return ExitCode::FAILURE; } else { return ExitCode::SUCCESS; @@ -1484,12 +1489,12 @@ pub async fn main() -> ExitCode { let mut ret_code = 0; - if let Err(e) = run_main(cli).await { - eprintln!("error: {:?}", e); + if let Err(error) = run_main(cli).await { + log::error!(%error); ret_code = 1; } - println!("Stopping easytier..."); + log::info!("Stopping easytier..."); set_prof_active(false); ExitCode::from(ret_code) diff --git a/easytier/src/gateway/tcp_proxy.rs b/easytier/src/gateway/tcp_proxy.rs index 72c480ba..fffe4733 100644 --- a/easytier/src/gateway/tcp_proxy.rs +++ b/easytier/src/gateway/tcp_proxy.rs @@ -23,7 +23,7 @@ use tracing::Instrument; use crate::common::error::Result; use crate::common::global_ctx::{ArcGlobalCtx, GlobalCtx}; use crate::common::join_joinset_background; - +use crate::common::log; use crate::common::stats_manager::{LabelSet, LabelType, MetricName}; use crate::peers::peer_manager::PeerManager; use crate::peers::{NicPacketFilter, PeerPacketFilter}; @@ -66,9 +66,9 @@ impl NatDstConnector for NatDstTcpConnector { async fn connect(&self, _src: SocketAddr, nat_dst: SocketAddr) -> Result { let socket = match TcpSocket::new_v4() { Ok(s) => s, - Err(e) => { - eprintln!("create v4 socket failed: {:?}", e); - return Err(e.into()); + Err(error) => { + log::error!(%error, "create v4 socket failed"); + return Err(error.into()); } }; diff --git a/easytier/src/instance/virtual_nic.rs b/easytier/src/instance/virtual_nic.rs index 6a67d65e..f516d493 100644 --- a/easytier/src/instance/virtual_nic.rs +++ b/easytier/src/instance/virtual_nic.rs @@ -12,6 +12,7 @@ use crate::{ error::Error, global_ctx::{ArcGlobalCtx, GlobalCtxEvent}, ifcfg::{IfConfiger, IfConfiguerTrait}, + log, }, instance::proxy_cidrs_monitor::ProxyCidrsMonitor, peers::{peer_manager::PeerManager, recv_packet_from_chan, PacketRecvChanReceiver}, @@ -95,7 +96,7 @@ impl Stream for TunStream { match ret { Ok(_) => Poll::Ready(Some(Ok(ZCPacket::new_from_buf(ret_buf, ZCPacketType::NIC)))), Err(err) => { - println!("tun stream error: {:?}", err); + log::error!("tun stream error: {:?}", err); Poll::Ready(None) } } @@ -249,10 +250,11 @@ impl Drop for VirtualNic { { if let Some(ref ifname) = self.ifname { // Try to clean up firewall rules, but don't panic in destructor - if let Err(e) = crate::arch::windows::remove_interface_firewall_rules(ifname) { - eprintln!( - "Warning: Failed to remove firewall rules for interface {}: {}", - ifname, e + if let Err(error) = crate::arch::windows::remove_interface_firewall_rules(ifname) { + log::warn!( + %error, + "failed to remove firewall rules for interface {}", + ifname ); } } @@ -293,25 +295,20 @@ impl VirtualNic { .unwrap_or(false); if !tun_module_available { - tracing::warn!("TUN kernel module may not be loaded"); - println!("⚠ Warning: TUN kernel module may not be available."); - println!(" You may need to load it with: sudo modprobe tun"); + log::warn!("TUN kernel module may not be available."); + log::warn!("\tYou may need to load it with: sudo modprobe tun."); } // Try to create /dev/net directory if it doesn't exist if tokio::fs::metadata(TUN_DIR_PATH).await.is_err() { - if let Err(e) = tokio::fs::create_dir_all(TUN_DIR_PATH).await { - tracing::warn!( - "Failed to create directory {}: {}. Continuing anyway.", - TUN_DIR_PATH, - e - ); - println!( - "⚠ Warning: Failed to create directory {}. TUN device creation may fail.", + if let Err(error) = tokio::fs::create_dir_all(TUN_DIR_PATH).await { + log::warn!( + ?error, + "Failed to create directory {}. TUN device creation may fail. Continuing anyway.", TUN_DIR_PATH ); - println!( - " You may need to run with root privileges or manually create the TUN device." + log::warn!( + "\tYou may need to run with root privileges or manually create the TUN device." ); Self::print_troubleshooting_info(); return; @@ -330,20 +327,14 @@ impl VirtualNic { dev_node, ) { Ok(_) => { - tracing::info!("Successfully created TUN device node {}", TUN_DEV_PATH); - println!("✓ Created TUN device node {}", TUN_DEV_PATH); + log::info!("Successfully created TUN device node {}", TUN_DEV_PATH); } - Err(e) => { + Err(error) => { tracing::warn!( - "Failed to create TUN device node {}: {}. Continuing anyway.", + %error, + "Failed to create TUN device node {}. Continuing anyway.", TUN_DEV_PATH, - e ); - println!( - "⚠ Warning: Failed to create TUN device node {}.", - TUN_DEV_PATH - ); - println!(" Error: {}", e); Self::print_troubleshooting_info(); } } @@ -352,13 +343,15 @@ impl VirtualNic { /// Print troubleshooting information for TUN device issues #[cfg(target_os = "linux")] fn print_troubleshooting_info() { - println!(" Possible solutions:"); - println!(" 1. Run with root privileges: sudo ./easytier-core [options]"); - println!(" 2. Manually create TUN device: sudo mkdir -p /dev/net && sudo mknod /dev/net/tun c 10 200"); - println!(" 3. Load TUN kernel module: sudo modprobe tun"); - println!(" 4. Use --no-tun flag if TUN functionality is not needed"); - println!(" 5. Check if your system/container supports TUN devices"); - println!(" Note: TUN functionality may still work if the kernel supports dynamic device creation."); + log::info!( + "Possible solutions:\ + \n\t1. Run with root privileges: sudo ./easytier-core [options]\ + \n\t2. Manually create TUN device: sudo mkdir -p /dev/net && sudo mknod /dev/net/tun c 10 200\ + \n\t3. Load TUN kernel module: sudo modprobe tun\ + \n\t4. Use --no-tun flag if TUN functionality is not needed\ + \n\t5. Check if your system/container supports TUN devices\ + \nNote: TUN functionality may still work if the kernel supports dynamic device creation." + ); } /// For non-Linux systems, this is a no-op @@ -535,10 +528,9 @@ impl VirtualNic { match crate::arch::windows::add_self_to_firewall_allowlist() { Ok(_) => tracing::info!("add_self_to_firewall_allowlist successful!"), - Err(e) => { - println!("Failed to add Easytier to firewall allowlist, Subnet proxy and KCP proxy may not work properly. error: {}", e); - println!("You can add firewall rules manually, or use --use-smoltcp to run with user-space TCP/IP stack."); - println!(); + Err(error) => { + log::warn!(%error, "Failed to add Easytier to firewall allowlist, Subnet proxy and KCP proxy may not work properly."); + log::warn!("You can add firewall rules manually, or use --use-smoltcp to run with user-space TCP/IP stack."); } } @@ -592,7 +584,7 @@ impl VirtualNic { &mut self, tun_fd: std::os::fd::RawFd, ) -> Result, Error> { - println!("tun_fd: {}", tun_fd); + log::debug!(%tun_fd); let mut config = Configuration::default(); config.layer(Layer::L3); @@ -711,19 +703,11 @@ impl VirtualNic { ifname ); } - Err(e) => { - tracing::warn!("Failed to configure Windows Firewall for {}: {}", ifname, e); - println!( - "⚠ Warning: Failed to configure Windows Firewall for interface {}.", - ifname - ); - println!(" This may cause connectivity issues with ping and other network functions."); - println!( - " Please run as Administrator or manually configure Windows Firewall." - ); - println!( - " Alternatively, you can disable Windows Firewall for testing purposes." - ); + Err(error) => { + log::warn!(%error, "Failed to configure Windows Firewall for interface {}\ + \n\tThis may cause connectivity issues with ping and other network functions.\ + \n\tPlease run as Administrator or manually configure Windows Firewall.\ + \n\tAlternatively, you can disable Windows Firewall for testing purposes.", ifname); } } } diff --git a/easytier/src/instance_manager.rs b/easytier/src/instance_manager.rs index e9934606..4e6c8eea 100644 --- a/easytier/src/instance_manager.rs +++ b/easytier/src/instance_manager.rs @@ -1,11 +1,12 @@ -use std::{collections::BTreeMap, path::PathBuf, sync::Arc}; - use dashmap::DashMap; +use std::fmt::{Display, Formatter}; +use std::{collections::BTreeMap, path::PathBuf, sync::Arc}; use crate::{ common::{ config::{ConfigFileControl, ConfigLoader, TomlConfigLoader}, global_ctx::{EventBusSubscriber, GlobalCtxEvent}, + log, scoped_task::ScopedTask, }, launcher::{NetworkInstance, NetworkInstanceRunningInfo}, @@ -85,10 +86,9 @@ impl NetworkInstanceManager { .map(|event| ScopedTask::from(handle_event(instance_id, event))); instance_stop_notifier.notified().await; if let Some(instance) = instance_map.get(&instance_id) { - if let Some(e) = instance.get_latest_error_msg() { - tracing::error!(?e, ?instance_id, "instance stopped with error"); - eprintln!("instance {} stopped with error: {}", instance_id, e); - instance_error_messages.insert(instance_id, e); + if let Some(error) = instance.get_latest_error_msg() { + log::error!(%error, "instance {} stopped", instance_id); + instance_error_messages.insert(instance_id, error); } } stop_check_notifier.notify_one(); @@ -261,6 +261,23 @@ impl NetworkInstanceManager { } } +macro_rules! event { + ($lvl:ident, category: $cat:expr, $($args:tt)+) => { + event!(@impl $lvl, concat!("INSTANCE::", $cat), $($args)+) + }; + + ($lvl:ident, $($args:tt)+) => { + event!(@impl $lvl, "INSTANCE", $($args)+) + }; + + (@impl $lvl:ident, $cat:expr, $($args:tt)+) => { + log::$lvl!( + category: $cat, + $($args)+ + ); + }; +} + #[tracing::instrument] fn handle_event( instance_id: uuid::Uuid, @@ -270,158 +287,140 @@ fn handle_event( loop { if let Ok(e) = events.recv().await { match e { - GlobalCtxEvent::PeerAdded(p) => { - print_event(instance_id, format!("new peer added. peer_id: {}", p)); + GlobalCtxEvent::PeerAdded(peer_id) => { + event!(info, peer_id, "[{}] new peer added", instance_id); } - GlobalCtxEvent::PeerRemoved(p) => { - print_event(instance_id, format!("peer removed. peer_id: {}", p)); + GlobalCtxEvent::PeerRemoved(peer_id) => { + event!(info, peer_id, "[{}] peer removed", instance_id); } - GlobalCtxEvent::PeerConnAdded(p) => { - print_event( + GlobalCtxEvent::PeerConnAdded(conn_info) => { + event!( + info, + category: "CONNECTION", + %conn_info, + "[{}] new peer connection added", instance_id, - format!( - "new peer connection added. conn_info: {}", - peer_conn_info_to_string(p) - ), ); } - GlobalCtxEvent::PeerConnRemoved(p) => { - print_event( + GlobalCtxEvent::PeerConnRemoved(conn_info) => { + event!( + info, + category: "CONNECTION", + %conn_info, + "[{}] peer connection removed", instance_id, - format!( - "peer connection removed. conn_info: {}", - peer_conn_info_to_string(p) - ), ); } - GlobalCtxEvent::ListenerAddFailed(p, msg) => { - print_event( - instance_id, - format!("listener add failed. listener: {}, msg: {}", p, msg), - ); + GlobalCtxEvent::ListenerAddFailed(listener, msg) => { + event!(warn, %listener, msg, "[{}] listener add failed", instance_id); } - GlobalCtxEvent::ListenerAcceptFailed(p, msg) => { - print_event( - instance_id, - format!("listener accept failed. listener: {}, msg: {}", p, msg), - ); + GlobalCtxEvent::ListenerAcceptFailed(listener, msg) => { + event!(warn, %listener, msg, "[{}] listener accept failed", instance_id); } - GlobalCtxEvent::ListenerAdded(p) => { - if p.scheme() == "ring" { + GlobalCtxEvent::ListenerAdded(listener) => { + if listener.scheme() == "ring" { continue; } - print_event(instance_id, format!("new listener added. listener: {}", p)); + event!( + info, + %listener, + "[{}] new listener added", + instance_id + ); } GlobalCtxEvent::ConnectionAccepted(local, remote) => { - print_event( - instance_id, - format!( - "new connection accepted. local: {}, remote: {}", - local, remote - ), - ); + event!(info, category: "CONNECTION", local, remote, "[{}] new connection accepted", instance_id); } GlobalCtxEvent::ConnectionError(local, remote, err) => { - print_event( - instance_id, - format!( - "connection error. local: {}, remote: {}, err: {}", - local, remote, err - ), - ); + event!(info, category: "CONNECTION", local, remote, err, "[{}] connection error", instance_id); } GlobalCtxEvent::TunDeviceReady(dev) => { - print_event(instance_id, format!("tun device ready. dev: {}", dev)); + event!(info, dev, "[{}] tun device ready", instance_id); } GlobalCtxEvent::TunDeviceError(err) => { - print_event(instance_id, format!("tun device error. err: {}", err)); + event!(error, %err, "[{}] tun device error", instance_id); } GlobalCtxEvent::Connecting(dst) => { - print_event(instance_id, format!("connecting to peer. dst: {}", dst)); + event!(info, category: "CONNECTION", %dst, "[{}] connecting to peer", instance_id); } - GlobalCtxEvent::ConnectError(dst, ip_version, err) => { - print_event( - instance_id, - format!( - "connect to peer error. dst: {}, ip_version: {}, err: {}", - dst, ip_version, err - ), + GlobalCtxEvent::ConnectError(dst, ip_version, error) => { + event!( + info, + category: "CONNECTION", + dst, + ip_version, + %error, + "[{}] connect to peer error", + instance_id ); } GlobalCtxEvent::VpnPortalStarted(portal) => { - print_event( - instance_id, - format!("vpn portal started. portal: {}", portal), - ); + event!(info, portal, "[{}] vpn portal started", instance_id); } GlobalCtxEvent::VpnPortalClientConnected(portal, client_addr) => { - print_event( - instance_id, - format!( - "vpn portal client connected. portal: {}, client_addr: {}", - portal, client_addr - ), + event!( + info, + portal, + client_addr, + "[{}] vpn portal client connected", + instance_id ); } GlobalCtxEvent::VpnPortalClientDisconnected(portal, client_addr) => { - print_event( - instance_id, - format!( - "vpn portal client disconnected. portal: {}, client_addr: {}", - portal, client_addr - ), + event!( + info, + portal, + client_addr, + "[{}] vpn portal client disconnected", + instance_id ); } GlobalCtxEvent::DhcpIpv4Changed(old, new) => { - print_event( - instance_id, - format!("dhcp ip changed. old: {:?}, new: {:?}", old, new), - ); + event!(info, ?old, ?new, "[{}] dhcp ip changed", instance_id); } GlobalCtxEvent::DhcpIpv4Conflicted(ip) => { - print_event(instance_id, format!("dhcp ip conflict. ip: {:?}", ip)); + event!(info, ?ip, "[{}] dhcp ip conflict", instance_id); } GlobalCtxEvent::PortForwardAdded(cfg) => { - print_event( + event!( + info, + local = %cfg.bind_addr.unwrap(), + remote = %cfg.dst_addr.unwrap(), + proto = %cfg.socket_type().as_str_name(), + "[{}] port forward added", instance_id, - format!( - "port forward added. local: {}, remote: {}, proto: {}", - cfg.bind_addr.unwrap(), - cfg.dst_addr.unwrap(), - cfg.socket_type().as_str_name() - ), ); } GlobalCtxEvent::ConfigPatched(patch) => { - print_event(instance_id, format!("config patched. patch: {:?}", patch)); + event!(info, ?patch, "[{}] config patched", instance_id); } GlobalCtxEvent::ProxyCidrsUpdated(added, removed) => { - print_event( - instance_id, - format!( - "proxy CIDRs updated. added: {:?}, removed: {:?}", - added, removed - ), + event!( + info, + ?added, + ?removed, + "[{}] proxy CIDRs updated", + instance_id ); } } @@ -432,20 +431,14 @@ fn handle_event( }) } -fn print_event(instance_id: uuid::Uuid, msg: String) { - println!( - "{}: [{}] {}", - chrono::Local::now().format("%Y-%m-%d %H:%M:%S"), - instance_id, - msg - ); -} - -fn peer_conn_info_to_string(p: proto::api::instance::PeerConnInfo) -> String { - format!( - "my_peer_id: {}, dst_peer_id: {}, tunnel_info: {:?}", - p.my_peer_id, p.peer_id, p.tunnel - ) +impl Display for proto::api::instance::PeerConnInfo { + fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result { + f.debug_struct("PeerConnInfo") + .field("my_peer_id", &self.my_peer_id) + .field("dst_peer_id", &self.peer_id) + .field("tunnel_info", &self.tunnel) + .finish() + } } #[cfg(test)] diff --git a/easytier/src/peers/encrypt/mod.rs b/easytier/src/peers/encrypt/mod.rs index 76d42b27..0e42beb5 100644 --- a/easytier/src/peers/encrypt/mod.rs +++ b/easytier/src/peers/encrypt/mod.rs @@ -1,6 +1,9 @@ use std::sync::Arc; -use crate::{common::config::EncryptionAlgorithm, tunnel::packet_def::ZCPacket}; +use crate::{ + common::{config::EncryptionAlgorithm, log}, + tunnel::packet_def::ZCPacket, +}; #[cfg(feature = "wireguard")] pub mod ring_aes_gcm; @@ -66,7 +69,7 @@ pub fn create_encryptor( let algorithm = match EncryptionAlgorithm::try_from(algorithm) { Ok(algorithm) => algorithm, Err(_) => { - eprintln!( + log::warn!( "Unknown encryption algorithm: {}, falling back to default AES-GCM", algorithm ); diff --git a/easytier/src/service_manager/mod.rs b/easytier/src/service_manager/mod.rs index 83dc5f26..83486250 100644 --- a/easytier/src/service_manager/mod.rs +++ b/easytier/src/service_manager/mod.rs @@ -4,6 +4,8 @@ use std::path::PathBuf; use service_manager::ServiceManager as _; +use crate::common::log; + #[derive(Debug)] pub struct ServiceInstallOptions { pub program: PathBuf, @@ -72,7 +74,7 @@ impl Service { let kind = service_manager::ServiceManagerKind::native()?; - println!("service manager kind: {:?}", kind); + log::info!("service manager kind: {:?}", kind); Ok(Self { label: name.parse()?, @@ -98,7 +100,7 @@ impl Service { self.service_manager .update(ctx) .map_err(|e| anyhow::anyhow!("failed to update service: {:?}", e))?; - println!("Service updated successfully! Service Name: {}", self.label); + log::info!("Service updated successfully! Service Name: {}", self.label); return Ok(()); } @@ -106,7 +108,7 @@ impl Service { .install(ctx) .map_err(|e| anyhow::anyhow!("failed to install service: {:?}", e))?; - println!( + log::info!( "Service installed successfully! Service Name: {}", self.label ); diff --git a/easytier/src/utils.rs b/easytier/src/utils.rs index 88b88322..10ae81d2 100644 --- a/easytier/src/utils.rs +++ b/easytier/src/utils.rs @@ -1,15 +1,7 @@ +use crate::common::log; +use indoc::formatdoc; use std::{fs::OpenOptions, str::FromStr}; -use anyhow::Context; -use tracing::level_filters::LevelFilter; -use tracing_subscriber::{ - layer::SubscriberExt, util::SubscriberInitExt, EnvFilter, Layer, Registry, -}; - -use crate::common::{ - config::LoggingConfigLoader, get_logger_timer_rfc3339, tracing_rolling_appender::*, -}; - pub type PeerRoutePair = crate::proto::api::instance::PeerRoutePair; pub fn cost_to_str(cost: i32) -> String { @@ -24,124 +16,6 @@ pub fn float_to_str(f: f64, precision: usize) -> String { format!("{:.1$}", f, precision) } -pub type NewFilterSender = std::sync::mpsc::Sender; - -pub fn init_logger( - config: impl LoggingConfigLoader, - need_reload: bool, -) -> Result, anyhow::Error> { - use crate::rpc_service::logger::{CURRENT_LOG_LEVEL, LOGGER_LEVEL_SENDER}; - - let file_config = config.get_file_logger_config(); - let file_level = file_config - .level - .map(|s| s.parse().unwrap()) - .unwrap_or(LevelFilter::OFF); - - let mut ret_sender: Option = None; - - // logger to rolling file - let mut file_layer = None; - if file_level != LevelFilter::OFF || need_reload { - let mut l = tracing_subscriber::fmt::layer(); - l.set_ansi(false); - let file_filter = EnvFilter::builder() - .with_default_directive(file_level.into()) - .from_env() - .with_context(|| "failed to create file filter")?; - let (file_filter, file_filter_reloader) = - tracing_subscriber::reload::Layer::new(file_filter); - - 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 e = file_filter_reloader.modify(|f| { - if let Ok(nf) = EnvFilter::builder() - .with_default_directive(lf.parse::().unwrap().into()) - .from_env() - .with_context(|| "failed to create file filter") - { - println!("Reload log filter succeed, new filter level: {:?}", lf); - *f = nf; - } - }); - if e.is_err() { - println!("Failed to reload log filter: {:?}", e); - } - } - println!("Stop log filter reloader"); - }); - } - - 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(); - - 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(); - - let wrapper = FileAppenderWrapper::new(file_appender); - - // Create a simple wrapper that implements MakeWriter - file_layer = Some( - l.with_writer(wrapper) - .with_timer(get_logger_timer_rfc3339()) - .with_filter(file_filter), - ); - } - - // 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 = EnvFilter::builder() - .with_default_directive(console_level.into()) - .from_env() - .unwrap(); - - let console_layer = tracing_subscriber::fmt::layer() - .pretty() - .with_timer(get_logger_timer_rfc3339()) - .with_writer(std::io::stderr) - .with_filter(console_filter); - - let registry = Registry::default(); - - #[cfg(not(feature = "tracing"))] - { - registry.with(console_layer).with(file_layer).init(); - } - - #[cfg(feature = "tracing")] - { - let console_subscriber_layer = console_subscriber::ConsoleLayer::builder().spawn(); - registry - .with(console_layer) - .with(file_layer) - .with(console_subscriber_layer) - .init(); - } - - Ok(ret_sender) -} - #[cfg(target_os = "windows")] pub fn utf8_or_gbk_to_string(s: &[u8]) -> String { use encoding::{all::GBK, DecoderTrap, Encoding}; @@ -165,13 +39,17 @@ pub fn setup_panic_handler() { use std::backtrace; use std::io::Write; std::panic::set_hook(Box::new(|info| { + let mut stderr = std::io::stderr(); + let sep = format!("{}\n", "=======".repeat(10)); + let _ = stderr.write_all(format!("{sep}{}\n{sep}", "!PANIC!".repeat(10)).as_bytes()); + PANIC_COUNT.with(|c| { let mut count = c.borrow_mut(); *count += 1; }); let panic_count = PANIC_COUNT.with(|c| *c.borrow()); if panic_count > 1 { - println!("panic happened more than once, exit immediately"); + log::error!("panic happened more than once, exit immediately"); std::process::exit(1); } @@ -208,36 +86,42 @@ pub fn setup_panic_handler() { } } - println!("{}", rust_i18n::t!("core_app.panic_backtrace_save")); + log::error!("{}", rust_i18n::t!("core_app.panic_backtrace_save")); // write str to stderr & file - let write_err = |s: String| { - let mut stderr = std::io::stderr(); - let content = format!("{}: {}", chrono::Local::now(), s); - let _ = writeln!(stderr, "{}", content); + let mut write_err = |s: String| { + let _ = stderr.write_all(s.as_bytes()); if let Some(mut f) = file.as_ref() { - let _ = writeln!(f, "{}", content); + let _ = f.write_all(s.as_bytes()); } }; - write_err("panic occurred, if this is a bug, please report this issue on github (https://github.com/easytier/easytier/issues)".to_string()); - write_err(format!("easytier version: {}", crate::VERSION)); - write_err(format!("os version: {}", std::env::consts::OS)); - write_err(format!("arch: {}", std::env::consts::ARCH)); - write_err(format!( - "panic is recorded in: {}", - file_path + let msg = formatdoc! {" + panic occurred, if this is a bug, please report this issue on github (https://github.com/easytier/easytier/issues) + easytier version: {version} + os: {os} + arch: {arch} + panic is recorded in: {file} + thread: {thread} + time: {time} + location: {location} + panic info: {payload} + ", + version = crate::VERSION, + os = std::env::consts::OS, + arch = std::env::consts::ARCH, + file = file_path .and_then(|p| p.to_str().map(|x| x.to_string())) - .unwrap_or("".to_string()) - )); - write_err(format!("thread: {}", thread)); - write_err(format!("time: {}", chrono::Local::now())); - write_err(format!("location: {}", location)); - write_err(format!("panic info: {}", payload_str)); + .unwrap_or("".to_string()), + thread = thread, + time = chrono::Local::now(), + location = location, + payload = payload_str, + }; - // backtrace is risky, so use it last - let backtrace = backtrace::Backtrace::force_capture(); - write_err(format!("backtrace: {:#?}", backtrace)); + write_err(msg); + write_err(sep); + write_err(format!("{:#?}", backtrace::Backtrace::force_capture())); std::process::exit(1); })); @@ -257,20 +141,3 @@ pub fn weak_upgrade(weak: &std::sync::Weak) -> anyhow::Result())) } - -#[cfg(test)] -mod tests { - use crate::common::config::{self}; - - use super::*; - - async fn test_logger_reload() { - println!("current working dir: {:?}", std::env::current_dir()); - let config = config::LoggingConfigBuilder::default().build().unwrap(); - let s = init_logger(&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"); - } -} diff --git a/easytier/src/web_client/mod.rs b/easytier/src/web_client/mod.rs index 05892e3e..d3dfb28d 100644 --- a/easytier/src/web_client/mod.rs +++ b/easytier/src/web_client/mod.rs @@ -2,7 +2,7 @@ use std::sync::Arc; use crate::{ common::{ - config::TomlConfigLoader, global_ctx::GlobalCtx, scoped_task::ScopedTask, + config::TomlConfigLoader, global_ctx::GlobalCtx, log, scoped_task::ScopedTask, set_default_machine_id, stun::MockStunInfoCollector, }, connector::create_connector_by_url, @@ -87,18 +87,16 @@ impl WebClient { loop { let conn = match connector.connect().await { Ok(conn) => conn, - Err(e) => { - println!( - "Failed to connect to the server ({}), retrying in 5 seconds...", - e - ); - tokio::time::sleep(std::time::Duration::from_secs(1)).await; + Err(error) => { + let wait = 1; + log::warn!(%error, "Failed to connect to the server, retrying in {} seconds...", wait); + tokio::time::sleep(std::time::Duration::from_secs(wait)).await; continue; } }; connected.store(true, Ordering::Release); - println!("Successfully connected to {:?}", conn.info()); + log::info!("Successfully connected to {:?}", conn.info()); let mut session = session::Session::new(conn, controller.clone()); session.wait().await;