From 8c995125e9d142547e8eadb712473d0cb09d9b36 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Kat=20March=C3=A1n?= Date: Tue, 7 Mar 2023 01:53:49 -0800 Subject: [PATCH] feat(log): write verbose trace to a separate debug logfile (#192) Fixes: https://github.com/orogene/orogene/issues/179 --- Cargo.lock | 22 +++++ Cargo.toml | 2 + crates/oro-client/src/api/packument.rs | 5 + src/lib.rs | 130 ++++++++++++++++++++----- 4 files changed, 133 insertions(+), 26 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 94429a76..4096b6c5 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -573,6 +573,16 @@ dependencies = [ "cfg-if", ] +[[package]] +name = "crossbeam-channel" +version = "0.5.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "cf2b3e8478797446514c91ef04bafcb59faba183e621ad488df88983cc14128c" +dependencies = [ + "cfg-if", + "crossbeam-utils", +] + [[package]] name = "crossbeam-utils" version = "0.8.15" @@ -1978,6 +1988,7 @@ dependencies = [ "term_grid", "term_size", "tracing", + "tracing-appender", "tracing-subscriber", "url", ] @@ -2965,6 +2976,17 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-appender" +version = "0.2.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "09d48f71a791638519505cefafe162606f706c25592e4bde4d97600c0195312e" +dependencies = [ + "crossbeam-channel", + "time 0.3.20", + "tracing-subscriber", +] + [[package]] name = "tracing-attributes" version = "0.1.23" diff --git a/Cargo.toml b/Cargo.toml index 0253ae9f..1141261d 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -37,6 +37,7 @@ serde_json = { workspace = true } term_grid = { workspace = true } term_size = { workspace = true } tracing = { workspace = true} +tracing-appender = { workspace = true } tracing-subscriber = { workspace = true, features = ["env-filter"] } url = { workspace = true } @@ -97,6 +98,7 @@ term_grid = "0.1.7" term_size = "0.3.2" thiserror = "1.0.38" tracing = "0.1.37" +tracing-appender = "0.2.2" tracing-subscriber = "0.3.16" url = "2.3.1" wasm-bindgen = "0.2.84" diff --git a/crates/oro-client/src/api/packument.rs b/crates/oro-client/src/api/packument.rs index 90cfae74..84c16c49 100644 --- a/crates/oro-client/src/api/packument.rs +++ b/crates/oro-client/src/api/packument.rs @@ -12,6 +12,11 @@ impl OroClient { package_name: impl AsRef, ) -> Result { let url = self.registry.join(package_name.as_ref())?; + tracing::trace!( + "fetching packument for {} from {}", + package_name.as_ref(), + url + ); let text = self.packument_impl(package_name, &url, false).await?; serde_json::from_str(&text) .map_err(move |e| OroClientError::from_json_err(e, url.to_string(), text)) diff --git a/src/lib.rs b/src/lib.rs index f65b3178..f7a4028d 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -101,7 +101,13 @@ use clap::{ArgMatches, CommandFactory, FromArgMatches as _, Parser, Subcommand}; use directories::ProjectDirs; use miette::{IntoDiagnostic, Result}; use oro_config::{OroConfig, OroConfigLayer, OroConfigOptions}; -use tracing_subscriber::{filter::LevelFilter, fmt, prelude::*, EnvFilter}; +use tracing_appender::non_blocking::WorkerGuard; +use tracing_subscriber::{ + filter::{Directive, LevelFilter, Targets}, + fmt, + prelude::*, + EnvFilter, +}; use url::Url; use commands::{ @@ -110,6 +116,8 @@ use commands::{ mod commands; +const MAX_RETAINED_LOGS: usize = 5; + #[derive(Debug, Parser)] #[command(author, version, about, long_about = None)] #[command(propagate_version = true)] @@ -158,24 +166,59 @@ pub struct Orogene { } impl Orogene { - fn setup_logging(&self) -> Result<()> { - tracing_subscriber::registry() - .with(fmt::layer()) - .with( - EnvFilter::builder() - .with_default_directive(if self.quiet { - LevelFilter::OFF.into() - } else { - self.loglevel - .clone() - .unwrap_or_else(|| "warn".to_owned()) - .parse() - .into_diagnostic()? - }) - .from_env_lossy(), - ) - .init(); - Ok(()) + fn setup_logging(&self) -> Result> { + let builder = EnvFilter::builder(); + let filter = if self.quiet { + builder + .with_default_directive(LevelFilter::OFF.into()) + .from_env_lossy() + } else { + let dir_str = self.loglevel.clone().unwrap_or_else(|| "warn".to_owned()); + let directives = dir_str + .split(',') + .filter(|s| !s.is_empty()) + .filter_map(|s| { + let dir: Result = s.parse(); + match dir { + Ok(dir) => Some(dir), + Err(_) => None, + } + }); + let mut filter = builder.from_env_lossy(); + for directive in directives { + filter = filter.add_directive(directive); + } + filter + }; + + let builder = tracing_subscriber::registry().with(fmt::layer().with_filter(filter)); + + if let Some(cache) = self.cache.as_deref() { + let targets = Targets::new() + .with_target("hyper", LevelFilter::WARN) + .with_target("reqwest", LevelFilter::WARN) + .with_target("tokio_util", LevelFilter::WARN) + .with_target("async_io", LevelFilter::WARN) + .with_target("want", LevelFilter::WARN) + .with_target("async_std", LevelFilter::WARN) + .with_target("mio", LevelFilter::WARN) + .with_default(LevelFilter::TRACE); + + clean_old_logs(cache)?; + + let file_appender = + tracing_appender::rolling::never(cache.join("_logs"), log_file_name()); + let (non_blocking, guard) = tracing_appender::non_blocking(file_appender); + + builder + .with(fmt::layer().with_writer(non_blocking).with_filter(targets)) + .init(); + + Ok(Some(guard)) + } else { + builder.init(); + Ok(None) + } } fn build_config(&self) -> Result { @@ -199,10 +242,7 @@ impl Orogene { cfg_builder.global_config_file(Some(file.clone())).load()? } else { cfg_builder - .global_config_file( - dirs.as_ref() - .map(|d| d.config_dir().to_owned().join("ororc.toml")), - ) + .global_config_file(dirs.map(|d| d.config_dir().to_owned().join("ororc.toml"))) .pkg_root(self.root.clone().or(Some(PathBuf::from(root)))) .load()? }; @@ -214,8 +254,9 @@ impl Orogene { let start = std::time::Instant::now(); let matches = Orogene::command().get_matches(); let mut oro = Orogene::from_arg_matches(&matches).into_diagnostic()?; - oro.layer_config(&matches, &oro.build_config()?)?; - oro.setup_logging()?; + let config = oro.build_config()?; + oro.layer_config(&matches, &config)?; + let _guard = oro.setup_logging()?; oro.execute().await?; tracing::info!("Ran in {}s", start.elapsed().as_millis() as f32 / 1000.0); Ok(()) @@ -236,6 +277,43 @@ fn pkg_root(start_dir: &Path) -> Option<&Path> { None } +fn log_file_name() -> PathBuf { + let now = chrono::Local::now(); + let prefix = format!("oro-debug-{}", now.format("%Y-%m-%d-%H-%M-%S%.3f")); + for i in 0.. { + let name = PathBuf::from(format!("{}-{}.log", prefix, i)); + if !name.exists() { + return name; + } + } + PathBuf::from(format!("{}-0.log", prefix)) +} + +fn clean_old_logs(cache: &Path) -> Result<()> { + if let Ok(readdir) = cache.join("_logs").read_dir() { + let mut logs = readdir.filter_map(|e| e.ok()).collect::>(); + logs.sort_by_key(|e| e.file_name()); + while logs.len() >= MAX_RETAINED_LOGS { + let log = logs.remove(0); + std::fs::remove_file(log.path()).into_diagnostic()?; + } + } + Ok(()) +} + +fn log_command_line() { + let mut args = std::env::args(); + let mut cmd = String::new(); + if let Some(arg) = args.next() { + cmd.push_str(&arg); + } + for arg in args { + cmd.push(' '); + cmd.push_str(&arg); + } + tracing::info!("Running command: {cmd}"); +} + #[derive(Debug, Subcommand)] pub enum OroCmd { /// Ping the registry. @@ -254,7 +332,7 @@ pub enum OroCmd { #[async_trait] impl OroCommand for Orogene { async fn execute(self) -> Result<()> { - tracing::info!("Running command: {:#?}", self.subcommand); + log_command_line(); match self.subcommand { OroCmd::Ping(cmd) => cmd.execute().await, OroCmd::Resolve(cmd) => cmd.execute().await,