diff --git a/Cargo.lock b/Cargo.lock index 60445962b..2a68f705e 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -167,7 +167,7 @@ dependencies = [ "objc2-foundation", "parking_lot", "percent-encoding", - "windows-sys 0.60.2", + "windows-sys 0.59.0", "wl-clipboard-rs", "x11rb", ] @@ -1139,10 +1139,7 @@ dependencies = [ "clash-verge-logging", "clash-verge-media-unlock", "clash-verge-signal", - "clash_verge_logger", "clash_verge_service_ipc", - "compact_str", - "console-subscriber", "core-foundation 0.9.4", "criterion", "dark-light", @@ -1150,7 +1147,6 @@ dependencies = [ "dirs 6.0.0", "dunce", "flate2", - "flexi_logger", "futures", "gethostname", "getrandom 0.4.3", @@ -1202,6 +1198,7 @@ dependencies = [ "tokio-rustls", "tokio-stream", "tokio-util", + "tracing", "warp", "webpki-roots", "windows 0.62.2", @@ -1237,10 +1234,11 @@ version = "0.1.0" name = "clash-verge-logging" version = "0.1.0" dependencies = [ - "compact_str", + "anyhow", "flexi_logger", "log", - "tokio", + "parking_lot", + "tracing-estuary", ] [[package]] @@ -1266,26 +1264,12 @@ dependencies = [ "tokio", ] -[[package]] -name = "clash_verge_logger" -version = "0.2.2" -source = "git+https://github.com/clash-verge-rev/clash-verge-logger#45adad7ae6dd76baa7457e3b111a0f1927998e22" -dependencies = [ - "arraydeque", - "compact_str", - "flexi_logger", - "log", - "nu-ansi-term", - "tokio", -] - [[package]] name = "clash_verge_service_ipc" -version = "2.6.6" -source = "git+https://github.com/clash-verge-rev/clash-verge-service-ipc.git?tag=v2.6.6#d1301e4bfad0b3ab3c4dadafcd2e5b4dc0e931cc" +version = "2.6.7" +source = "git+https://github.com/clash-verge-rev/clash-verge-service-ipc.git?tag=v2.6.7#aadc638b4947bd8de6a9f579da8a4a9d5fe76f8c" dependencies = [ "anyhow", - "compact_str", "kode-bridge", "libc", "log", @@ -1409,9 +1393,6 @@ dependencies = [ "castaway", "cfg-if", "itoa", - "rkyv", - "serde", - "smallvec", "static_assertions", "zmij", ] @@ -2073,7 +2054,7 @@ dependencies = [ "libc", "option-ext", "redox_users 0.5.2", - "windows-sys 0.60.2", + "windows-sys 0.59.0", ] [[package]] @@ -2347,7 +2328,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "39cab71617ae0d63f51a36d69f866391735b51691dbda63cf6f96d042b63efeb" dependencies = [ "libc", - "windows-sys 0.60.2", + "windows-sys 0.59.0", ] [[package]] @@ -2865,7 +2846,7 @@ dependencies = [ "gobject-sys 0.21.5", "libc", "system-deps 7.0.8", - "windows-sys 0.60.2", + "windows-sys 0.59.0", ] [[package]] @@ -3488,7 +3469,7 @@ dependencies = [ "libc", "percent-encoding", "pin-project-lite", - "socket2 0.5.10", + "socket2 0.6.5", "system-configuration", "tokio", "tower-service", @@ -3773,15 +3754,6 @@ dependencies = [ "either", ] -[[package]] -name = "itertools" -version = "0.12.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "ba291022dbbd398a455acf126c1e341954079855bc60dfdda641363bd6922569" -dependencies = [ - "either", -] - [[package]] name = "itertools" version = "0.13.0" @@ -4316,27 +4288,7 @@ dependencies = [ "png 0.18.1", "serde", "thiserror 2.0.20", - "windows-sys 0.60.2", -] - -[[package]] -name = "munge" -version = "0.4.7" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "5e17401f259eba956ca16491461b6e8f72913a0a114e39736ce404410f915a0c" -dependencies = [ - "munge_macro", -] - -[[package]] -name = "munge_macro" -version = "0.4.7" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "4568f25ccbd45ab5d5603dc34318c1ec56b117531781260002151b8530a9f931" -dependencies = [ - "proc-macro2", - "quote", - "syn 2.0.119", + "windows-sys 0.61.2", ] [[package]] @@ -4485,7 +4437,7 @@ version = "0.50.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7957b9740744892f114936ab4a57b3f487491bbeafaf8083688b16841a4240e5" dependencies = [ - "windows-sys 0.60.2", + "windows-sys 0.59.0", ] [[package]] @@ -5495,7 +5447,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "81bddcdb20abf9501610992b6759a4c888aef7d1a7247ef75e2404275ac24af1" dependencies = [ "anyhow", - "itertools 0.12.1", + "itertools 0.11.0", "proc-macro2", "quote", "syn 2.0.119", @@ -5508,7 +5460,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "b570b25f7617e43d59005d0990ccb79e950a423952cea19671b7a876da390adf" dependencies = [ "anyhow", - "itertools 0.14.0", + "itertools 0.13.0", "proc-macro2", "quote", "syn 2.0.119", @@ -5538,26 +5490,6 @@ version = "2.0.11" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "33cb294fe86a74cbcf50d4445b37da762029549ebeea341421c7c70370f86cac" -[[package]] -name = "ptr_meta" -version = "0.3.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "0b9a0cf95a1196af61d4f1cbdab967179516d9a4a4312af1f31948f8f6224a79" -dependencies = [ - "ptr_meta_derive", -] - -[[package]] -name = "ptr_meta_derive" -version = "0.3.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "7347867d0a7e1208d93b46767be83e2b8f978c3dad35f775ac8d8847551d6fe1" -dependencies = [ - "proc-macro2", - "quote", - "syn 2.0.119", -] - [[package]] name = "publicsuffix" version = "2.3.0" @@ -5602,7 +5534,7 @@ dependencies = [ "quinn-udp", "rustc-hash", "rustls", - "socket2 0.5.10", + "socket2 0.6.5", "thiserror 2.0.20", "tokio", "tracing", @@ -5641,9 +5573,9 @@ dependencies = [ "cfg_aliases", "libc", "once_cell", - "socket2 0.5.10", + "socket2 0.6.5", "tracing", - "windows-sys 0.60.2", + "windows-sys 0.59.0", ] [[package]] @@ -5667,15 +5599,6 @@ version = "6.0.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f8dcc9c7d52a811697d2151c701e0d08956f92b0e24136cf4cf27b57a6a0d9bf" -[[package]] -name = "rancor" -version = "0.1.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "daff8b7b3ccf5f7ba270b3e7a0a4d4c701c5797e38dec27c7e2c3dbb830fed1c" -dependencies = [ - "ptr_meta", -] - [[package]] name = "rand" version = "0.8.7" @@ -5877,12 +5800,6 @@ dependencies = [ "memchr", ] -[[package]] -name = "rend" -version = "0.5.4" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "663ba70707f96e871406fe10d68128412e619b06d1d47cb91c3a4c6501176240" - [[package]] name = "replace_with" version = "0.1.8" @@ -6047,30 +5964,6 @@ dependencies = [ "portable-atomic-util", ] -[[package]] -name = "rkyv" -version = "0.8.17" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "815cc8a37159a463064825246cadb07961e25cd9885908606f6d08a98d8f8874" -dependencies = [ - "munge", - "ptr_meta", - "rancor", - "rend", - "rkyv_derive", -] - -[[package]] -name = "rkyv_derive" -version = "0.8.17" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "c0ed1a78a1b19d184b0daa629dd9a024573173ec7d485b287cb369fb3607cc1c" -dependencies = [ - "proc-macro2", - "quote", - "syn 2.0.119", -] - [[package]] name = "runas" version = "1.2.0" @@ -6198,7 +6091,7 @@ dependencies = [ "errno", "libc", "linux-raw-sys 0.12.1", - "windows-sys 0.60.2", + "windows-sys 0.59.0", ] [[package]] @@ -6257,7 +6150,7 @@ dependencies = [ "security-framework", "security-framework-sys", "webpki-root-certs", - "windows-sys 0.60.2", + "windows-sys 0.59.0", ] [[package]] @@ -6480,7 +6373,7 @@ checksum = "7bd22781911de0ca6debda95f073c8f18bec65d1a94f1fa9573f3102e514cea4" dependencies = [ "ahash", "annotate-snippets", - "base64 0.22.1", + "base64 0.21.7", "encoding_rs_io", "getrandom 0.3.4", "granit-parser", @@ -6899,7 +6792,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "c3d1e2c7f27f8d4cb10542a02c49005dbd6e93095799d6f3be745fae9f8fedd4" dependencies = [ "libc", - "windows-sys 0.60.2", + "windows-sys 0.61.2", ] [[package]] @@ -7113,7 +7006,7 @@ dependencies = [ [[package]] name = "sysproxy" version = "0.7.0" -source = "git+https://github.com/clash-verge-rev/sysproxy-rs.git?branch=main#62c952b3a60c39a360f7e6cecde2bef5448659eb" +source = "git+https://github.com/clash-verge-rev/sysproxy-rs.git?branch=main#61118cab4878ce66b8cb12b467b682b493f20e6c" dependencies = [ "iptools", "log", @@ -7824,7 +7717,7 @@ dependencies = [ "serde_with", "swift-rs", "thiserror 2.0.20", - "toml 1.1.4+spec-1.1.0", + "toml 0.9.12+spec-1.1.0", "url", "urlpattern", "uuid", @@ -7860,10 +7753,10 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "32497e9a4c7b38532efcdebeef879707aa9f794296a4f0244f6f69e9bc8574bd" dependencies = [ "fastrand", - "getrandom 0.4.3", + "getrandom 0.3.4", "once_cell", "rustix 1.1.4", - "windows-sys 0.60.2", + "windows-sys 0.59.0", ] [[package]] @@ -8534,6 +8427,24 @@ dependencies = [ "valuable", ] +[[package]] +name = "tracing-estuary" +version = "0.1.0" +source = "git+https://github.com/Tunglies/tracing-estuary.git?branch=main#dbfce033fa4cff8f936f3e7c2282af1277546f3c" +dependencies = [ + "anyhow", + "compact_str", + "console-subscriber", + "flexi_logger", + "log", + "nu-ansi-term", + "parking_lot", + "tokio", + "tracing", + "tracing-log", + "tracing-subscriber", +] + [[package]] name = "tracing-log" version = "0.2.0" @@ -8582,7 +8493,7 @@ dependencies = [ "png 0.18.1", "serde", "thiserror 2.0.20", - "windows-sys 0.60.2", + "windows-sys 0.61.2", ] [[package]] @@ -8685,7 +8596,7 @@ checksum = "f2f6fb2847f6742cd76af783a2a2c49e9375d0a111c7bef6f71cd9e738c72d6e" dependencies = [ "memoffset", "tempfile", - "windows-sys 0.60.2", + "windows-sys 0.61.2", ] [[package]] @@ -9874,7 +9785,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7d6f32a0ff4a9f6f01231eb2059cc85479330739333e0e58cadf03b6af2cca10" dependencies = [ "cfg-if", - "windows-sys 0.60.2", + "windows-sys 0.59.0", ] [[package]] diff --git a/Cargo.toml b/Cargo.toml index 72fe7b772..527258615 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -53,7 +53,9 @@ clash-verge-logging = { path = "crates/clash-verge-logging" } clash-verge-signal = { path = "crates/clash-verge-signal" } clash-verge-i18n = { path = "crates/clash-verge-i18n" } clash-verge-limiter = { path = "crates/clash-verge-limiter" } +tracing-estuary = { git = "https://github.com/Tunglies/tracing-estuary.git", branch = "main" } tauri-plugin-clash-verge-sysinfo = { path = "crates/tauri-plugin-clash-verge-sysinfo" } +tracing = "0.1" tauri = { version = "2.11.5" } tauri-plugin-clipboard-manager = "2.3.2" @@ -74,7 +76,6 @@ reqwest = { version = "0.13.4", features = ["json", "cookies", "gzip", "rustls", rust_iso3166 = "0.2.0" smartstring = { version = "1.0.1" } -compact_str = { version = "0.10.0", features = ["serde"] } serde = { version = "1.0.229" } serde_json = { version = "1.0.151" } diff --git a/crates/clash-verge-logging/Cargo.toml b/crates/clash-verge-logging/Cargo.toml index db3a05df4..3a9152857 100644 --- a/crates/clash-verge-logging/Cargo.toml +++ b/crates/clash-verge-logging/Cargo.toml @@ -5,9 +5,13 @@ edition = "2024" [dependencies] log = { workspace = true } -tokio = { workspace = true } -compact_str = { workspace = true } +parking_lot = { workspace = true } +anyhow = { workspace = true } flexi_logger = { workspace = true } +tracing-estuary = { workspace = true } [features] default = [] +tokio-trace = ["tracing-estuary/tokio-trace"] +chrome-trace = ["tracing-estuary/chrome-trace"] +color = ["tracing-estuary/color"] diff --git a/crates/clash-verge-logging/src/lib.rs b/crates/clash-verge-logging/src/lib.rs index 4ef83cf7d..6c4c4ba55 100644 --- a/crates/clash-verge-logging/src/lib.rs +++ b/crates/clash-verge-logging/src/lib.rs @@ -1,14 +1,23 @@ -use compact_str::CompactString; -use flexi_logger::DeferredNow; -use flexi_logger::filter::LogLineFilter; -use flexi_logger::writers::FileLogWriter; -use flexi_logger::writers::LogWriter as _; -use log::Level; -use log::Record; -use std::{fmt, sync::Arc}; -use tokio::sync::{Mutex, MutexGuard}; +use std::{ + collections::VecDeque, + fmt, + path::PathBuf, + str::FromStr as _, + sync::{ + OnceLock, + atomic::{AtomicU64, AtomicUsize, Ordering}, + }, + time::Duration, +}; -pub type SharedWriter = Arc>; +use anyhow::{Result, bail}; +use flexi_logger::{ + Cleanup, Criterion, DeferredNow, FileSpec, Naming, + writers::{FileLogWriter, FileLogWriterBuilder, LogWriter as _}, +}; +use log::{Level, LevelFilter, Record}; +use parking_lot::RwLock; +use tracing_estuary::Pipeline; #[derive(Debug, PartialEq, Eq)] pub enum Type { @@ -80,57 +89,246 @@ macro_rules! logging_error { }; } -#[inline] -pub fn write_sidecar_log( - writer: MutexGuard<'_, FileLogWriter>, - now: &mut DeferredNow, - level: Level, - message: &CompactString, -) { - let args = format_args!("{}", message); +const LOGS_QUEUE_LEN: usize = 100; - let record = Record::builder().args(args).level(level).target("sidecar").build(); - - let _ = writer.write(now, &record); +/// In-memory ring buffer of recent mihomo core log lines. +pub struct LogRing { + inner: RwLock>, } -pub struct ModuleFilter<'a> { - block: Vec<&'a str>, - exclude: Option>, -} - -impl<'a> ModuleFilter<'a> { - pub fn new(block: Vec<&'a str>, exclude: Option>) -> Self { - Self { block, exclude } +impl LogRing { + #[must_use] + pub fn new() -> Self { + Self { + inner: RwLock::new(VecDeque::with_capacity(LOGS_QUEUE_LEN)), + } } - #[inline] - pub fn filter(&self, record: &Record) -> bool { - let Some(module) = record.module_path() else { - return true; + pub fn append_log(&self, log: String) { + let mut guard = self.inner.write(); + if guard.len() >= LOGS_QUEUE_LEN { + guard.pop_front(); + } + guard.push_back(log); + } + + pub fn get_logs(&self) -> Vec { + let guard = self.inner.read(); + guard.iter().cloned().collect() + } + + pub fn clear_logs(&self) { + let mut guard = self.inner.write(); + guard.clear(); + } +} + +impl Default for LogRing { + fn default() -> Self { + Self::new() + } +} + +// Buffered writes avoid flexi's one-syscall-per-line default; the flusher +// bounds the hard-kill loss window. +const WRITE_BUFFER_CAPACITY: usize = 64 * 1024; +const WRITE_FLUSH_INTERVAL: Duration = Duration::from_millis(500); + +const ROTATE_NAMING: Naming = Naming::TimestampsCustomFormat { + current_infix: Some("latest"), + format: "%Y-%m-%d_%H-%M-%S", +}; + +/// Directories and limits supplied by the embedder; the crate owns no path logic. +pub struct LoggerConfig { + pub level: LevelFilter, + pub max_size_kb: u64, + pub max_count: usize, + pub log_dir: PathBuf, + pub sidecar_log_dir: PathBuf, +} + +pub struct Logger { + pipeline: OnceLock, + sidecar_file_writer: RwLock>, + log_dir: OnceLock, + sidecar_log_dir: OnceLock, + log_max_size: AtomicU64, + log_max_count: AtomicUsize, +} + +static LOGGER: OnceLock = OnceLock::new(); + +impl Logger { + fn new() -> Self { + Self { + pipeline: OnceLock::new(), + sidecar_file_writer: RwLock::new(None), + log_dir: OnceLock::new(), + sidecar_log_dir: OnceLock::new(), + log_max_size: AtomicU64::new(128), + log_max_count: AtomicUsize::new(8), + } + } + + pub fn global() -> &'static Self { + LOGGER.get_or_init(Self::new) + } + + /// Installs the global tracing pipeline. `RUST_LOG` (parsed as a bare + /// level) overrides the configured level. + pub fn init(&self, cfg: &LoggerConfig) -> Result<()> { + let log_level = std::env::var("RUST_LOG") + .ok() + .and_then(|v| LevelFilter::from_str(v.trim()).ok()) + .unwrap_or(cfg.level); + self.store_config(cfg); + let pipeline = tracing_estuary::PipelineBuilder::new() + .default_level(log_level) + .file_writer(self.generate_file_log_writer()?) + .init()?; + self.pipeline.set(pipeline).ok(); + Ok(()) + } + + /// Installs the sidecar file writer and the panic hook. Safe to call when + /// the pipeline is owned elsewhere (e.g. a devtools-provided subscriber). + pub fn init_sidecar(&self, cfg: &LoggerConfig) -> Result<()> { + self.store_config(cfg); + self.ensure_sidecar_writer(self.generate_sidecar_builder())?; + + std::panic::set_hook(Box::new(move |info| { + // Capture both common panic payload types instead of logging String payloads as unknown. + // This global hook covers panics after logger init; early setup panics are handled separately. + let payload = info + .payload() + .downcast_ref::<&str>() + .map(|s| (*s).to_string()) + .or_else(|| info.payload().downcast_ref::().cloned()) + .unwrap_or_else(|| "Unknown panic payload".to_string()); + let location = info + .location() + .map(|loc| format!("{}:{}", loc.file(), loc.line())) + .unwrap_or_else(|| "Unknown location".to_string()); + logging!(error, Type::System, "Panic occurred at {}: {}", location, payload); + Self::global().flush_logs(); + std::thread::sleep(Duration::from_millis(100)); + })); + + Ok(()) + } + + fn store_config(&self, cfg: &LoggerConfig) { + self.log_dir.set(cfg.log_dir.clone()).ok(); + self.sidecar_log_dir.set(cfg.sidecar_log_dir.clone()).ok(); + self.log_max_size.store(cfg.max_size_kb, Ordering::SeqCst); + self.log_max_count.store(cfg.max_count, Ordering::SeqCst); + } + + fn generate_file_log_writer(&self) -> Result { + let log_dir = self.log_dir.get().cloned().unwrap_or_default(); + let log_max_size = self.log_max_size.load(Ordering::SeqCst); + let log_max_count = self.log_max_count.load(Ordering::SeqCst); + let flwb = FileLogWriter::builder(FileSpec::default().directory(log_dir).basename("")) + .format(tracing_estuary::file_format_with_level) + .write_mode(flexi_logger::WriteMode::BufferAndFlushWith( + WRITE_BUFFER_CAPACITY, + WRITE_FLUSH_INTERVAL, + )) + .rotate( + Criterion::Size(log_max_size * 1024), + ROTATE_NAMING, + Cleanup::KeepLogFiles(log_max_count), + ); + Ok(flwb) + } + + /// Ensures the sidecar writer exists and points at `builder`'s config: + /// built once, then reset in place — flexi's flusher thread cannot be + /// stopped, so every dropped writer would leak a thread and an fd. + fn ensure_sidecar_writer(&self, builder: FileLogWriterBuilder) -> Result<()> { + let sidecar = self.sidecar_file_writer.write(); + match sidecar.as_ref() { + Some(writer) => { + let _ = writer.flush(); + writer.reset(&builder)?; + } + None => { + // Build outside the guard: a spawn panic inside it would + // deadlock the panic hook, which takes this lock to flush. + drop(sidecar); + let writer = builder.try_build()?; + *self.sidecar_file_writer.write() = Some(writer); + } + } + Ok(()) + } + + fn generate_sidecar_builder(&self) -> FileLogWriterBuilder { + let sidecar_log_dir = self.sidecar_log_dir.get().cloned().unwrap_or_default(); + let log_max_size = self.log_max_size.load(Ordering::SeqCst); + let log_max_count = self.log_max_count.load(Ordering::SeqCst); + FileLogWriter::builder( + FileSpec::default() + .directory(sidecar_log_dir) + .basename("sidecar") + .suppress_timestamp(), + ) + .format(tracing_estuary::file_format_without_level) + .write_mode(flexi_logger::WriteMode::BufferAndFlushWith( + WRITE_BUFFER_CAPACITY, + WRITE_FLUSH_INTERVAL, + )) + .rotate( + Criterion::Size(log_max_size * 1024), + ROTATE_NAMING, + Cleanup::KeepLogFiles(log_max_count), + ) + } + + /// Drains the pipeline and the sidecar writer, whose flusher only runs every 500ms. + pub fn flush_logs(&self) { + if let Some(pipeline) = self.pipeline.get() { + pipeline.flush_all(); + } + if let Some(writer) = self.sidecar_file_writer.read().as_ref() { + let _ = writer.flush(); + } + } + + /// only update app log level + pub fn update_log_level(&self, level: LevelFilter) -> Result<()> { + if let Some(pipeline) = self.pipeline.get() { + pipeline.filter.set_default_level(level)?; + } else { + bail!("failed to get tracing pipeline, make sure it init"); }; + Ok(()) + } - if let Some(excludes) = &self.exclude - && excludes.iter().any(|e| module.starts_with(e)) - { - return true; + /// Rebuilds both file writers with the new limits. + pub fn update_log_config(&self, log_max_size: u64, log_max_count: usize) -> Result<()> { + self.log_max_size.store(log_max_size, Ordering::SeqCst); + self.log_max_count.store(log_max_count, Ordering::SeqCst); + if let Some(pipeline) = self.pipeline.get() { + let log_file_writer = self.generate_file_log_writer()?; + if let Some(sink) = pipeline.sink.as_ref() { + sink.reset(log_file_writer) + .map_err(|error| anyhow::anyhow!("failed to reset log writer: {error}"))?; + } + } else { + bail!("failed to get tracing pipeline, make sure it init"); + }; + self.ensure_sidecar_writer(self.generate_sidecar_builder())?; + Ok(()) + } + + pub fn writer_sidecar_log(&self, level: Level, message: &str) { + if let Some(writer) = self.sidecar_file_writer.read().as_ref() { + let mut now = DeferredNow::default(); + let args = format_args!("{}", message); + let record = Record::builder().args(args).level(level).target("sidecar").build(); + let _ = writer.write(&mut now, &record); } - - !self.block.iter().any(|b| module.starts_with(b)) - } -} - -impl<'a> LogLineFilter for ModuleFilter<'a> { - #[inline] - fn write( - &self, - now: &mut DeferredNow, - record: &Record, - writer: &dyn flexi_logger::filter::LogLineWriter, - ) -> std::io::Result<()> { - if !self.filter(record) { - return Ok(()); - } - writer.write(now, record) } } diff --git a/src-tauri/Cargo.toml b/src-tauri/Cargo.toml index c9f62b2e5..0c902d70b 100755 --- a/src-tauri/Cargo.toml +++ b/src-tauri/Cargo.toml @@ -17,12 +17,12 @@ crate-type = ["staticlib", "cdylib", "rlib"] [features] default = ["custom-protocol"] custom-protocol = ["tauri/custom-protocol"] -verge-dev = ["clash_verge_logger/color", "clash_verge_service_ipc/development-channel"] +verge-dev = ["clash-verge-logging/color", "clash_verge_service_ipc/development-channel"] dev-sidecar = ["verge-dev"] tauri-dev = ["dep:tauri-plugin-devtools"] -tokio-trace = ["dep:console-subscriber"] +tokio-trace = ["clash-verge-logging/tokio-trace"] +chrome-trace = ["clash-verge-logging/chrome-trace"] clippy = ["tauri/test"] -tracing = [] perf-harness = ["dep:tauri-plugin-wdio-webdriver"] [package.metadata.bundle] @@ -43,6 +43,7 @@ tauri-plugin-clipboard-manager = { workspace = true } tauri = { workspace = true, features = [ "protocol-asset", "devtools", + "tracing", "tray-icon", "image-ico", "image-png", @@ -50,8 +51,6 @@ tauri = { workspace = true, features = [ parking_lot = { workspace = true } anyhow = { workspace = true } tokio = { workspace = true } -compact_str = { workspace = true } -flexi_logger = { workspace = true } log = { workspace = true } serde = { workspace = true, features = ["derive"] } serde_json = { workspace = true } @@ -95,12 +94,11 @@ tauri-plugin-notification = "2.3.3" tokio-stream = "0.1.19" backon = { version = "1.6.0", features = ["tokio-sleep"] } tauri-plugin-http = "2.5.9" -console-subscriber = { version = "0.5.0", optional = true } +tracing = { workspace = true } tauri-plugin-devtools = { version = "2.1.0", optional = true } tauri-plugin-mihomo = { git = "https://github.com/clash-verge-rev/tauri-plugin-mihomo", branch = "main" } -clash_verge_logger = { git = "https://github.com/clash-verge-rev/clash-verge-logger" } async-trait = "0.1.92" -clash_verge_service_ipc = { git = "https://github.com/clash-verge-rev/clash-verge-service-ipc.git", tag = "v2.6.6", version = "2.6.6", features = [ +clash_verge_service_ipc = { git = "https://github.com/clash-verge-rev/clash-verge-service-ipc.git", tag = "v2.6.7", version = "2.6.7", features = [ "client", ] } arc-swap = "1.9.2" diff --git a/src-tauri/src/cmd/clash.rs b/src-tauri/src/cmd/clash.rs index 16f908e72..4b70b136c 100644 --- a/src-tauri/src/cmd/clash.rs +++ b/src-tauri/src/cmd/clash.rs @@ -11,7 +11,6 @@ use crate::{ }, }; use clash_verge_logging::{Type, logging, logging_error}; -use compact_str::CompactString; use serde_yaml_ng::Mapping; use smartstring::alias::String; use tokio::fs; @@ -57,7 +56,6 @@ pub async fn change_clash_core(clash_core: String) -> CmdResult { - logging!(info, Type::Core, "core changed and restarted to {clash_core}"); handle::Handle::notice_message("config_core::change_success", clash_core); handle::Handle::refresh_clash(); Ok(None) @@ -66,7 +64,7 @@ pub async fn change_clash_core(clash_core: String) -> CmdResult CmdResult { let result = match feat::test_delay(url).await { Ok(delay) => delay, Err(e) => { - logging!(error, Type::Cmd, "{}", e); + logging!(error, Type::Cmd, "get clash delay failed: {e:#}"); 10000u32 } }; @@ -147,8 +145,6 @@ pub async fn apply_dns_config(apply: bool) -> CmdResult { logging!(error, Type::Config, "Failed to parse DNS config: {e}"); })?; - logging!(info, Type::Config, "Applying DNS config from file"); - let mut patch = serde_yaml_ng::Mapping::new(); patch.insert("dns".into(), patch_config.into()); @@ -207,7 +203,7 @@ pub async fn validate_dns_config() -> CmdResult { } #[tauri::command] -pub async fn get_clash_logs() -> CmdResult> { +pub async fn get_clash_logs() -> CmdResult> { let logs = CoreManager::global().get_clash_logs().await.unwrap_or_default(); Ok(logs) } diff --git a/src-tauri/src/cmd/network.rs b/src-tauri/src/cmd/network.rs index b8925f649..dd3475336 100644 --- a/src-tauri/src/cmd/network.rs +++ b/src-tauri/src/cmd/network.rs @@ -1,7 +1,7 @@ use super::CmdResult; use crate::cmd::StringifyErr as _; use crate::core::{proxy_control, sysopt::Sysopt}; -use clash_verge_logging::{Type, logging}; + use gethostname::gethostname; use network_interface::NetworkInterface; use serde_yaml_ng::Mapping; @@ -10,8 +10,6 @@ use tauri_plugin_clash_verge_sysinfo; #[tauri::command] pub async fn get_sys_proxy() -> CmdResult { - logging!(debug, Type::Network, "异步获取系统代理配置"); - Sysopt::global().wait_idle().await; // With no network service there is no proxy configured anywhere, which reads as disabled. let sys_proxy = match Sysproxy::get_system_proxy() { @@ -29,15 +27,6 @@ pub async fn get_sys_proxy() -> CmdResult { map.insert("enable".into(), (*enable).into()); map.insert("server".into(), format!("{}:{}", host, port).into()); map.insert("bypass".into(), bypass.as_str().into()); - - logging!( - debug, - Type::Network, - "返回系统代理配置: enable={}, {}:{}", - sys_proxy.enable, - sys_proxy.host, - sys_proxy.port - ); Ok(map) } @@ -53,14 +42,6 @@ pub async fn get_auto_proxy() -> CmdResult { let mut map = Mapping::new(); map.insert("enable".into(), (*enable).into()); map.insert("url".into(), url.as_str().into()); - - logging!( - debug, - Type::Network, - "返回自动代理配置（缓存）: enable={}, url={}", - auto_proxy.enable, - auto_proxy.url - ); Ok(map) } diff --git a/src-tauri/src/cmd/profile.rs b/src-tauri/src/cmd/profile.rs index a8f8df33f..dcdd4b12b 100644 --- a/src-tauri/src/cmd/profile.rs +++ b/src-tauri/src/cmd/profile.rs @@ -33,7 +33,6 @@ fn profile_import_error(err: &anyhow::Error) -> std::string::String { #[tauri::command] pub async fn get_profiles() -> CmdResult> { - logging!(debug, Type::Cmd, "获取配置文件列表"); let draft = Config::profiles().await; let data = draft.data_arc(); Ok(data) @@ -57,45 +56,39 @@ pub async fn enhance_profiles() -> CmdResult { Ok(outcome) } Err(e) => { - logging!(error, Type::Cmd, "{}", e); + logging!(error, Type::Cmd, "enhance profiles failed: {e:#}"); Err(coded_error("PROFILE_ENHANCE_FAILED", e)) } } } #[tauri::command] +#[tracing::instrument(skip_all, level = "info", fields(url = %help::mask_url(&url), uid = tracing::field::Empty))] pub async fn import_profile(url: std::string::String, option: Option) -> CmdResult { - logging!(info, Type::Cmd, "[导入订阅] 开始导入: {}", help::mask_url(&url)); - let item = &mut match PrfItem::from_url(&url, None, None, option.as_ref()).await { - Ok(it) => { - logging!(info, Type::Cmd, "[导入订阅] 下载完成，开始保存配置"); - it - } + Ok(it) => it, Err(e) => { - logging!(error, Type::Cmd, "[导入订阅] 下载失败: {}", e); + logging!(error, Type::Cmd, "[导入订阅] 下载失败: {e:#}"); return Err(coded_error("PROFILE_IMPORT_FAILED", profile_import_error(&e))); } }; if let Err(e) = profiles_append_item_safe(item).await { - logging!(error, Type::Cmd, "[导入订阅] 保存配置失败: {}", e); + logging!(error, Type::Cmd, "[导入订阅] 保存配置失败: {e:#}"); return Err(coded_error("PROFILE_IMPORT_FAILED", e)); } if let Err(e) = profiles_save_file_safe().await { - logging!(error, Type::Cmd, "[导入订阅] 保存配置文件失败: {}", e); + logging!(error, Type::Cmd, "[导入订阅] 保存配置文件失败: {e:#}"); return Err(coded_error("PROFILE_IMPORT_FAILED", e)); } - logging!(info, Type::Cmd, "[导入订阅] 配置文件保存成功"); logging_error!(Type::Timer, Timer::global().refresh().await); if let Some(uid) = &item.uid { - logging!(info, Type::Cmd, "[导入订阅] 发送配置变更通知: {}", uid); + tracing::Span::current().record("uid", tracing::field::display(uid)); handle::Handle::notify_profile_changed(uid); } - logging!(info, Type::Cmd, "[导入订阅] 导入完成: {}", help::mask_url(&url)); Ok(()) } @@ -103,11 +96,17 @@ pub async fn import_profile(url: std::string::String, option: Option) pub async fn reorder_profile(active_id: String, over_id: String) -> CmdResult { match profiles_reorder_safe(&active_id, &over_id).await { Ok(_) => { - logging!(info, Type::Cmd, "重新排序配置文件"); + logging!(info, Type::Cmd, "重新排序配置文件: {} -> {}", active_id, over_id); Ok(()) } Err(err) => { - logging!(error, Type::Cmd, "重新排序配置文件失败: {}", err); + logging!( + error, + Type::Cmd, + "重新排序配置文件失败: {} -> {}: {err:#}", + active_id, + over_id + ); Err(coded_error("PROFILE_REORDER_FAILED", err)) } } @@ -122,7 +121,6 @@ pub async fn create_profile(item: PrfItem, file_data: Option) -> CmdResu .with_error_code("PROFILE_CREATE_FAILED")?; logging_error!(Type::Timer, Timer::global().refresh().await); if let Some(uid) = &item.uid { - logging!(info, Type::Cmd, "[创建订阅] 发送配置变更通知: {}", uid); handle::Handle::notify_profile_changed(uid); } Ok(()) @@ -136,7 +134,7 @@ pub async fn update_profile(index: String, option: Option) -> CmdResu match feat::update_profile(&index, option.as_ref(), true).await { Ok(_) => Ok(()), Err(e) => { - logging!(error, Type::Cmd, "{}", e); + logging!(error, Type::Cmd, "update profile failed: {e:#}"); Err(coded_error("PROFILE_UPDATE_FAILED", e)) } } @@ -183,16 +181,15 @@ pub async fn delete_profile(index: String) -> CmdResult { drop(profile_write_guard); if let Err(e) = Tray::global().update_tooltip().await { - logging!(warn, Type::Cmd, "Warning: 异步更新托盘提示失败: {e}"); + logging!(warn, Type::Cmd, "异步更新托盘提示失败: {e:#}"); } if let Err(e) = Tray::global().update_menu().await { - logging!(warn, Type::Cmd, "Warning: 异步更新托盘菜单失败: {e}"); + logging!(warn, Type::Cmd, "异步更新托盘菜单失败: {e:#}"); } if should_update { handle::Handle::refresh_clash(); if let Some(current) = current.as_ref() { - logging!(info, Type::Cmd, "[删除订阅] 发送配置变更通知: {}", current); handle::Handle::notify_profile_changed(current); } } @@ -212,10 +209,9 @@ async fn restore_previous_profile(prev_profile: &String) -> CmdResult<()> { Config::profiles().await.apply(); crate::process::AsyncHandler::spawn(|| async move { if let Err(e) = profiles_save_file_safe().await { - logging!(warn, Type::Cmd, "Warning: 异步保存恢复配置文件失败: {e}"); + logging!(warn, Type::Cmd, "异步保存恢复配置文件失败: {e:#}"); } }); - logging!(info, Type::Cmd, "成功恢复到之前的配置"); Ok(()) } @@ -244,13 +240,12 @@ async fn handle_success(current_value: Option<&String>) -> CmdResult CmdResult { if CURRENT_SWITCHING_PROFILE .compare_exchange(false, true, Ordering::Acquire, Ordering::Relaxed) @@ -325,10 +321,7 @@ pub async fn patch_profiles_config(profiles: IProfiles) -> CmdResult CmdResult CmdResult { - logging!(info, Type::Cmd, "切换配置到: {}", profile_index); - let profiles = IProfiles { current: Some(profile_index), items: None, @@ -377,7 +368,7 @@ pub async fn patch_profile(index: String, profile: PrfItem) -> CmdResult { crate::process::AsyncHandler::spawn(move || async move { logging!(info, Type::Timer, "Timer update settings changed, refreshing timer..."); if let Err(e) = crate::core::Timer::global().refresh().await { - logging!(error, Type::Timer, "Failed to refresh timer: {}", e); + logging!(error, Type::Timer, "Failed to refresh timer: {e:#}"); } else { crate::core::handle::Handle::notify_timer_updated(&index); } diff --git a/src-tauri/src/cmd/proxy.rs b/src-tauri/src/cmd/proxy.rs index 551c3a88e..66e027ce1 100644 --- a/src-tauri/src/cmd/proxy.rs +++ b/src-tauri/src/cmd/proxy.rs @@ -87,10 +87,10 @@ async fn run_tray_sync_loop() { loop { match Tray::global().update_menu().await { Ok(_) => { - logging!(info, Type::Cmd, "Tray proxy selection synced successfully"); + logging!(debug, Type::Cmd, "Tray proxy selection synced successfully"); } Err(e) => { - logging!(error, Type::Cmd, "Failed to sync tray proxy selection: {e}"); + logging!(error, Type::Cmd, "Failed to sync tray proxy selection: {e:#}"); } } diff --git a/src-tauri/src/cmd/runtime.rs b/src-tauri/src/cmd/runtime.rs index 24cac919a..d96168fb7 100644 --- a/src-tauri/src/cmd/runtime.rs +++ b/src-tauri/src/cmd/runtime.rs @@ -94,7 +94,7 @@ pub async fn update_proxy_chain_config_in_runtime(proxy_chain_config: Option logging!(error, Type::Core, "Failed to apply runtime proxy chain config: {}", err), + Err(err) => logging!(error, Type::Core, "Failed to apply runtime proxy chain config: {err:#}"), } Ok(()) diff --git a/src-tauri/src/cmd/save_profile.rs b/src-tauri/src/cmd/save_profile.rs index 060cc567d..e1f566f4f 100644 --- a/src-tauri/src/cmd/save_profile.rs +++ b/src-tauri/src/cmd/save_profile.rs @@ -66,14 +66,6 @@ pub async fn save_profile_file(index: String, file_data: Option) -> CmdR // 保存新的配置文件 fs::write(&file_path, &file_data).await.stringify_err()?; - logging!( - info, - Type::Config, - "[cmd配置save] 开始验证配置文件: {}, 是否为merge文件: {}", - file_path_str, - is_merge_file - ); - let changes_applied = handle_saved_profile_file( &file_path_str, &file_path, @@ -144,18 +136,8 @@ async fn handle_saved_profile_file( (ValidationNoticeTarget::Runtime, "YAML配置文件") }; - logging!( - info, - Type::Config, - "[cmd配置save] 开始{}验证: {}", - file_type, - file_path_str - ); - match CoreConfigValidator::validate_config_file_outcome(file_path_str, Some(is_merge_file)).await { - Ok(outcome) if outcome.is_valid() => { - logging!(info, Type::Config, "[cmd配置save] 文件验证通过: {}", file_path_str); - } + Ok(outcome) if outcome.is_valid() => {} Ok(outcome) => { logging!(warn, Type::Config, "[cmd配置save] 文件验证失败: {}", outcome); restore_original(file_path, original_content, original_existed).await?; @@ -163,7 +145,7 @@ async fn handle_saved_profile_file( return Ok(outcome); } Err(e) => { - logging!(error, Type::Config, "[cmd配置save] 验证过程发生错误: {}", e); + logging!(error, Type::Config, "[cmd配置save] 验证过程发生错误: {e:#}"); restore_original(file_path, original_content, original_existed).await?; return Err(e.to_string().into()); } @@ -190,7 +172,7 @@ async fn handle_saved_profile_file( Ok(outcome) } Err(err) => { - logging!(error, Type::Config, "[cmd配置save] 运行时配置应用错误: {}", err); + logging!(error, Type::Config, "[cmd配置save] 运行时配置应用错误: {err:#}"); restore_original(file_path, original_content, original_existed).await?; Err(err.to_string().into()) } diff --git a/src-tauri/src/config/clash.rs b/src-tauri/src/config/clash.rs index 9ddc5558d..8495572ee 100644 --- a/src-tauri/src/config/clash.rs +++ b/src-tauri/src/config/clash.rs @@ -43,7 +43,11 @@ impl IClashTemp { Self(Self::guard(map)) } Err(err) => { - logging!(error, Type::Config, "{err}"); + logging!( + error, + Type::Config, + "failed to load clash config, using template: {err:#}" + ); Self::template() } } diff --git a/src-tauri/src/config/config.rs b/src-tauri/src/config/config.rs index 28a1db7c6..eccbd476c 100644 --- a/src-tauri/src/config/config.rs +++ b/src-tauri/src/config/config.rs @@ -144,16 +144,16 @@ impl Config { .await?; return Ok(Some(("config_validate::boot_error", error_msg))); } - logging!(info, Type::Config, "生成运行时配置成功"); + logging!(debug, Type::Config, "生成运行时配置成功"); let config_result = Self::generate_file(ConfigType::Run).await; if config_result.is_ok() { - logging!(info, Type::Config, "开始验证配置"); + logging!(debug, Type::Config, "开始验证配置"); match CoreConfigValidator::global().validate_config_outcome().await { Ok(outcome) if outcome.is_valid() => { - logging!(info, Type::Config, "配置验证成功"); + logging!(debug, Type::Config, "配置验证成功"); Ok(None) } Ok(outcome) => { @@ -170,7 +170,7 @@ impl Config { Ok(Some(("config_validate::boot_error", error_msg))) } Err(err) => { - logging!(warn, Type::Config, "验证过程执行失败: {}", err); + logging!(warn, Type::Config, "验证过程执行失败: {err:#}"); CoreManager::global() .use_default_config("config_validate::process_terminated", "") .await?; @@ -178,7 +178,8 @@ impl Config { } } } else { - logging!(warn, Type::Config, "生成配置文件失败，使用默认配置"); + let error_msg = config_result.err().map(|err| err.to_string()).unwrap_or_default(); + logging!(warn, Type::Config, "生成配置文件失败，使用默认配置: {error_msg}"); CoreManager::global() .use_default_config("config_validate::error", "") .await?; @@ -250,13 +251,13 @@ impl Config { .retry(backoff) .await { - logging!(error, Type::Setup, "Config init verification failed: {}", e); + logging!(error, Type::Setup, "Config init verification failed: {e:#}"); } } /// Commits drafts during exit/restart/shutdown so user changes are not lost. pub async fn apply_all_and_save_file() { - logging!(info, Type::Config, "save all draft data"); + logging!(debug, Type::Config, "save all draft data"); let save_clash_task = AsyncHandler::spawn(|| async { let clash = Self::clash().await; clash.apply(); diff --git a/src-tauri/src/config/port.rs b/src-tauri/src/config/port.rs index ec97c3d0a..5219690b1 100644 --- a/src-tauri/src/config/port.rs +++ b/src-tauri/src/config/port.rs @@ -262,7 +262,7 @@ async fn owned_service_core_uses_port(port: u16) -> bool { logging!( warn, Type::Service, - "Current user's service core is active but its mixed proxy port is unavailable: {error}; \ + "Current user's service core is active but its mixed proxy port is unavailable: {error:#}; \ preserving the selected port until core replacement resolves ownership" ); true diff --git a/src-tauri/src/config/profiles.rs b/src-tauri/src/config/profiles.rs index e65545c97..2116eadfc 100644 --- a/src-tauri/src/config/profiles.rs +++ b/src-tauri/src/config/profiles.rs @@ -93,7 +93,7 @@ impl IProfiles { let path = match dirs::profiles_path() { Ok(p) => p, Err(err) => { - logging!(error, Type::Config, "{err}"); + logging!(error, Type::Config, "failed to get profiles path: {err:#}"); return Self::default(); } }; @@ -124,12 +124,12 @@ impl IProfiles { } if home_changed && let Err(err) = profiles.save_file().await { - logging!(error, Type::Config, "无法保存已清理的 profiles.yaml: {err}"); + logging!(error, Type::Config, "无法保存已清理的 profiles.yaml: {err:#}"); } profiles } Err(err) => { - logging!(error, Type::Config, "{err}"); + logging!(error, Type::Config, "failed to read profiles.yaml: {err:#}"); Self::default() } } @@ -599,7 +599,7 @@ async fn fetch_proxies_with_timeout() -> Result { match handle::Handle::mihomo().get_proxies().await { Ok(proxies) => return proxies, Err(err) => { - logging!(debug, Type::Config, "mihomo proxies are not ready yet: {err}"); + logging!(debug, Type::Config, "mihomo proxies are not ready yet: {err:#}"); tokio::time::sleep(Duration::from_millis(500)).await; } } @@ -999,7 +999,7 @@ pub(crate) async fn restore_selected_nodes() { } fn activate_selected_nodes_with(repair: SelectionRepair) -> tokio::sync::oneshot::Receiver<()> { - logging!(info, Type::Config, "starting activating selected nodes"); + logging!(debug, Type::Config, "starting activating selected nodes"); let mut active_task = ACTIVATE_SELECTED_TASK.lock(); let generation = ACTIVATE_SELECTED_GENERATION.fetch_add(1, Ordering::AcqRel) + 1; let previous_task = active_task.take(); @@ -1043,7 +1043,7 @@ fn activate_selected_nodes_with(repair: SelectionRepair) -> tokio::sync::oneshot handle::Handle::refresh_clash(); } update_tray_after_activation(generation).await; - logging!(info, Type::Config, "activating selected nodes done!"); + logging!(debug, Type::Config, "activating selected nodes done!"); } }); *active_task = Some(handle); diff --git a/src-tauri/src/config/verge.rs b/src-tauri/src/config/verge.rs index 5aeefbedc..92abd308b 100644 --- a/src-tauri/src/config/verge.rs +++ b/src-tauri/src/config/verge.rs @@ -262,13 +262,13 @@ impl IVerge { } if needs_fix { - logging!(info, Type::Config, "正在保存修正后的配置文件..."); + logging!(debug, Type::Config, "正在保存修正后的配置文件..."); help::save_yaml(&config_path, &config, Some("# Clash Verge Config")).await?; logging!(info, Type::Config, "配置文件修正完成，需要重新加载配置"); Self::reload_config_after_fix(config).await; } else { - logging!(info, Type::Config, "clash_core配置验证通过: {:?}", config.clash_core); + logging!(debug, Type::Config, "clash_core配置验证通过: {:?}", config.clash_core); } Ok(()) @@ -305,12 +305,12 @@ impl IVerge { config } Err(err) => { - logging!(error, Type::Config, "{err}"); + logging!(error, Type::Config, "failed to read verge config: {err:#}"); Self::template() } }, Err(err) => { - logging!(error, Type::Config, "{err}"); + logging!(error, Type::Config, "failed to get verge config path: {err:#}"); Self::template() } } diff --git a/src-tauri/src/core/logger.rs b/src-tauri/src/core/logger.rs index 6d4529c55..66d1f68c0 100644 --- a/src-tauri/src/core/logger.rs +++ b/src-tauri/src/core/logger.rs @@ -1,236 +1,61 @@ -use std::{ - str::FromStr as _, - sync::{ - Arc, - atomic::{AtomicU64, AtomicUsize, Ordering}, - }, -}; - -use anyhow::{Result, bail}; -use clash_verge_logging::{Type, logging}; -use compact_str::CompactString; -use flexi_logger::{ - Cleanup, Criterion, DeferredNow, FileSpec, LogSpecBuilder, LogSpecification, LoggerHandle, - writers::{FileLogWriter, FileLogWriterBuilder, LogWriter as _}, -}; -use log::{Level, LevelFilter, Record}; -use parking_lot::{Mutex, RwLock}; +use anyhow::Result; +use clash_verge_logging::{LoggerConfig, Type, logging}; use crate::{ core::{CoreManager, manager::RunningMode, service}, - singleton, - utils::dirs::{self, sidecar_log_dir}, + utils::dirs, }; +pub use clash_verge_logging::Logger; + const fn should_sync_service_writer(running_mode: RunningMode) -> bool { matches!(running_mode, RunningMode::Service) } -pub struct Logger { - handle: Arc>>, - sidecar_file_writer: Arc>>, - log_level: Arc>, - log_max_size: AtomicU64, - log_max_count: AtomicUsize, -} - -impl Default for Logger { - fn default() -> Self { - Self { - handle: Arc::new(Mutex::new(None)), - sidecar_file_writer: Arc::new(RwLock::new(None)), - log_level: Arc::new(RwLock::new(LevelFilter::Info)), - log_max_size: AtomicU64::new(128), - log_max_count: AtomicUsize::new(8), - } - } -} - -singleton!(Logger, LOGGER); - -impl Logger { - fn new() -> Self { - Self::default() - } - - pub async fn init(&self) -> Result<()> { - let (log_level, log_max_size, log_max_count) = { - let verge_guard = crate::config::Config::verge().await; - let verge = verge_guard.latest_arc(); - ( - verge.get_log_level(), - verge.app_log_max_size.unwrap_or(128), - verge.app_log_max_count.unwrap_or(8), - ) - }; - let log_level = std::env::var("RUST_LOG") - .ok() - .and_then(|v| log::LevelFilter::from_str(&v).ok()) - .unwrap_or(log_level); - *self.log_level.write() = log_level; - self.log_max_size.store(log_max_size, Ordering::SeqCst); - self.log_max_count.store(log_max_count, Ordering::SeqCst); - - #[cfg(not(any(feature = "tauri-dev", feature = "tokio-trace")))] - { - let log_spec = Self::generate_log_spec(log_level); - let log_dir = dirs::app_logs_dir()?; - let logger = flexi_logger::Logger::with(log_spec) - .log_to_file(FileSpec::default().directory(log_dir).basename("")) - .duplicate_to_stdout(log_level.into()) - .format(clash_verge_logger::console_format) - .format_for_files(clash_verge_logger::file_format_with_level) - .rotate( - Criterion::Size(log_max_size * 1024), - flexi_logger::Naming::TimestampsCustomFormat { - current_infix: Some("latest"), - format: "%Y-%m-%d_%H-%M-%S", - }, - Cleanup::KeepLogFiles(log_max_count), - ); - - let mut filter_modules = vec!["wry", "tokio_tungstenite", "tungstenite"]; - #[cfg(not(feature = "tracing"))] - filter_modules.push("tauri"); - #[cfg(feature = "tracing")] - filter_modules.extend(["tauri_plugin_mihomo", "kode_bridge"]); - let logger = logger.filter(Box::new(clash_verge_logging::ModuleFilter::new( - filter_modules, - Some(vec!["tauri_plugin_mihomo"]), - ))); - - let handle = logger.start()?; - *self.handle.lock() = Some(handle); - } - - let sidecar_file_writer = self.generate_sidecar_writer()?; - *self.sidecar_file_writer.write() = Some(sidecar_file_writer); - - std::panic::set_hook(Box::new(move |info| { - // Capture both common panic payload types instead of logging String payloads as unknown. - // This global hook covers panics after logger init; early setup panics are handled separately. - let payload = info - .payload() - .downcast_ref::<&str>() - .map(|s| (*s).to_string()) - .or_else(|| info.payload().downcast_ref::().cloned()) - .unwrap_or_else(|| "Unknown panic payload".to_string()); - let location = info - .location() - .map(|loc| format!("{}:{}", loc.file(), loc.line())) - .unwrap_or_else(|| "Unknown location".to_string()); - logging!(error, Type::System, "Panic occurred at {}: {}", location, payload); - if let Some(h) = Self::global().handle.lock().as_ref() { - h.flush(); - std::thread::sleep(std::time::Duration::from_millis(100)); - } - })); - - Ok(()) - } - - fn generate_log_spec(log_level: LevelFilter) -> LogSpecification { - let mut spec = LogSpecBuilder::new(); - let log_level = std::env::var("RUST_LOG") - .ok() - .and_then(|v| log::LevelFilter::from_str(&v).ok()) - .unwrap_or(log_level); - spec.default(log_level); - #[cfg(feature = "tracing")] - spec.module("tauri", log::LevelFilter::Debug) - .module("wry", log::LevelFilter::Off) - .module("tauri_plugin_mihomo", log::LevelFilter::Off); - spec.build() - } - - fn generate_file_log_writer(&self) -> Result { - let log_dir = dirs::app_logs_dir()?; - let log_max_size = self.log_max_size.load(Ordering::SeqCst); - let log_max_count = self.log_max_count.load(Ordering::SeqCst); - let flwb = FileLogWriter::builder(FileSpec::default().directory(log_dir).basename("")).rotate( - Criterion::Size(log_max_size * 1024), - flexi_logger::Naming::TimestampsCustomFormat { - current_infix: Some("latest"), - format: "%Y-%m-%d_%H-%M-%S", - }, - Cleanup::KeepLogFiles(log_max_count), - ); - Ok(flwb) - } - - /// only update app log level - pub fn update_log_level(&self, level: LevelFilter) -> Result<()> { - *self.log_level.write() = level; - let log_level = self.log_level.read().to_owned(); - if let Some(handle) = self.handle.lock().as_mut() { - let log_spec = Self::generate_log_spec(log_level); - handle.set_new_spec(log_spec); - handle.adapt_duplication_to_stdout(log_level.into())?; - } else { - bail!("failed to get logger handle, make sure it init"); - }; - Ok(()) - } - - /// update app and mihomo core log config - pub async fn update_log_config(&self, log_max_size: u64, log_max_count: usize) -> Result<()> { - self.log_max_size.store(log_max_size, Ordering::SeqCst); - self.log_max_count.store(log_max_count, Ordering::SeqCst); - if let Some(handle) = self.handle.lock().as_ref() { - let log_file_writer = self.generate_file_log_writer()?; - handle.reset_flw(&log_file_writer)?; - } else { - bail!("failed to get logger handle, make sure it init"); - }; - let sidecar_writer = self.generate_sidecar_writer()?; - *self.sidecar_file_writer.write() = Some(sidecar_writer); - - // The service writer is auxiliary to the local logger. Synchronize it only - // for an active service session and do not roll back local settings on failure. - if should_sync_service_writer(*CoreManager::global().get_running_mode()) - && let Err(error) = service::update_writer_by_service(&clash_verge_service_ipc::WriterConfig { - directory: String::new(), - max_log_size: log_max_size * 1024, - max_log_files: log_max_count, - }) - .await - { - logging!(warn, Type::Service, "failed to update service writer config: {error:#}"); - } - - Ok(()) - } - - fn generate_sidecar_writer(&self) -> Result { - let sidecar_log_dir = sidecar_log_dir()?; - let log_max_size = self.log_max_size.load(Ordering::SeqCst); - let log_max_count = self.log_max_count.load(Ordering::SeqCst); - Ok(FileLogWriter::builder( - FileSpec::default() - .directory(sidecar_log_dir) - .basename("sidecar") - .suppress_timestamp(), +async fn logger_config() -> Result { + let (level, max_size, max_count) = { + let verge_guard = crate::config::Config::verge().await; + let verge = verge_guard.latest_arc(); + ( + verge.get_log_level(), + verge.app_log_max_size.unwrap_or(128), + verge.app_log_max_count.unwrap_or(8), ) - .format(clash_verge_logger::file_format_without_level) - .rotate( - Criterion::Size(log_max_size * 1024), - flexi_logger::Naming::TimestampsCustomFormat { - current_infix: Some("latest"), - format: "%Y-%m-%d_%H-%M-%S", - }, - Cleanup::KeepLogFiles(log_max_count), - ) - .try_build()?) + }; + Ok(LoggerConfig { + level, + max_size_kb: max_size, + max_count, + log_dir: dirs::app_logs_dir()?, + sidecar_log_dir: dirs::sidecar_log_dir()?, + }) +} + +/// Initializes the logging stack. The devtools plugin installs its own global +/// subscriber; in that mode only the sidecar writer and panic hook are set up. +pub async fn init() -> Result<()> { + let cfg = logger_config().await?; + #[cfg(not(feature = "tauri-dev"))] + Logger::global().init(&cfg)?; + Logger::global().init_sidecar(&cfg)?; + Ok(()) +} + +pub async fn update_log_config(log_max_size: u64, log_max_count: usize) -> Result<()> { + Logger::global().update_log_config(log_max_size, log_max_count)?; + + // The service writer is auxiliary to the local logger. Synchronize it only + // for an active service session and do not roll back local settings on failure. + if should_sync_service_writer(*CoreManager::global().get_running_mode()) + && let Err(error) = service::update_writer_by_service(&clash_verge_service_ipc::WriterConfig { + directory: String::new(), + max_log_size: log_max_size * 1024, + max_log_files: log_max_count, + }) + .await + { + logging!(warn, Type::Service, "failed to update service writer config: {error:#}"); } - pub fn writer_sidecar_log(&self, level: Level, message: &CompactString) { - if let Some(writer) = self.sidecar_file_writer.read().as_ref() { - let mut now = DeferredNow::default(); - let args = format_args!("{}", message); - let record = Record::builder().args(args).level(level).target("sidecar").build(); - let _ = writer.write(&mut now, &record); - } else { - logging!(error, Type::System, "failed to get sidecar file log writer"); - } - } + Ok(()) } diff --git a/src-tauri/src/core/manager/config.rs b/src-tauri/src/core/manager/config.rs index 5e4f0eb59..f6b1d2634 100644 --- a/src-tauri/src/core/manager/config.rs +++ b/src-tauri/src/core/manager/config.rs @@ -90,7 +90,7 @@ async fn ask_to_stage(path: &std::path::Path) -> StageAttempt { match crate::core::service::stage_runtime_by_service(path).await { Ok(StageRequest::Answered(outcome)) => StageAttempt::Answered(outcome), Ok(StageRequest::Refused { code, message }) => { - let message = message.to_string().into(); + let message = message.into(); if StageRequest::is_about_the_bundle(code) { StageAttempt::RefusedTheBundle(message) } else { @@ -103,6 +103,7 @@ async fn ask_to_stage(path: &std::path::Path) -> StageAttempt { /// Confirms one silent request because the service may commit before its reply is lost. /// Re-staging an already committed bundle is idempotent and bounded by `confirm_within`. +#[tracing::instrument(skip_all, level = "debug", fields(confirm_within = ?confirm_within, asks = 1))] async fn stage_with_confirmation(confirm_within: Duration, ask: Ask) -> StageAttempt where Ask: Fn() -> Fut, @@ -117,6 +118,7 @@ where Type::Core, "Staging did not answer ({first}); asking once more before replacing the core" ); + tracing::Span::current().record("asks", 2); match tokio::time::timeout(confirm_within, ask()).await { Ok(StageAttempt::Unanswered(again)) => { StageAttempt::Unanswered(format!("{first}; asked again: {again}").into()) @@ -150,6 +152,7 @@ impl CoreManager { self.update_config_with_force(true).await } + #[tracing::instrument(skip_all, level = "info", fields(force))] pub async fn update_config_with_force(&self, force: bool) -> Result { if handle::Handle::global().is_exiting() { return Ok(ValidationOutcome::Skipped { @@ -158,7 +161,7 @@ impl CoreManager { } if !self.try_start_config_update() { - logging!(info, Type::Core, "Configuration update is already running"); + logging!(debug, Type::Core, "Configuration update is already running"); return Ok(ValidationOutcome::Busy); } defer! { @@ -179,6 +182,7 @@ impl CoreManager { self.perform_config_update(None).await } + #[tracing::instrument(skip_all, level = "info", fields(profile = ?candidate.current, outcome = tracing::field::Empty))] pub(crate) async fn update_config_forced_with_profiles( &self, candidate: &IProfiles, @@ -202,17 +206,23 @@ impl CoreManager { { Ok(outcome) => outcome, Err(error) => { + tracing::Span::current().record("outcome", "rolled_back"); self.restore_profile_config(rollback).await?; return Err(error); } }; if !outcome.is_valid() { + tracing::Span::current().record("outcome", "invalid"); crate::config::profiles::restore_selected_nodes().await; return Ok(Err(outcome)); } match candidate.save_file().await { - Ok(()) => Ok(Ok(guard)), + Ok(()) => { + tracing::Span::current().record("outcome", "committed"); + Ok(Ok(guard)) + } Err(error) => { + tracing::Span::current().record("outcome", "save_rolled_back"); self.restore_profile_config(rollback).await?; Err(error) } @@ -273,7 +283,7 @@ impl CoreManager { F: FnOnce(&mut IRuntime), { if !self.try_start_config_update() { - logging!(info, Type::Core, "Configuration update is already running"); + logging!(debug, Type::Core, "Configuration update is already running"); return Ok(ValidationOutcome::Busy); } defer! { @@ -315,6 +325,7 @@ impl CoreManager { /// Applies through the service, replacing the core when in-place staging is unavailable. /// Caller must hold `lifecycle_lock`. + #[tracing::instrument(skip_all, level = "info", fields(path = %path.display(), outcome = tracing::field::Empty))] async fn apply_config_by_service(&self, path: &std::path::Path) -> Result<()> { match plan_config_application(&self.attempt_staging(path).await) { ConfigApplication::Fail(message) => { @@ -328,7 +339,7 @@ impl CoreManager { } ConfigApplication::ReloadFrom(staged) => match self.reload_config(&staged).await { Ok(()) => { - logging!(info, Type::Core, "Configuration staged and applied by service"); + tracing::Span::current().record("outcome", "staged"); return Ok(()); } Err(err) => logging!( @@ -341,7 +352,7 @@ impl CoreManager { } self.replace_service_core_with_config(path).await?; - logging!(info, Type::Core, "Configuration materialized and applied by service"); + tracing::Span::current().record("outcome", "replaced"); Ok(()) } @@ -353,9 +364,10 @@ impl CoreManager { } /// Reload the Core from `path`, and replace the Core if it will not take it. + #[tracing::instrument(skip_all, level = "info", fields(outcome = tracing::field::Empty))] async fn reload_or_restart(&self, path: &str) -> Result<()> { let Err(err) = self.reload_config(path).await else { - logging!(info, Type::Core, "Configuration applied"); + tracing::Span::current().record("outcome", "reloaded"); return Ok(()); }; @@ -366,7 +378,7 @@ impl CoreManager { ); match self.restart_core_during_config_update().await { Ok(_) => { - logging!(info, Type::Core, "Configuration applied after restart"); + tracing::Span::current().record("outcome", "restarted"); Ok(()) } Err(err) => { diff --git a/src-tauri/src/core/manager/lifecycle.rs b/src-tauri/src/core/manager/lifecycle.rs index 714b4134e..8bb0f6cb8 100644 --- a/src-tauri/src/core/manager/lifecycle.rs +++ b/src-tauri/src/core/manager/lifecycle.rs @@ -317,6 +317,7 @@ impl CoreManager { .await } + #[tracing::instrument(skip_all, level = "info", fields(status = tracing::field::Empty, tun_disabled = false, readiness_generation = tracing::field::Empty))] pub async fn continue_with_sidecar(&self) -> Result<()> { if !self.try_start_config_update() { anyhow::bail!("configuration update is already running"); @@ -329,6 +330,7 @@ impl CoreManager { let config_write = Config::lock_config_write().await; let _life = self.lifecycle_lock.lock().await; let status = SERVICE_MANAGER.current().await; + tracing::Span::current().record("status", tracing::field::debug(&status)); let mode = self.get_running_mode(); if !can_allow_sidecar_for_session(&mode, &status) { anyhow::bail!("Sidecar continuation is not allowed from {mode:?} / {status:?}"); @@ -342,6 +344,7 @@ impl CoreManager { .state() .tun_should_be_disabled(tun_enabled) { + tracing::Span::current().record("tun_disabled", true); Config::disable_tun_and_persist().await?; } Config::generate().await @@ -361,6 +364,7 @@ impl CoreManager { { anyhow::bail!("Sidecar did not become ready"); } + tracing::Span::current().record("readiness_generation", self.current_core_readiness_generation()); self.apply_proxy_after_start().await } .await; @@ -376,6 +380,7 @@ impl CoreManager { Ok(()) } + #[tracing::instrument(skip_all, level = "info", fields(readiness_generation = tracing::field::Empty))] pub async fn uninstall_service_and_start_sidecar(&self) -> Result<()> { if !self.try_start_config_update() { anyhow::bail!("configuration update is already running"); @@ -413,6 +418,7 @@ impl CoreManager { { anyhow::bail!("Sidecar did not become ready after service uninstall"); } + tracing::Span::current().record("readiness_generation", self.current_core_readiness_generation()); self.apply_proxy_after_start().await }, ) @@ -456,6 +462,7 @@ impl CoreManager { .await } + #[tracing::instrument(skip_all, level = "info", fields(mode = ?*self.get_running_mode(), readiness_generation = self.current_core_readiness_generation(), owner_generation = crate::core::service::owner_monitor_generation()))] pub(crate) async fn apply_proxy_after_start(&self) -> Result<()> { let expectation = ProxyRestoreExpectation::capture( *self.get_running_mode(), @@ -519,6 +526,7 @@ impl CoreManager { Ok(()) } + #[tracing::instrument(skip_all, level = "info", fields(decision = tracing::field::Empty))] async fn start_core_inner(&self) -> Result<()> { if Handle::global().is_exiting() { return Ok(()); @@ -526,7 +534,7 @@ impl CoreManager { if !matches!(*self.get_running_mode(), RunningMode::NotRunning) { logging!( - info, + debug, Type::Core, "start_core called while a core is running; treated as no-op" ); @@ -534,6 +542,7 @@ impl CoreManager { } let startup = self.prepare_startup().await; + tracing::Span::current().record("decision", tracing::field::debug(&startup)); if matches!(startup, StartupDecision::Wait) { self.rollback_failed_start().await; return Ok(()); @@ -563,6 +572,7 @@ impl CoreManager { result } + #[tracing::instrument(skip_all, level = "info", fields(mode = ?*self.get_running_mode()))] pub async fn stop_core(&self) -> Result<()> { let _life = self.lifecycle_lock.lock().await; self.controlled_stop_core_inner().await @@ -594,7 +604,7 @@ impl CoreManager { } async fn stop_core_unprepared_inner(&self) -> Result<()> { - CLASH_LOGGER.clear_logs().await; + CLASH_LOGGER.clear_logs(); match *self.get_running_mode() { RunningMode::Service => self.stop_core_by_service().await, RunningMode::Sidecar => { @@ -605,6 +615,7 @@ impl CoreManager { } } + #[tracing::instrument(skip_all, level = "info")] pub async fn restart_core(&self) -> Result<()> { if !self.try_start_config_update() { anyhow::bail!("configuration update is already running"); @@ -617,7 +628,6 @@ impl CoreManager { pub(crate) async fn restart_core_during_config_update(&self) -> Result<()> { let _life = self.lifecycle_lock.lock().await; - logging!(info, Type::Core, "Restarting core"); let proxy_intent = self.proxy_stop_intent().await; run_core_replacement_transition( || self.controlled_stop_core_with_intent(proxy_intent), @@ -635,6 +645,7 @@ impl CoreManager { .await } + #[tracing::instrument(skip_all, level = "info", fields(core = %clash_core))] pub async fn change_core(&self, clash_core: &String) -> Result<()> { if !IVerge::VALID_CLASH_CORES.contains(&clash_core.as_str()) { anyhow::bail!("invalid clash core: {clash_core}"); @@ -757,6 +768,7 @@ impl CoreManager { } #[cfg(target_os = "windows")] + #[tracing::instrument(skip_all, level = "debug", fields(outcome = tracing::field::Empty))] async fn try_handoff_sidecar_to_service(&self) -> HandoffOutcome { // Before probing: a probe reply records an observation, which clears sidecar_allowed. if crate::core::runstate::RUN_STATE.state().sidecar_allowed { diff --git a/src-tauri/src/core/manager/mod.rs b/src-tauri/src/core/manager/mod.rs index c7b5b4191..79fc511fe 100644 --- a/src-tauri/src/core/manager/mod.rs +++ b/src-tauri/src/core/manager/mod.rs @@ -4,8 +4,7 @@ mod state; use anyhow::Result; use arc_swap::{ArcSwap, ArcSwapOption}; -use clash_verge_logger::AsyncLogger; -use clash_verge_logging::{Type, logging}; +use clash_verge_logging::{LogRing, Type, logging}; use once_cell::sync::Lazy; use std::{ fmt, @@ -22,7 +21,7 @@ use crate::singleton; #[cfg(target_os = "windows")] use std::os::windows::io::OwnedHandle; -pub(crate) static CLASH_LOGGER: Lazy> = Lazy::new(|| Arc::new(AsyncLogger::new())); +pub(crate) static CLASH_LOGGER: Lazy> = Lazy::new(|| Arc::new(LogRing::new())); tokio::task_local! { static PROFILE_SELECTIONS_PENDING_COMMIT: bool; @@ -161,6 +160,10 @@ impl CoreManager { /// Run State derives PAC availability and the outward mode mirror from this; callers must /// not set those alongside. pub fn core_started(&self, mode: RunningMode) { + let previous = *self.get_running_mode(); + if previous != mode { + logging!(info, Type::Core, "Core running mode changed: {previous} -> {mode}"); + } self.run_state.core_started(mode); } @@ -169,6 +172,10 @@ impl CoreManager { /// Core readiness is invalidated here rather than inside Run State because readiness /// belongs to the process this manager supervises. pub fn core_stopped(&self) { + let previous = *self.get_running_mode(); + if !matches!(previous, RunningMode::NotRunning) { + logging!(info, Type::Core, "Core running mode changed: {previous} -> NotRunning"); + } self.invalidate_core_readiness(); self.run_state.core_stopped(); } @@ -244,6 +251,7 @@ impl CoreManager { self.config_update_in_progress.store(false, Ordering::Release); } + #[tracing::instrument(skip_all, level = "info", fields(retries = 0))] pub async fn init(&self) -> Result { const MAX_PORT_FALLBACK_RETRIES: usize = 3; @@ -266,10 +274,11 @@ impl CoreManager { match crate::config::Config::resolve_startup_mixed_port().await { Ok(true) => { retries += 1; + tracing::Span::current().record("retries", retries); logging!( warn, Type::Core, - "Retrying core startup after mixed proxy port fallback ({}/{})", + "Retrying core startup after mixed proxy port fallback ({}/{}): {start_error:#}", retries, MAX_PORT_FALLBACK_RETRIES ); diff --git a/src-tauri/src/core/manager/state.rs b/src-tauri/src/core/manager/state.rs index fe5cc91c7..c90831867 100644 --- a/src-tauri/src/core/manager/state.rs +++ b/src-tauri/src/core/manager/state.rs @@ -10,7 +10,6 @@ use crate::{ }; use anyhow::{Context as _, Result}; use clash_verge_logging::Type; -use compact_str::CompactString; use log::Level; use scopeguard::defer; use std::path::Path; @@ -49,7 +48,16 @@ where for attempt in 0..max_attempts { match probe().await { Ok(()) => return Ok(()), - Err(error) => last_error = Some(error), + Err(error) => { + logging!( + debug, + Type::Core, + "sidecar readiness probe {}/{} failed: {error:#}", + attempt + 1, + max_attempts + ); + last_error = Some(error); + } } if attempt + 1 < max_attempts { tokio::time::sleep(retry_delay).await; @@ -80,16 +88,16 @@ use { }; impl CoreManager { - pub async fn get_clash_logs(&self) -> Result> { + pub async fn get_clash_logs(&self) -> Result> { match *self.get_running_mode() { RunningMode::Service => service::get_clash_logs_by_service().await, - RunningMode::Sidecar => Ok(CLASH_LOGGER.get_logs().await), + RunningMode::Sidecar => Ok(CLASH_LOGGER.get_logs()), RunningMode::NotRunning => Ok(Vec::new()), } } + #[tracing::instrument(skip_all, level = "info", fields(pid = tracing::field::Empty))] pub(super) async fn start_core_by_sidecar(&self) -> Result<()> { - logging!(info, Type::Core, "Starting core in sidecar mode"); self.core_stopped(); let sidecar_ipc = dirs::sidecar_ipc_path()?; @@ -158,7 +166,7 @@ impl CoreManager { }; let pid = child.pid(); - logging!(trace, Type::Core, "Sidecar started with PID: {}", pid); + tracing::Span::current().record("pid", pid); let readiness = poll_sidecar_readiness(SIDECAR_READINESS_ATTEMPTS, SIDECAR_READINESS_INTERVAL, || async { tokio::time::timeout(SIDECAR_READINESS_PROBE_TIMEOUT, async { @@ -192,22 +200,22 @@ impl CoreManager { match event { tauri_plugin_shell::process::CommandEvent::Stdout(line) | tauri_plugin_shell::process::CommandEvent::Stderr(line) => { - let message = CompactString::from(&*String::from_utf8_lossy(&line)); + let message = String::from_utf8_lossy(&line).into_owned(); Logger::global().writer_sidecar_log(Level::Error, &message); - CLASH_LOGGER.append_log(message).await; + CLASH_LOGGER.append_log(message); } tauri_plugin_shell::process::CommandEvent::Terminated(term) => { let manager = Self::global(); let _ = manager.invalidate_core_readiness_if(core_readiness_generation); let message = if let Some(code) = term.code { - CompactString::from(format!("Process terminated with code: {}", code)) + format!("Process terminated with code: {}", code) } else if let Some(signal) = term.signal { - CompactString::from(format!("Process terminated by signal: {}", signal)) + format!("Process terminated by signal: {}", signal) } else { - CompactString::from("Process terminated") + String::from("Process terminated") }; Logger::global().writer_sidecar_log(Level::Info, &message); - CLASH_LOGGER.clear_logs().await; + CLASH_LOGGER.clear_logs(); manager.clear_terminated_sidecar(pid).await; break; } @@ -222,7 +230,6 @@ impl CoreManager { /// Terminates the sidecar after its caller has successfully cleared the /// system proxy. pub(super) fn stop_core_by_sidecar_unprepared(&self) { - logging!(info, Type::Core, "Stopping sidecar"); defer! { self.core_stopped(); } @@ -234,27 +241,16 @@ impl CoreManager { // Setting the job handle to None clears the stored handle and // closes the previous Windows job handle in `set_job_handle`. self.set_job_handle(None); - logging!( - trace, - Type::Core, - "Closed job handle for sidecar process (PID: {})", - pid - ); + let _ = pid; } - let result = child.kill(); - logging!( - trace, - Type::Core, - "Sidecar stopped (PID: {:?}, Result: {:?})", - pid, - result - ); + if let Err(error) = child.kill() { + logging!(warn, Type::Core, "failed to terminate sidecar PID {pid}: {error:#}"); + } } } pub(super) async fn start_core_by_service(&self) -> Result<()> { - logging!(info, Type::Core, "Starting core in service mode"); self.core_starting(); let service_ipc = dirs::ipc_path()?; let config_file = Config::generate_file(crate::config::ConfigType::Run).await?; @@ -265,6 +261,7 @@ impl CoreManager { self.start_core_by_service_with_config(&config_file).await } + #[tracing::instrument(skip_all, level = "info", fields(config_file = %config_file.display()))] pub(super) async fn start_core_by_service_with_config(&self, config_file: &Path) -> Result<()> { // 交接时等待 sidecar 释放 ext-controller 通道。 #[cfg(target_os = "windows")] @@ -283,10 +280,9 @@ impl CoreManager { logging!( warn, Type::Core, - "service start attempt {}/{} failed: {}", + "service start attempt {}/{} failed: {e:#}", attempt + 1, - timing::SERVICE_START_RETRIES, - e + timing::SERVICE_START_RETRIES ); last_err = Some(e); tokio::time::sleep(timing::SERVICE_START_RETRY_DELAY).await; @@ -307,7 +303,6 @@ impl CoreManager { } pub(super) async fn stop_core_by_service(&self) -> Result<()> { - logging!(info, Type::Core, "Stopping service"); service::stop_core_by_service().await?; self.core_stopped(); Ok(()) diff --git a/src-tauri/src/core/network_watch.rs b/src-tauri/src/core/network_watch.rs index cc054f17b..2da416cf0 100644 --- a/src-tauri/src/core/network_watch.rs +++ b/src-tauri/src/core/network_watch.rs @@ -43,6 +43,11 @@ pub fn start() { }; CFRunLoop::get_main().add_source(&source, unsafe { kCFRunLoopCommonModes }); ARMED.store(true, Ordering::Release); + logging!( + debug, + Type::Core, + "network watch armed; the system proxy is re-applied on network changes" + ); } fn on_change(_: SCDynamicStore, _: CFArray, (): &mut ()) { diff --git a/src-tauri/src/core/proxy_control.rs b/src-tauri/src/core/proxy_control.rs index addc064a5..538cc6dcf 100644 --- a/src-tauri/src/core/proxy_control.rs +++ b/src-tauri/src/core/proxy_control.rs @@ -471,10 +471,13 @@ fn table_effect(result: &Result<()>) -> TableEffect<'_> { } } +#[tracing::instrument(skip_all, level = "info", fields(route = tracing::field::Empty))] pub async fn apply() -> Result<()> { let running_mode = CoreManager::global().get_running_mode(); let verge = Config::verge().await.latest_arc(); - let result = match proxy_backend_route(cfg!(target_os = "macos"), &running_mode) { + let route = proxy_backend_route(cfg!(target_os = "macos"), &running_mode); + tracing::Span::current().record("route", tracing::field::debug(&route)); + let result = match route { ProxyBackendRoute::Local => match Sysopt::global().update_sysproxy().await { Ok(()) => Ok(()), Err(error) => Err(classify_local_apply_failure(error).await), @@ -520,7 +523,7 @@ pub async fn clear() -> Result<()> { /// A failed system call is usually a transient RPC hiccup, so give it a few tries. async fn clear_with_retry() -> Result<()> { - for _ in 1..CLEAR_ATTEMPTS { + for attempt in 1..CLEAR_ATTEMPTS { match clear_inner().await { Err(error) if matches!( @@ -531,7 +534,7 @@ async fn clear_with_retry() -> Result<()> { logging!( warn, Type::Core, - "clearing the system proxy failed; retrying: {error:#}" + "clearing the system proxy failed (attempt {attempt}/{CLEAR_ATTEMPTS}); retrying: {error:#}" ); tokio::time::sleep(CLEAR_RETRY_DELAY).await; } @@ -541,9 +544,12 @@ async fn clear_with_retry() -> Result<()> { clear_inner().await } +#[tracing::instrument(skip_all, level = "info", fields(route = tracing::field::Empty))] async fn clear_inner() -> Result<()> { let running_mode = CoreManager::global().get_running_mode(); - match proxy_backend_route(cfg!(target_os = "macos"), &running_mode) { + let route = proxy_backend_route(cfg!(target_os = "macos"), &running_mode); + tracing::Span::current().record("route", tracing::field::debug(&route)); + match route { ProxyBackendRoute::Local => Sysopt::global().reset_sysproxy().await.map_err(classify_local_failure), ProxyBackendRoute::Service => { SERVICE_PROXY_OPERATIONS @@ -599,13 +605,16 @@ pub async fn refresh_guard() -> Result<()> { .await { Ok(true) => consecutive_failures = 0, - Ok(false) => break, + Ok(false) => { + logging!(debug, Type::Core, "proxy guard superseded (generation {generation})"); + break; + } Err(error) => { consecutive_failures += 1; logging!( warn, Type::Core, - "failed to refresh system proxy through Service ({}/{}): {:#}", + "failed to refresh system proxy through Service (generation {generation}, {}/{}): {:#}", consecutive_failures, GUARD_FAILURES_BEFORE_STOPPING, error diff --git a/src-tauri/src/core/service.rs b/src-tauri/src/core/service.rs index 5514a31f1..0d0e3a3cb 100644 --- a/src-tauri/src/core/service.rs +++ b/src-tauri/src/core/service.rs @@ -23,7 +23,6 @@ use clash_verge_service_ipc::{ MacosProxyConfig, OwnerSessionProof, ProxyApplyOutcome, RuntimeBundle, ServiceErrorCode, StageRuntimeOutcome, StartClashRequest, WriterConfig, }; -use compact_str::CompactString; use once_cell::sync::Lazy; use parking_lot::Mutex; use std::{ @@ -74,13 +73,19 @@ pub(crate) fn clear_active_service_session() { } /// Probes staging support without failing startup when the fast path is unavailable. +#[tracing::instrument(skip_all, level = "info", fields(supported = tracing::field::Empty))] async fn probe_runtime_staging_support() -> bool { match clash_verge_service_ipc::get_version().await { - Ok(response) if response.code == 0 => response - .data - .as_ref() - .is_some_and(clash_verge_service_ipc::ProtocolInfo::supports_runtime_staging), + Ok(response) if response.code == 0 => { + let supported = response + .data + .as_ref() + .is_some_and(clash_verge_service_ipc::ProtocolInfo::supports_runtime_staging); + tracing::Span::current().record("supported", supported); + supported + } Ok(response) => { + tracing::Span::current().record("supported", false); logging!( warn, Type::Service, @@ -91,6 +96,7 @@ async fn probe_runtime_staging_support() -> bool { false } Err(error) => { + tracing::Span::current().record("supported", false); logging!( warn, Type::Service, @@ -818,7 +824,7 @@ async fn collect_service_runtime_bundle(config_file: &Path) -> Result Result 0 { return Ok(StageRequest::Refused { code: response.code, - message: response.message.into(), + message: response.message, }); } response @@ -851,8 +857,8 @@ pub(super) async fn stage_runtime_by_service(config_file: &Path) -> Result Result<()> { - logging!(info, Type::Service, "尝试使用现有服务启动核心"); clear_active_service_session(); let credentials = current_owner_credentials()?; @@ -867,14 +873,23 @@ pub(super) async fn start_with_existing_service(config_file: &Path) -> Result<() let response = match clash_verge_service_ipc::start_clash(&credentials, &request).await { Ok(response) => response, Err(error) => { + tracing::Span::current().record("outcome", "ipc-unreachable"); start_owner_monitor(); return Err(error).context("无法连接到Clash Verge Service"); } }; if response.code > 0 { + tracing::Span::current().record("code", response.code); + tracing::Span::current().record("outcome", "refused"); let err_msg = response.message; - logging!(error, Type::Service, "启动核心失败: {}", err_msg); + logging!( + error, + Type::Service, + "启动核心失败 (code {}): {}", + response.code, + err_msg + ); start_owner_monitor(); bail!( "failed to start Service core at {}: {err_msg}", @@ -883,7 +898,9 @@ pub(super) async fn start_with_existing_service(config_file: &Path) -> Result<() } let result = response.data.context("Clash Verge Service 未返回会话信息")?; + tracing::Span::current().record("generation", result.session.generation); let supports_runtime_staging = probe_runtime_staging_support().await; + tracing::Span::current().record("staging", supports_runtime_staging); *ACTIVE_SERVICE_SESSION.lock() = Some(ActiveServiceSession { proof: OwnerSessionProof { generation: result.session.generation, @@ -894,14 +911,18 @@ pub(super) async fn start_with_existing_service(config_file: &Path) -> Result<() // PAC follows the Running Mode; the caller opens it via `core_started(Service)`. start_owner_monitor(); - logging!(info, Type::Service, "服务成功启动核心"); + tracing::Span::current().record("outcome", "started"); + logging!( + info, + Type::Service, + "服务成功启动核心 (session generation {})", + result.session.generation + ); Ok(()) } // 以服务启动core pub(super) async fn run_core_by_service(config_file: &Path) -> Result<()> { - logging!(info, Type::Service, "正在尝试通过服务启动核心"); - SERVICE_MANAGER.refresh().await?; let status = SERVICE_MANAGER.current().await; @@ -922,9 +943,8 @@ where (captured, operation().await) } -pub(super) async fn get_clash_logs_by_service() -> Result> { - logging!(info, Type::Service, "正在获取服务模式下的 Clash 日志"); - +pub(super) async fn get_clash_logs_by_service() -> Result> { + // Frontend-polled: no per-call logging here. let credentials = current_owner_credentials()?; let (generation, response) = capture_generation_before(&OWNER_MONITOR_GENERATION, || { clash_verge_service_ipc::get_clash_logs(&credentials) @@ -937,11 +957,9 @@ pub(super) async fn get_clash_logs_by_service() -> Result> { recover_after_owner_loss(generation, OwnerRecoveryReason::Displaced).await; } let err_msg = response.message; - logging!(error, Type::Service, "获取服务模式下的 Clash 日志失败: {}", err_msg); bail!(err_msg); } - logging!(info, Type::Service, "成功获取服务模式下的 Clash 日志"); Ok(response.data.unwrap_or_default()) } @@ -970,8 +988,8 @@ pub(crate) async fn get_clash_log_snapshot_by_service() -> Result { } /// 通过服务停止core +#[tracing::instrument(skip_all, level = "info", fields(code = tracing::field::Empty, outcome = tracing::field::Empty))] pub(super) async fn stop_core_by_service() -> Result<()> { - logging!(info, Type::Service, "通过服务停止核心 (IPC)"); cancel_owner_monitors(); let credentials = match current_owner_credentials() { @@ -1007,11 +1025,20 @@ pub(super) async fn stop_core_by_service() -> Result<()> { start_owner_monitor(); } let err_msg = response.message; - logging!(error, Type::Service, "停止核心失败: {}", err_msg); + tracing::Span::current().record("code", response.code); + tracing::Span::current().record("outcome", "refused"); + logging!( + error, + Type::Service, + "停止核心失败 (code {}): {}", + response.code, + err_msg + ); bail!(err_msg); } clear_active_service_session(); + tracing::Span::current().record("outcome", "stopped"); logging!(info, Type::Service, "服务成功停止核心"); Ok(()) } @@ -1023,6 +1050,13 @@ pub(crate) async fn update_writer_by_service(writer: &WriterConfig) -> Result<() .await .context("无法连接到Clash Verge Service")?; if response.code > 0 { + logging!( + warn, + Type::Service, + "update writer rejected by service: code={}, {}", + response.code, + response.message + ); bail!(response.message); } Ok(()) @@ -1042,6 +1076,13 @@ pub(super) async fn set_system_proxy_by_service_with_session( .await .context("无法连接到Clash Verge Service")?; if response.code > 0 { + logging!( + warn, + Type::Service, + "set system proxy rejected by service: code={}, {}", + response.code, + response.message + ); bail!(response.message); } response.data.context("Clash Verge Service 未返回系统代理结果") @@ -1074,13 +1115,24 @@ const SUSTAINED_OWNER_SAMPLES: u8 = 3; fn start_owner_monitor() { let generation = OWNER_MONITOR_GENERATION.fetch_add(1, Ordering::AcqRel) + 1; AsyncHandler::spawn(move || async move { + logging!(debug, Type::Service, "owner monitor started (generation {generation})"); let mut watch = OwnerWatch::new(); loop { tokio::time::sleep(OWNER_MONITOR_INTERVAL).await; if OWNER_MONITOR_GENERATION.load(Ordering::Acquire) != generation { + logging!( + debug, + Type::Service, + "owner monitor superseded (generation {generation})" + ); break; } if !matches!(*CoreManager::global().get_running_mode(), RunningMode::Service) { + logging!( + debug, + Type::Service, + "owner monitor stopped; core no longer in service mode (generation {generation})" + ); break; } @@ -1091,7 +1143,7 @@ fn start_owner_monitor() { logging!( warn, Type::Service, - "service owner status unavailable for {SUSTAINED_OWNER_SAMPLES} samples; \ + "service owner status unavailable for {SUSTAINED_OWNER_SAMPLES} samples (generation {generation}); \ preserving local proxy state while the core endpoint still answers" ); } @@ -1199,6 +1251,7 @@ fn claim_owner_recovery_generation(generation: &AtomicU64, captured_generation: .map(|_| recovery_generation) } +#[tracing::instrument(skip_all, level = "info", fields(reason = ?reason))] async fn recover_after_owner_loss_while_locked(reason: OwnerRecoveryReason) { logging!( warn, @@ -1215,10 +1268,15 @@ async fn recover_after_owner_loss_while_locked(reason: OwnerRecoveryReason) { } let mut last_error = None; - for _ in 0..3 { + for attempt in 1..=3 { match proxy_control::clear().await { Ok(()) => return, Err(error) => { + logging!( + warn, + Type::Service, + "proxy clear attempt {attempt}/3 after owner loss failed: {error:#}" + ); last_error = Some(error); tokio::time::sleep(Duration::from_millis(100)).await; } @@ -1228,24 +1286,35 @@ async fn recover_after_owner_loss_while_locked(reason: OwnerRecoveryReason) { logging!( error, Type::Service, - "failed to clear local proxy after owner loss: {error}" + "failed to clear local proxy after owner loss: {error:#}" ); } } /// Waits for a repaired service, preserving readable rejection details but classifying sustained /// silence as unavailable. +#[tracing::instrument(skip_all, level = "info", fields(attempts = tracing::field::Empty, interval_ms = tracing::field::Empty, outcome = tracing::field::Empty))] async fn wait_for_service_ipc() -> Result<()> { const CONTEXT: &str = "service IPC did not become available"; let config = ServiceManager::config(); + let span = tracing::Span::current(); + span.record("attempts", config.max_retries); + span.record("interval_ms", config.retry_delay.as_millis() as u64); match RUN_STATE.await_ready(config.max_retries, config.retry_delay).await { - Ok(_) => Ok(()), + Ok(_) => { + tracing::Span::current().record("outcome", "ready"); + Ok(()) + } Err(ReadyWaitError::Unreachable(error)) => { + tracing::Span::current().record("outcome", "unreachable"); RUN_STATE.observe(ServiceHealth::Unavailable(format!("{CONTEXT}: {error:#}"))); Err(error).context(CONTEXT) } - Err(ReadyWaitError::Rejected(error)) => Err(error).context(CONTEXT), + Err(ReadyWaitError::Rejected(error)) => { + tracing::Span::current().record("outcome", "rejected"); + Err(error).context(CONTEXT) + } } } diff --git a/src-tauri/src/core/timer.rs b/src-tauri/src/core/timer.rs index a9a7edee4..45b69bffa 100644 --- a/src-tauri/src/core/timer.rs +++ b/src-tauri/src/core/timer.rs @@ -132,7 +132,7 @@ impl Timer { if let Err(e) = self.refresh().await { self.initialized.store(false, Ordering::SeqCst); - logging_error!(Type::Timer, "Failed to initialize timer: {}", e); + logging!(error, Type::Timer, "Failed to initialize timer: {e:#}"); return Err(e); } @@ -424,7 +424,7 @@ impl Timer { } fn spawn_update_task(uid: String, command_tx: mpsc::UnboundedSender) { - logging!(info, Type::Timer, "Starting timer task: uid={}", uid); + logging!(debug, Type::Timer, "Starting timer task: uid={}", uid); AsyncHandler::spawn(move || async move { Self::wait_until_resolve_done(Duration::from_millis(5000)).await; Self::async_task(&uid).await; @@ -466,8 +466,8 @@ impl Timer { } } + #[tracing::instrument(skip_all, level = "info", fields(uid = %uid))] async fn async_task(uid: &String) { - let task_start = std::time::Instant::now(); logging!(debug, Type::Timer, "Running timer task for profile: {}", uid); run_timer_profile_update_transition( @@ -475,15 +475,9 @@ impl Timer { || feat::update_profile(uid, None, false), |result| match result { Ok(_) => { - logging!( - info, - Type::Timer, - "Timer task completed for uid: {} (took {}ms)", - uid, - task_start.elapsed().as_millis() - ); + logging!(debug, Type::Timer, "timer task completed for uid: {}", uid); } - Err(e) => logging_error!(Type::Timer, "Failed to update profile uid {}: {}", uid, e), + Err(e) => logging_error!(Type::Timer, "Failed to update profile uid {}: {e:#}", uid), }, || Self::emit_update_event(uid, false), ) diff --git a/src-tauri/src/enhance/mod.rs b/src-tauri/src/enhance/mod.rs index ec4464a56..1d57d6240 100644 --- a/src-tauri/src/enhance/mod.rs +++ b/src-tauri/src/enhance/mod.rs @@ -551,7 +551,7 @@ async fn apply_builtin_scripts(mut config: Mapping, clash_core: Option, config = res_config; } Err(err) => { - logging!(error, Type::Core, "builtin script error `{err}`"); + logging!(error, Type::Core, "builtin script error `{err:#}`"); } } } @@ -678,7 +678,7 @@ async fn apply_dns_settings(mut config: Mapping, enable_dns_settings: bool) -> M && hosts_value.is_mapping() { config.insert("hosts".into(), hosts_value.clone()); - logging!(info, Type::Core, "apply hosts configuration"); + logging!(debug, Type::Core, "apply hosts configuration"); } if let Some(dns_value) = dns_config.get("dns") { @@ -686,13 +686,13 @@ async fn apply_dns_settings(mut config: Mapping, enable_dns_settings: bool) -> M let mut dns_mapping = dns_mapping.clone(); ensure_fake_ip_range6(&mut dns_mapping); config.insert("dns".into(), dns_mapping.into()); - logging!(info, Type::Core, "apply dns_config.yaml (dns section)"); + logging!(debug, Type::Core, "apply dns_config.yaml (dns section)"); } } else { let mut dns_config = dns_config; ensure_fake_ip_range6(&mut dns_config); config.insert("dns".into(), dns_config.into()); - logging!(info, Type::Core, "apply dns_config.yaml"); + logging!(debug, Type::Core, "apply dns_config.yaml"); } } } diff --git a/src-tauri/src/enhance/script.rs b/src-tauri/src/enhance/script.rs index 15797fb04..40d151fe0 100644 --- a/src-tauri/src/enhance/script.rs +++ b/src-tauri/src/enhance/script.rs @@ -3,7 +3,7 @@ use crate::process::AsyncHandler; use super::field::{use_lowercase, use_lowercase_owned}; use anyhow::{Error, Result}; use boa_engine::{Context, JsString, JsValue, Source, native_function::NativeFunction}; -use clash_verge_logging::{Type, logging_error}; +use clash_verge_logging::{Type, logging}; use parking_lot::Mutex; use serde_yaml_ng::Mapping; use smartstring::alias::String; @@ -131,7 +131,11 @@ fn use_script_sync(script: String, config: &Mapping, name: &String) -> Result<(M outputs .lock() .push(("exception".into(), "Script execution failed".into())); - logging_error!(Type::Config, "Script execution error: {}. Script name: {}", err, name); + logging!( + error, + Type::Config, + "Script execution error: {err:#}. Script name: {name}" + ); Ok((config, outputs.lock().to_vec())) } } diff --git a/src-tauri/src/feat/backup.rs b/src-tauri/src/feat/backup.rs index 4652c2aa4..414f530b9 100644 --- a/src-tauri/src/feat/backup.rs +++ b/src-tauri/src/feat/backup.rs @@ -69,7 +69,7 @@ async fn finalize_restored_verge_config( } .await; if let Err(err) = result { - logging!(error, Type::Backup, "Failed to turn the system proxy off: {err:#?}"); + logging!(error, Type::Backup, "Failed to turn the system proxy off: {err:#}"); if SystemProxyStateUnknown::is_in(&err) { return Err(err); } @@ -79,7 +79,7 @@ async fn finalize_restored_verge_config( // Run configuration side effects without rewriting the already-restored file. if let Err(err) = super::patch_verge(&restored, true).await { - logging!(error, Type::Backup, "Failed to apply restored verge config: {err:#?}"); + logging!(error, Type::Backup, "Failed to apply restored verge config: {err:#}"); // Propagate unknown proxy state; ordinary side-effect failures stay logged. if SystemProxyStateUnknown::is_in(&err) { return Err(err); @@ -88,9 +88,10 @@ async fn finalize_restored_verge_config( Ok(()) } +#[tracing::instrument(skip_all, level = "info")] pub async fn create_backup_and_upload_webdav() -> Result<()> { let (file_name, temp_file_path) = backup::create_backup().await.map_err(|err| { - logging!(error, Type::Backup, "Failed to create backup: {err:#?}"); + logging!(error, Type::Backup, "Failed to create backup: {err:#}"); err })?; @@ -98,13 +99,13 @@ pub async fn create_backup_and_upload_webdav() -> Result<()> { .upload(temp_file_path.clone(), file_name) .await { - logging!(error, Type::Backup, "Failed to upload to WebDAV: {err:#?}"); + logging!(error, Type::Backup, "Failed to upload to WebDAV: {err:#}"); backup::WebDavClient::global().reset(); return Err(err); } if let Err(err) = temp_file_path.remove_if_exists().await { - logging!(warn, Type::Backup, "Failed to remove temp file: {err:#?}"); + logging!(warn, Type::Backup, "Failed to remove temp file: {err:#}"); } Ok(()) @@ -112,18 +113,24 @@ pub async fn create_backup_and_upload_webdav() -> Result<()> { pub async fn list_wevdav_backup() -> Result> { backup::WebDavClient::global().list().await.map_err(|err| { - logging!(error, Type::Backup, "Failed to list WebDAV backup files: {err:#?}"); + logging!(error, Type::Backup, "Failed to list WebDAV backup files: {err:#}"); err }) } pub async fn delete_webdav_backup(filename: String) -> Result<()> { + let name = filename.to_string(); backup::WebDavClient::global().delete(filename).await.map_err(|err| { - logging!(error, Type::Backup, "Failed to delete WebDAV backup file: {err:#?}"); + logging!( + error, + Type::Backup, + "Failed to delete WebDAV backup file {name}: {err:#}" + ); err }) } +#[tracing::instrument(skip_all, level = "info", fields(filename = %filename))] pub async fn restore_webdav_backup(filename: String) -> Result<()> { let verge = Config::verge().await; let verge_data = verge.latest_arc(); @@ -134,11 +141,16 @@ pub async fn restore_webdav_backup(filename: String) -> Result<()> { let backup_storage_path = app_home_dir() .map_err(|e| anyhow::anyhow!("Failed to get app home dir: {e}"))? .join(filename.as_str()); + let name = filename.to_string(); backup::WebDavClient::global() .download(filename, backup_storage_path.clone()) .await .map_err(|err| { - logging!(error, Type::Backup, "Failed to download WebDAV backup file: {err:#?}"); + logging!( + error, + Type::Backup, + "Failed to download WebDAV backup file {name}: {err:#}" + ); err })?; @@ -163,7 +175,7 @@ where F: FnOnce(&str) -> String, { let (file_name, temp_file_path) = backup::create_backup().await.map_err(|err| { - logging!(error, Type::Backup, "Failed to create local backup: {err:#?}"); + logging!(error, Type::Backup, "Failed to create local backup: {err:#}"); err })?; @@ -172,12 +184,17 @@ where let target_path = backup_dir.join(final_name.as_str()); if let Err(err) = move_file(temp_file_path.clone(), target_path.clone()).await { - logging!(error, Type::Backup, "Failed to move local backup file: {err:#?}"); + logging!( + error, + Type::Backup, + "Failed to move local backup file to {}: {err:#}", + target_path.display() + ); if let Err(clean_err) = temp_file_path.remove_if_exists().await { logging!( warn, Type::Backup, - "Failed to remove temp backup file after move error: {clean_err:#?}" + "Failed to remove temp backup file after move error: {clean_err:#}" ); } return Err(err); @@ -186,6 +203,7 @@ where Ok(final_name) } +#[tracing::instrument(skip_all, level = "info", fields(source = %source))] pub async fn import_local_backup(source: String) -> Result { let source_path = PathBuf::from(source.as_str()); if !source_path.exists() { @@ -226,7 +244,7 @@ pub async fn import_local_backup(source: String) -> Result { fs::copy(&source_path, &target_path) .await - .map_err(|err| anyhow!("Failed to import backup file: {err:#?}"))?; + .map_err(|err| anyhow!("Failed to import backup file: {err:#}"))?; Ok(file_name.to_string().into()) } @@ -243,14 +261,14 @@ async fn move_file(from: PathBuf, to: PathBuf) -> Result<()> { logging!( warn, Type::Backup, - "Failed to rename backup file directly, fallback to copy/remove: {rename_err:#?}" + "Failed to rename backup file directly, fallback to copy/remove: {rename_err}" ); fs::copy(&from, &to) .await - .map_err(|err| anyhow!("Failed to copy backup file: {err:#?}"))?; + .map_err(|err| anyhow!("Failed to copy backup file: {err:#}"))?; fs::remove_file(&from) .await - .map_err(|err| anyhow!("Failed to remove temp backup file: {err:#?}"))?; + .map_err(|err| anyhow!("Failed to remove temp backup file: {err:#}"))?; Ok(()) } } @@ -295,13 +313,14 @@ pub async fn delete_local_backup(filename: String) -> Result<()> { let backup_dir = local_backup_dir()?; let target_path = backup_dir.join(filename.as_str()); if !target_path.exists() { - logging!(warn, Type::Backup, "Local backup file not found: {}", filename); + logging!(debug, Type::Backup, "Local backup file not found: {}", filename); return Ok(()); } target_path.remove_if_exists().await?; Ok(()) } +#[tracing::instrument(skip_all, level = "info", fields(filename = %filename))] pub async fn restore_local_backup(filename: String) -> Result<()> { let backup_dir = local_backup_dir()?; let target_path = backup_dir.join(filename.as_str()); @@ -327,6 +346,7 @@ pub async fn restore_local_backup(filename: String) -> Result<()> { Ok(()) } +#[tracing::instrument(skip_all, level = "info", fields(filename = %filename, destination = %destination))] pub async fn export_local_backup(filename: String, destination: String) -> Result<()> { let backup_dir = local_backup_dir()?; let source_path = backup_dir.join(filename.as_str()); @@ -342,6 +362,6 @@ pub async fn export_local_backup(filename: String, destination: String) -> Resul fs::copy(&source_path, &dest_path) .await .map(|_| ()) - .map_err(|err| anyhow!("Failed to export backup file: {err:#?}"))?; + .map_err(|err| anyhow!("Failed to export backup file: {err:#}"))?; Ok(()) } diff --git a/src-tauri/src/feat/clash.rs b/src-tauri/src/feat/clash.rs index e7400ab74..1bd8da356 100644 --- a/src-tauri/src/feat/clash.rs +++ b/src-tauri/src/feat/clash.rs @@ -31,7 +31,7 @@ pub async fn restart_clash_core() { } Err(err) => { handle::Handle::notice_message("set_config::error", format!("{err:#}")); - logging!(error, Type::Core, "{err:#}"); + logging!(error, Type::Core, "restart core failed: {err:#}"); } } } @@ -42,7 +42,6 @@ pub async fn restart_app() { Config::apply_all_and_save_file().await; - logging!(info, Type::System, "开始异步清理资源"); let cleanup_result = clean_async().await; logging!( @@ -85,9 +84,8 @@ pub async fn change_clash_mode(mode: String) -> Result<(), String> { let json_value = serde_json::json!({ "mode": mode }); - logging!(debug, Type::Core, "change clash mode to {mode}"); if let Err(err) = handle::Handle::mihomo().patch_base_config(&json_value).await { - logging!(error, Type::Core, "{err}"); + logging!(error, Type::Core, "change clash mode failed: {err}"); return Err(err.to_string().into()); } @@ -111,6 +109,7 @@ pub async fn change_clash_mode(mode: String) -> Result<(), String> { /// Test delay to a URL through proxy. /// HTTPS: measures TLS handshake time. HTTP: measures HEAD round-trip time. +#[tracing::instrument(skip_all, level = "trace", fields(url = %url))] pub async fn test_delay(url: String) -> anyhow::Result { use std::sync::Arc; use std::time::Duration; diff --git a/src-tauri/src/feat/config.rs b/src-tauri/src/feat/config.rs index db7077387..81ab7efb7 100644 --- a/src-tauri/src/feat/config.rs +++ b/src-tauri/src/feat/config.rs @@ -1,6 +1,6 @@ use crate::{ config::{Config, IVerge}, - core::{CoreManager, autostart, handle, hotkey, logger::Logger, proxy_control, tray}, + core::{CoreManager, autostart, handle, hotkey, logger, proxy_control, tray}, module::{auto_backup::AutoBackupManager, lightweight}, }; use anyhow::Result; @@ -267,12 +267,12 @@ async fn process_terminated_flags(update_flags: UpdateFlags, patch: &IVerge) -> } } if update_flags.contains(UpdateFlags::LOG_LEVEL) { - Logger::global().update_log_level(patch.get_log_level())?; + logger::Logger::global().update_log_level(patch.get_log_level())?; } if update_flags.contains(UpdateFlags::LOG_FILE) { let log_max_size = patch.app_log_max_size.unwrap_or(128); let log_max_count = patch.app_log_max_count.unwrap_or(8); - Logger::global().update_log_config(log_max_size, log_max_count).await?; + logger::update_log_config(log_max_size, log_max_count).await?; } Ok(()) } @@ -317,7 +317,6 @@ pub(super) async fn apply_verge_patch_locked( if !not_save_file { // 分离数据获取和异步调用 let verge_data = verge.data_arc(); - logging!(debug, Type::Setup, "Saving Verge configuration to file..."); verge_data.save_file().await?; } Ok(()) diff --git a/src-tauri/src/feat/core_upgrade.rs b/src-tauri/src/feat/core_upgrade.rs index a0e87393e..19919d4d1 100644 --- a/src-tauri/src/feat/core_upgrade.rs +++ b/src-tauri/src/feat/core_upgrade.rs @@ -45,6 +45,7 @@ pub struct CoreUpgradeReport { pub async fn upgrade_core(force: bool) -> Result { let _serialized = UPGRADE_LOCK.lock().await; let core = Config::verge().await.latest_arc().get_valid_clash_core(); + tracing::Span::current().record("core", tracing::field::display(&core)); let alpha = core.ends_with("-alpha"); let target = managed_core_path(&core)?; @@ -55,11 +56,10 @@ pub async fn upgrade_core(force: bool) -> Result { }); let (proxy, latest) = resolve_latest_version(alpha).await?; - logging!( - info, - Type::Core, - "core upgrade: {core} installed={installed:?} latest={latest:?} via {proxy:?}" - ); + let span = tracing::Span::current(); + span.record("from", tracing::field::display(&installed)); + span.record("to", tracing::field::display(&latest)); + logging!(debug, Type::Core, "core upgrade: latest version resolved via {proxy:?}"); if !force && installed == latest { return Ok(CoreUpgradeReport { @@ -111,7 +111,6 @@ pub async fn upgrade_core(force: bool) -> Result { #[cfg(windows)] let _ = std::fs::remove_file(target.with_extension("old")); - logging!(info, Type::Core, "core upgrade: {core} now at {latest}"); Ok(CoreUpgradeReport { upgraded: true, from: installed, @@ -175,6 +174,7 @@ fn asset_base_name(alpha: bool) -> Result<&'static str> { } /// Returns the proxy that reached GitHub so the package download reuses it. +#[tracing::instrument(skip_all, level = "debug", fields(alpha))] async fn resolve_latest_version(alpha: bool) -> Result<(ProxyType, std::string::String)> { let url = if alpha { format!("{ALPHA_BASE_URL}/version.txt") @@ -193,13 +193,33 @@ async fn resolve_latest_version(alpha: bool) -> Result<(ProxyType, std::string:: // An error page answered with 200 must not become a version, nor reach the URL. let version = response.text().trim().to_owned(); if !is_usable_version(&version) { + logging!( + warn, + Type::Core, + "core upgrade: {url} returned an unusable version: {version:?}" + ); last_error = Some(anyhow!("{url} returned an unusable version")); continue; } return Ok((proxy, version)); } - Ok(response) => last_error = Some(anyhow!("{url} returned status {}", response.status())), - Err(error) => last_error = Some(error.context(format!("{proxy:?} could not reach {url}"))), + Ok(response) => { + logging!( + debug, + Type::Core, + "core upgrade: version probe via {proxy:?}: status {}", + response.status() + ); + last_error = Some(anyhow!("{url} returned status {}", response.status())); + } + Err(error) => { + logging!( + debug, + Type::Core, + "core upgrade: version probe via {proxy:?} failed: {error:#}" + ); + last_error = Some(error.context(format!("{proxy:?} could not reach {url}"))); + } } } diff --git a/src-tauri/src/feat/icon.rs b/src-tauri/src/feat/icon.rs index e78082629..a69577cee 100644 --- a/src-tauri/src/feat/icon.rs +++ b/src-tauri/src/feat/icon.rs @@ -157,13 +157,7 @@ pub async fn copy_icon_file(path: String, icon_info: IconInfo) -> CmdResult file dist: {:?}", - path, - dest_path - ); + logging!(debug, Type::Cmd, "copying icon file: {path} -> {}", dest_path.display()); match fs::copy(file_path, &dest_path).await { Ok(_) => Ok(dest_path.to_string_lossy().into()), diff --git a/src-tauri/src/feat/profile.rs b/src-tauri/src/feat/profile.rs index 46233fda1..ff9e3f7c3 100644 --- a/src-tauri/src/feat/profile.rs +++ b/src-tauri/src/feat/profile.rs @@ -5,15 +5,18 @@ use crate::{ utils::help::{mask_err, mask_url}, }; use anyhow::{Result, bail}; -use clash_verge_logging::{Type, logging, logging_error}; +use clash_verge_logging::{Type, logging}; use smartstring::alias::String; /// Toggle proxy profile pub async fn toggle_proxy_profile(profile_index: String) { - logging_error!( - Type::Config, - cmd::patch_profiles_config_by_profile_index(profile_index).await - ); + if let Err(err) = cmd::patch_profiles_config_by_profile_index(profile_index.clone()).await { + logging!( + error, + Type::Config, + "toggle proxy profile {profile_index} failed: {err}" + ); + } } /// Tell the profile which node this group is on now. @@ -25,7 +28,7 @@ async fn record_switched_node(group_name: &str, proxy_name: &str) { if let Err(error) = crate::config::profiles::record_selected_node(group_name, proxy_name).await { logging!( warn, - Type::Tray, + Type::Config, "切换代理成功但未能记录到配置: {} -> {}, 错误: {error:#}", group_name, proxy_name @@ -39,21 +42,13 @@ pub async fn switch_proxy_node(group_name: &str, proxy_name: &str) { .await { Ok(_) => { - logging!(info, Type::Tray, "切换代理成功: {} -> {}", group_name, proxy_name); record_switched_node(group_name, proxy_name).await; handle::Handle::refresh_proxy_config(); let _ = tray::Tray::global().update_menu().await; return; } Err(err) => { - logging!( - error, - Type::Tray, - "切换代理失败: {} -> {}, 错误: {:?}", - group_name, - proxy_name, - err - ); + logging!(error, Type::Tray, "切换代理失败: {err:?}"); } } @@ -67,14 +62,7 @@ pub async fn switch_proxy_node(group_name: &str, proxy_name: &str) { let _ = tray::Tray::global().update_menu().await; } Err(err) => { - logging!( - error, - Type::Tray, - "代理切换最终失败: {} -> {}, 错误: {:?}", - group_name, - proxy_name, - err - ); + logging!(error, Type::Tray, "代理切换最终失败: {err:?}"); } } } @@ -86,20 +74,19 @@ async fn should_update_profile(uid: &String, ignore_auto_update: bool) -> Result let is_remote = item.itype.as_ref().is_some_and(|s| s == "remote"); if !is_remote { - logging!(info, Type::Config, "[订阅更新] {uid} 不是远程订阅，跳过更新"); + logging!(info, Type::Config, "[订阅更新] 不是远程订阅，跳过更新"); Ok(None) } else if item.url.is_none() { - logging!(warn, Type::Config, "Warning: [订阅更新] {uid} 缺少URL，无法更新"); + logging!(warn, Type::Config, "[订阅更新] 缺少URL，无法更新"); bail!("failed to get the profile item url"); } else if !ignore_auto_update && !item.option.as_ref().and_then(|o| o.allow_auto_update).unwrap_or(true) { - logging!(info, Type::Config, "[订阅更新] {} 禁止自动更新，跳过更新", uid); + logging!(info, Type::Config, "[订阅更新] 禁止自动更新，跳过更新"); Ok(None) } else { logging!( info, Type::Config, - "[订阅更新] {} 是远程订阅，URL: {}", - uid, + "[订阅更新] 远程订阅，URL: {}", mask_url( item.url .as_ref() @@ -113,6 +100,7 @@ async fn should_update_profile(uid: &String, ignore_auto_update: bool) -> Result } } +#[tracing::instrument(skip_all, level = "info", fields(uid = %uid, strategy = tracing::field::Empty))] async fn perform_profile_update( uid: &String, url: &String, @@ -120,7 +108,6 @@ async fn perform_profile_update( option: Option<&PrfOption>, is_mannual_trigger: bool, ) -> Result<()> { - logging!(info, Type::Config, "[订阅更新] 开始下载新的订阅内容"); let mut merged_opt = PrfOption::merge(opt, option); let profiles = Config::profiles().await; let profiles_arc = profiles.latest_arc(); @@ -140,8 +127,8 @@ async fn perform_profile_update( logging!( warn, Type::Config, - "Warning: [订阅更新] 正常更新失败: {}，尝试使用Clash代理更新", - mask_err(&err.to_string()) + "[订阅更新] 直接更新失败: {}，尝试使用Clash代理更新", + mask_err(&format!("{err:#}")) ); } } @@ -160,8 +147,8 @@ async fn perform_profile_update( logging!( warn, Type::Config, - "Warning: [订阅更新] Clash代理更新失败: {}，尝试使用系统代理更新", - mask_err(&err.to_string()) + "[订阅更新] Clash代理更新失败: {}，尝试使用系统代理更新", + mask_err(&format!("{err:#}")) ); } } @@ -180,8 +167,8 @@ async fn perform_profile_update( logging!( warn, Type::Config, - "Warning: [订阅更新] 系统代理更新失败: {}，所有重试均已失败", - mask_err(&err.to_string()) + "[订阅更新] 系统代理更新失败: {}，所有重试均已失败", + mask_err(&format!("{err:#}")) ); err } @@ -194,8 +181,8 @@ async fn perform_profile_update( bail!(last_err) } +#[tracing::instrument(skip_all, level = "info", fields(uid = %uid, manual = is_mannual_trigger))] pub async fn update_profile(uid: &String, option: Option<&PrfOption>, is_mannual_trigger: bool) -> Result<()> { - logging!(info, Type::Config, "[订阅更新] 开始更新订阅 {}", uid); let url_opt = should_update_profile(uid, is_mannual_trigger).await?; let profile_persisted = match url_opt { @@ -210,10 +197,9 @@ pub async fn update_profile(uid: &String, option: Option<&PrfOption>, is_mannual let should_refresh = is_current || (!profile_persisted && is_mannual_trigger); if should_refresh { - logging!(info, Type::Config, "[订阅更新] 更新内核配置"); + logging!(debug, Type::Config, "[订阅更新] 更新内核配置"); match CoreManager::global().update_config_with_force(is_mannual_trigger).await { Ok(outcome) if outcome.is_valid() => { - logging!(info, Type::Config, "[订阅更新] 更新成功"); handle::Handle::refresh_clash(); } Ok(outcome @ (ValidationOutcome::Skipped { .. } | ValidationOutcome::Busy)) if !is_mannual_trigger => { diff --git a/src-tauri/src/feat/proxy.rs b/src-tauri/src/feat/proxy.rs index d5226dfeb..ac118ac79 100644 --- a/src-tauri/src/feat/proxy.rs +++ b/src-tauri/src/feat/proxy.rs @@ -23,7 +23,11 @@ pub async fn toggle_system_proxy() -> Option { && auto_close_connection && let Err(err) = handle::Handle::mihomo().close_all_connections().await { - logging!(error, Type::ProxyMode, "Failed to close all connections: {err}"); + logging!( + error, + Type::ProxyMode, + "toggle system proxy: failed to close all connections: {err}" + ); } let requested = !current; @@ -42,7 +46,7 @@ pub async fn toggle_system_proxy() -> Option { match patch_result { Ok(_) => Some(requested), Err(err) => { - logging!(error, Type::ProxyMode, "{err:#}"); + logging!(error, Type::ProxyMode, "toggle system proxy failed: {err:#}"); report_toggle_failure(&err).await; None } @@ -84,7 +88,7 @@ pub async fn toggle_tun_mode(not_save_file: Option) -> bool { Config::verge().await.latest_arc().enable_tun_mode.unwrap_or(false) } Err(err) => { - logging!(error, Type::ProxyMode, "{err:#}"); + logging!(error, Type::ProxyMode, "toggle tun mode failed: {err:#}"); current } } @@ -133,7 +137,7 @@ pub async fn copy_clash_env() { } }; - if clipboard.write_text(&export_text).is_err() { - logging!(error, Type::ProxyMode, "Failed to write to clipboard"); + if let Err(err) = clipboard.write_text(&export_text) { + logging!(error, Type::ProxyMode, "Failed to write to clipboard: {err}"); } } diff --git a/src-tauri/src/feat/window.rs b/src-tauri/src/feat/window.rs index 57a9e4b02..0c13b3d1b 100644 --- a/src-tauri/src/feat/window.rs +++ b/src-tauri/src/feat/window.rs @@ -88,11 +88,11 @@ async fn restore_dns_after_core_stop() -> bool { .await { Ok(_) => { - logging!(info, Type::Window, "DNS设置已恢复"); + logging!(debug, Type::Window, "DNS设置已恢复"); true } Err(_) => { - logging!(warn, Type::Window, "Warning: 恢复DNS设置超时"); + logging!(warn, Type::Window, "恢复DNS设置超时"); false } } @@ -117,7 +117,6 @@ pub async fn quit() -> clash_verge_signal::ShutdownOutcome { Config::apply_all_and_save_file().await; - logging!(info, Type::System, "开始异步清理资源"); let cleanup_result = clean_async().await; logging!( @@ -143,21 +142,12 @@ pub async fn quit() -> clash_verge_signal::ShutdownOutcome { } pub async fn clean_async() -> CleanupResult { - logging!( - info, - Type::System, - "Starting interactive cleanup; controlled core stop will be awaited to completion" - ); - let stop_error = Mutex::new(None); let mut result = run_interactive_cleanup_transition( || async { - logging!(info, Type::System, "Stopping core for interactive quit or restart"); + logging!(debug, Type::System, "Stopping core for interactive quit or restart"); match CoreManager::global().stop_core().await { - Ok(()) => { - logging!(info, Type::Window, "Core stopped for interactive quit or restart"); - true - } + Ok(()) => true, Err(error) => { logging!( warn, @@ -199,13 +189,10 @@ pub async fn clean_session_ending_best_effort() -> CleanupResult { let result = run_session_ending_cleanup_transition( || async { - logging!(info, Type::System, "Clearing all WebSocket connections before stopping core"); - let _ = handle::Handle::mihomo().clear_all_ws_connections(); - logging!(info, Type::System, "Stopping core during session-ending best-effort cleanup"); - match CoreManager::global().stop_core().await { + let _ = handle::Handle::mihomo().clear_all_ws_connections(); + match CoreManager::global().stop_core().await { Ok(()) => { - logging!(info, Type::Window, "Core stopped during session-ending best-effort cleanup"); - true + true } Err(error) => { logging!( diff --git a/src-tauri/src/lib.rs b/src-tauri/src/lib.rs index 48f917b76..3fbcc20ca 100644 --- a/src-tauri/src/lib.rs +++ b/src-tauri/src/lib.rs @@ -33,7 +33,7 @@ mod app_init { /// Initialize singleton monitoring for other instances pub fn init_singleton_check() -> Result { AsyncHandler::block_on(async move { - logging!(info, Type::Setup, "开始检查单例实例..."); + logging!(debug, Type::Setup, "开始检查单例实例..."); server::check_singleton().await }) } @@ -74,7 +74,7 @@ mod app_init { pub fn setup_deep_links(app: &tauri::App) { #[cfg(any(target_os = "linux", all(debug_assertions, windows)))] { - logging!(info, Type::Setup, "注册深层链接..."); + logging!(debug, Type::Setup, "注册深层链接..."); let _ = app.deep_link().register_all(); } @@ -107,7 +107,7 @@ mod app_init { /// Setup window state management pub fn setup_window_state(app: &tauri::App) -> Result<(), Box> { - logging!(info, Type::Setup, "初始化窗口状态管理..."); + logging!(debug, Type::Setup, "初始化窗口状态管理..."); let window_state_plugin = tauri_plugin_window_state::Builder::new() .with_filename(files::WINDOW_STATE) .with_state_flags(tauri_plugin_window_state::StateFlags::default()) @@ -280,10 +280,10 @@ pub fn run() -> std::process::ExitCode { .expect("failed to set global app handle"); if let Err(e) = resolve::init_work_dir_and_logger() { - logging!(error, Type::Setup, "Failed to init work dir/logger: {}", e); + logging!(error, Type::Setup, "Failed to init work dir/logger: {e:#}"); } - logging!(info, Type::Setup, "开始应用初始化..."); + logging!(debug, Type::Setup, "开始应用初始化..."); if let Err(e) = app_init::setup_autostart(app) { logging!(error, Type::Setup, "Failed to setup autostart: {}", e); } @@ -302,7 +302,6 @@ pub fn run() -> std::process::ExitCode { resolve::resolve_setup_async(); resolve::resolve_setup_sync(); resolve::init_signal(); - logging!(info, Type::Setup, "初始化已启动"); })) { log_setup_panic("window-core", panic); } @@ -470,6 +469,7 @@ pub fn run() -> std::process::ExitCode { ); } logging!(info, Type::System, "Application exited"); + crate::core::logger::Logger::global().flush_logs(); }), #[allow(unused_variables)] tauri::RunEvent::ExitRequested { api, code, .. } => { diff --git a/src-tauri/src/main.rs b/src-tauri/src/main.rs index 77a38de5b..659b574b8 100755 --- a/src-tauri/src/main.rs +++ b/src-tauri/src/main.rs @@ -34,8 +34,5 @@ fn main() -> ExitCode { let tokio_handle = tokio_runtime.handle(); tauri::async_runtime::set(tokio_handle.clone()); - #[cfg(feature = "tokio-trace")] - console_subscriber::init(); - app_lib::run() } diff --git a/src-tauri/src/utils/dirs.rs b/src-tauri/src/utils/dirs.rs index c76e780a5..236b3f189 100644 --- a/src-tauri/src/utils/dirs.rs +++ b/src-tauri/src/utils/dirs.rs @@ -329,7 +329,7 @@ impl PathBufExec for PathBuf { async fn remove_if_exists(&self) -> Result<()> { if self.exists() { tokio::fs::remove_file(self).await?; - logging!(info, Type::File, "Removed file: {:?}", self); + logging!(debug, Type::File, "Removed file: {:?}", self); } Ok(()) } diff --git a/src-tauri/src/utils/init.rs b/src-tauri/src/utils/init.rs index 3bf61399a..4afc96292 100644 --- a/src-tauri/src/utils/init.rs +++ b/src-tauri/src/utils/init.rs @@ -33,7 +33,7 @@ async fn delete_snapshot_logs(log_dir: &Path) -> Result<()> { let path = entry.path(); if path.extension().and_then(|s| s.to_str()) == Some("log") { let _ = path.remove_if_exists().await; - logging!(info, Type::Setup, "delete snapshot log file: {}", path.display()); + logging!(debug, Type::Setup, "delete snapshot log file: {}", path.display()); } } } @@ -69,7 +69,7 @@ pub async fn delete_log() -> Result<()> { _ => return Ok(()), }; - logging!(info, Type::Setup, "try to delete log files, day: {}", day); + logging!(debug, Type::Setup, "try to delete log files, day: {}", day); let parse_time_str = |s: &str| { let sa: Vec<&str> = s.split('-').collect(); @@ -102,7 +102,7 @@ pub async fn delete_log() -> Result<()> { let duration = now.signed_duration_since(file_time); if duration.num_days() > day { let _ = file.path().remove_if_exists().await; - logging!(info, Type::Setup, "delete log file: {}", file_name); + logging!(debug, Type::Setup, "delete log file: {}", file_name); } } Ok(()) @@ -284,7 +284,7 @@ async fn migrate_legacy_macos_logs() -> Result<()> { if is_logs_dir_writable(&log_dir).await { if let Err(e) = migrate_legacy_macos_service_logs(&log_dir).await { - logging!(warn, Type::Setup, "Failed to migrate legacy macOS service logs: {}", e); + logging!(warn, Type::Setup, "Failed to migrate legacy macOS service logs: {e:#}"); } return Ok(()); } @@ -489,9 +489,9 @@ pub async fn init_config() -> Result<()> { AsyncHandler::spawn(|| async { if let Err(e) = delete_log().await { - logging!(warn, Type::Setup, "Failed to clean old logs: {}", e); + logging!(warn, Type::Setup, "Failed to clean old logs: {e:#}"); } - logging!(info, Type::Setup, "后台日志清理任务完成"); + logging!(debug, Type::Setup, "后台日志清理任务完成"); }); Ok(()) diff --git a/src-tauri/src/utils/resolve/dns.rs b/src-tauri/src/utils/resolve/dns.rs index 11d27dc40..3992ed1dd 100644 --- a/src-tauri/src/utils/resolve/dns.rs +++ b/src-tauri/src/utils/resolve/dns.rs @@ -27,7 +27,7 @@ pub async fn set_public_dns(dns_server: String) { use tauri_plugin_shell::ShellExt as _; let app_handle = handle::Handle::app_handle(); - logging!(info, Type::Config, "try to set system dns"); + logging!(debug, Type::Config, "try to set system dns"); let resource_dir = match dirs::app_resources_dir() { Ok(dir) => dir, Err(e) => { @@ -75,7 +75,7 @@ pub async fn restore_public_dns() { use crate::{core::handle, utils::dirs}; use tauri_plugin_shell::ShellExt as _; let app_handle = handle::Handle::app_handle(); - logging!(info, Type::Config, "try to unset system dns"); + logging!(debug, Type::Config, "try to unset system dns"); let resource_dir = match dirs::app_resources_dir() { Ok(dir) => dir, Err(e) => { diff --git a/src-tauri/src/utils/resolve/mod.rs b/src-tauri/src/utils/resolve/mod.rs index 9a185d90f..ff20b1c97 100644 --- a/src-tauri/src/utils/resolve/mod.rs +++ b/src-tauri/src/utils/resolve/mod.rs @@ -8,7 +8,7 @@ use crate::{ CoreManager, Timer, handle::Handle, hotkey::Hotkey, - logger::Logger, + logger, service::{SERVICE_MANAGER, ServiceManager}, tray::Tray, }, @@ -31,7 +31,7 @@ pub(crate) fn init_work_dir_and_logger() -> anyhow::Result<()> { AsyncHandler::block_on(async { init_work_config().await; logging!(info, Type::Setup, "Initializing logger"); - Logger::global().init().await?; + logger::init().await?; Ok(()) }) } @@ -46,50 +46,53 @@ pub(crate) fn resolve_setup_sync() { } pub(crate) fn resolve_setup_async() { - AsyncHandler::spawn(|| async { - logging!(info, Type::ClashVergeRev, "Version: {}", env!("CARGO_PKG_VERSION")); + AsyncHandler::spawn(resolve_setup); +} - // Migrate before windows or timers can change the loaded config. - logging_error!(Type::Setup, init::migrate_short_update_intervals().await); +#[tracing::instrument(skip_all, level = "info")] +async fn resolve_setup() { + logging!(info, Type::ClashVergeRev, "Version: {}", env!("CARGO_PKG_VERSION")); - #[cfg(target_os = "macos")] - resolve_dock_show().await; - init_startup_script().await; - init_service_manager().await; - let config_initialized = init_verge_config_before_window().await; - init_window().await; - feat::reconcile_startup_tun_availability().await; - init_resources().await; - if let Err(e) = init::init_dns_config().await { - logging!(warn, Type::Setup, "DNS config initialization failed: {}", e); - } - if config_initialized { - init_verge_config().await; - } - Config::verify_config_initialization().await; + // Migrate before windows or timers can change the loaded config. + logging_error!(Type::Setup, init::migrate_short_update_intervals().await); - // Live before the core starts, so a service appearing mid-start is not missed. - #[cfg(target_os = "macos")] - crate::core::network_watch::start(); + #[cfg(target_os = "macos")] + resolve_dock_show().await; + init_startup_script().await; + init_service_manager().await; + let config_initialized = init_verge_config_before_window().await; + init_window().await; + feat::reconcile_startup_tun_availability().await; + init_resources().await; + if let Err(e) = init::init_dns_config().await { + logging!(warn, Type::Setup, "DNS config initialization failed: {}", e); + } + if config_initialized { + init_verge_config().await; + } + Config::verify_config_initialization().await; - let core_init = AsyncHandler::spawn(|| async { - init_core_manager().await; - }); + // Live before the core starts, so a service appearing mid-start is not missed. + #[cfg(target_os = "macos")] + crate::core::network_watch::start(); - let _ = futures::join!( - core_init, - init_tray(), - init_timer(), - init_hotkey(), - init_auto_lightweight_boot(), - init_auto_backup(), - init_silent_updater(), - ); - - Handle::refresh_clash(); - refresh_tray_menu().await; - resolve_done(); + let core_init = AsyncHandler::spawn(|| async { + init_core_manager().await; }); + + let _ = futures::join!( + core_init, + init_tray(), + init_timer(), + init_hotkey(), + init_auto_lightweight_boot(), + init_auto_backup(), + init_silent_updater(), + ); + + Handle::refresh_clash(); + refresh_tray_menu().await; + resolve_done(); } pub async fn resolve_reset_async() -> Result<(), anyhow::Error> { @@ -165,7 +168,7 @@ async fn init_silent_updater() { use crate::core::SilentUpdater; use crate::core::handle::Handle; - logging!(info, Type::Setup, "Initializing silent updater..."); + logging!(debug, Type::Setup, "Initializing silent updater..."); let app_handle = Handle::app_handle(); @@ -184,7 +187,7 @@ async fn init_silent_updater() { } pub(crate) fn init_signal() { - logging!(info, Type::Setup, "Initializing signal handlers..."); + logging!(debug, Type::Setup, "Initializing signal handlers..."); clash_verge_signal::register(feat::quit); } diff --git a/src-tauri/src/utils/resolve/scheme.rs b/src-tauri/src/utils/resolve/scheme.rs index 158c43291..3aae4991e 100644 --- a/src-tauri/src/utils/resolve/scheme.rs +++ b/src-tauri/src/utils/resolve/scheme.rs @@ -98,7 +98,7 @@ async fn import_subscription(url: &str, name: Option<&String>) { } if let Err(e) = profiles::profiles_save_file_safe().await { - logging!(error, Type::Config, "failed to save imported subscription: {}", e); + logging!(error, Type::Config, "failed to save imported subscription: {e:#}"); handle::Handle::notice_message("import_sub_url::error", e.to_string()); return; } @@ -152,7 +152,7 @@ async fn refresh_core_config() { handle::Handle::notice_message("config_validate::error", message); } Err(err) => { - logging!(error, Type::Config, "Apply config error: {}", err); + logging!(error, Type::Config, "Apply config error: {err:#}"); handle::Handle::notice_message("update_failed", format!("{err}")); } } diff --git a/src-tauri/src/utils/window_manager.rs b/src-tauri/src/utils/window_manager.rs index e35e14bdb..eab10d089 100644 --- a/src-tauri/src/utils/window_manager.rs +++ b/src-tauri/src/utils/window_manager.rs @@ -46,7 +46,7 @@ pub struct WindowManager; impl WindowManager { #[cfg(target_os = "macos")] fn set_macos_activation_policy_regular() { - logging!(info, Type::Window, "应用 macOS 特定的激活策略"); + logging!(debug, Type::Window, "应用 macOS 特定的激活策略"); handle::Handle::global().set_activation_policy_regular(); } @@ -86,16 +86,16 @@ impl WindowManager { return WindowOperationResult::NoAction; } - logging!(info, Type::Window, "开始智能显示主窗口"); + logging!(debug, Type::Window, "开始智能显示主窗口"); logging!(debug, Type::Window, "{}", Self::get_window_status_info()); let current_state = Self::get_main_window_state(); match current_state { WindowState::NotExist => { - logging!(info, Type::Window, "窗口不存在，创建新窗口"); + logging!(debug, Type::Window, "窗口不存在，创建新窗口"); if Self::create_window(true).await { - logging!(info, Type::Window, "窗口创建成功"); + logging!(debug, Type::Window, "窗口创建成功"); tokio::time::sleep(std::time::Duration::from_millis(50)).await; WindowOperationResult::Created } else { @@ -104,13 +104,13 @@ impl WindowManager { } } WindowState::VisibleFocused => { - logging!(info, Type::Window, "窗口已经可见且有焦点，无需操作"); + logging!(debug, Type::Window, "窗口已经可见且有焦点，无需操作"); WindowOperationResult::NoAction } WindowState::VisibleUnfocused | WindowState::Minimized | WindowState::Hidden => { let (window, state_after_check) = Self::get_main_window_with_state(); if state_after_check == WindowState::VisibleFocused { - logging!(info, Type::Window, "窗口在检查期间已变为可见和有焦点状态"); + logging!(debug, Type::Window, "窗口在检查期间已变为可见和有焦点状态"); return WindowOperationResult::NoAction; } if let Some(window) = window { @@ -139,7 +139,7 @@ impl WindowManager { } async fn handle_not_exist_toggle() -> WindowOperationResult { - logging!(info, Type::Window, "窗口不存在，将创建新窗口"); + logging!(debug, Type::Window, "窗口不存在，将创建新窗口"); if Self::create_window(true).await { WindowOperationResult::Created } else { @@ -148,7 +148,7 @@ impl WindowManager { } fn hide_main_window(window: Option<&WebviewWindow>) -> WindowOperationResult { - logging!(info, Type::Window, "窗口可见，将隐藏窗口"); + logging!(debug, Type::Window, "窗口可见，将隐藏窗口"); if let Some(window) = window { match window.close() { Ok(_) => { @@ -167,7 +167,7 @@ impl WindowManager { } fn activate_existing_main_window(window: Option<&WebviewWindow>) -> WindowOperationResult { - logging!(info, Type::Window, "窗口存在但被隐藏或最小化，将激活窗口"); + logging!(debug, Type::Window, "窗口存在但被隐藏或最小化，将激活窗口"); if let Some(window) = window { Self::activate_window(window) } else { @@ -177,7 +177,7 @@ impl WindowManager { } fn activate_window(window: &WebviewWindow) -> WindowOperationResult { - logging!(info, Type::Window, "开始激活窗口"); + logging!(debug, Type::Window, "开始激活窗口"); #[cfg(target_os = "macos")] Self::set_macos_activation_policy_regular(); @@ -196,7 +196,7 @@ impl WindowManager { let mut operations_successful = true; if window.is_minimized().unwrap_or(false) { - logging!(info, Type::Window, "窗口已最小化，正在取消最小化"); + logging!(debug, Type::Window, "窗口已最小化，正在取消最小化"); if let Err(e) = window.unminimize() { logging!(warn, Type::Window, "取消最小化失败: {}", e); operations_successful = false; @@ -248,7 +248,7 @@ impl WindowManager { /// Keep new windows hidden until the frontend overlay renders, avoiding a theme flash. pub fn create_window(should_create: bool) -> Pin + Send>> { Box::pin(async move { - logging!(info, Type::Window, "开始创建主窗口, should_create={}", should_create); + logging!(debug, Type::Window, "开始创建主窗口, should_create={}", should_create); if !should_create { return false; @@ -277,7 +277,7 @@ impl WindowManager { logging!(info, Type::Window, "窗口已摧毁"); #[cfg(target_os = "macos")] { - logging!(info, Type::Window, "应用 macOS 特定的激活策略"); + logging!(debug, Type::Window, "应用 macOS 特定的激活策略"); handle::Handle::global().set_activation_policy_accessory(); } return WindowOperationResult::Destroyed;