diff --git a/crates/node-maintainer/src/maintainer.rs b/crates/node-maintainer/src/maintainer.rs index 2a56a52d..794bcfa2 100644 --- a/crates/node-maintainer/src/maintainer.rs +++ b/crates/node-maintainer/src/maintainer.rs @@ -398,7 +398,7 @@ impl NodeMaintainer { } } - tracing::info!("No metadata file found in node_modules/. Pruned entire node_modules/ directory in {}ms.", start.elapsed().as_micros() / 1000); + tracing::debug!("No metadata file found in node_modules/. Pruned entire node_modules/ directory in {}ms.", start.elapsed().as_micros() / 1000); // TODO: get an accurate count here? return Ok(0); @@ -501,12 +501,12 @@ impl NodeMaintainer { } if extraneous_packages == 0 { - tracing::info!( + tracing::debug!( "Nothing to prune. Completed check in {}ms.", start.elapsed().as_micros() / 1000 ); } else { - tracing::info!( + tracing::debug!( "Pruned {extraneous_packages} extraneous package{} in {}ms.", start.elapsed().as_micros() / 1000, if extraneous_packages == 1 { "" } else { "s" }, @@ -566,13 +566,13 @@ impl NodeMaintainer { on_extract(&self.graph[child_idx].package); } - tracing::debug!( - "Extracted {} to {} in {:?}ms. {}/{total} done. {} in flight.", + tracing::trace!( + in_flight = concurrent_count.fetch_sub(1, atomic::Ordering::SeqCst) - 1, + "Extracted {} to {} in {:?}ms. {}/{total} done.", self.graph[child_idx].package.name(), target_dir.display(), start.elapsed().as_millis(), total_completed.fetch_add(1, atomic::Ordering::SeqCst) + 1, - concurrent_count.fetch_sub(1, atomic::Ordering::SeqCst) - 1 ); Ok::<_, NodeMaintainerError>(()) }, @@ -583,7 +583,7 @@ impl NodeMaintainer { self.to_kdl()?.to_string(), )?; let actually_extracted = actually_extracted.load(atomic::Ordering::SeqCst); - tracing::info!( + tracing::debug!( "Extracted {actually_extracted} package{} in {}ms.", if actually_extracted == 1 { "" } else { "s" }, start.elapsed().as_millis(), @@ -813,7 +813,7 @@ impl NodeMaintainer { } #[cfg(not(target_arch = "wasm32"))] - tracing::info!( + tracing::debug!( "Resolved graph of {} nodes in {}ms", self.graph.inner.node_count(), start.elapsed().as_millis() @@ -1031,21 +1031,21 @@ fn supports_reflink(src_dir: &Path, dest_dir: &Path) -> bool { let temp = match tempfile::NamedTempFile::new_in(src_dir) { Ok(t) => t, Err(e) => { - tracing::info!("error creating tempfile while checking for reflink support: {e}."); + tracing::debug!("error creating tempfile while checking for reflink support: {e}."); return false; } }; match std::fs::write(&temp, "a") { Ok(_) => {} Err(e) => { - tracing::info!("error writing to tempfile while checking for reflink support: {e}."); + tracing::debug!("error writing to tempfile while checking for reflink support: {e}."); return false; } }; let tempdir = match tempfile::TempDir::new_in(dest_dir) { Ok(t) => t, Err(e) => { - tracing::info!( + tracing::debug!( "error creating destination tempdir while checking for reflink support: {e}." ); return false; @@ -1054,7 +1054,7 @@ fn supports_reflink(src_dir: &Path, dest_dir: &Path) -> bool { let supports_reflink = reflink::reflink(temp.path(), tempdir.path().join("b")) .map(|_| true) .map_err(|e| { - tracing::info!( + tracing::debug!( "reflink support check failed. Files will be hard linked or copied. ({e})" ); e @@ -1062,7 +1062,7 @@ fn supports_reflink(src_dir: &Path, dest_dir: &Path) -> bool { .unwrap_or(false); if supports_reflink { - tracing::info!("Verified reflink support. Extracted data will use copy-on-write reflinks instead of hard links or full copies.") + tracing::debug!("Verified reflink support. Extracted data will use copy-on-write reflinks instead of hard links or full copies.") } supports_reflink diff --git a/src/commands/ping.rs b/src/commands/ping.rs index d7df3224..ba9b1f8b 100644 --- a/src/commands/ping.rs +++ b/src/commands/ping.rs @@ -18,9 +18,6 @@ pub struct PingCmd { #[clap(from_global)] json: bool, - - #[clap(from_global)] - quiet: bool, } #[async_trait] @@ -30,15 +27,11 @@ impl OroCommand for PingCmd { let registry = self .registry .unwrap_or_else(|| "https://registry.npmjs.org".parse().unwrap()); - if !self.quiet && !self.json { - eprintln!("ping: {registry}"); - } + tracing::info!("ping: {registry}"); let client = OroClient::new(registry.clone()); let payload = client.ping().await?; let time = start.elapsed().as_micros() as f32 / 1000.0; - if !self.quiet && !self.json { - eprintln!("pong: {time}ms"); - } + tracing::info!("pong: {time}ms"); if self.json { let details: Value = serde_json::from_str(&payload) .into_diagnostic() @@ -50,11 +43,9 @@ impl OroCommand for PingCmd { })) .into_diagnostic() .wrap_err("ping::serialize")?; - if !self.quiet { - println!("{output}"); - } - } else if !self.quiet { - eprintln!("payload: {payload}"); + println!("{output}"); + } else { + tracing::info!("payload: {payload}"); } Ok(()) } diff --git a/src/commands/restore.rs b/src/commands/restore.rs index dd80cded..a5df858f 100644 --- a/src/commands/restore.rs +++ b/src/commands/restore.rs @@ -21,9 +21,6 @@ pub struct RestoreCmd { #[clap(from_global)] json: bool, - #[clap(from_global)] - quiet: bool, - #[clap(from_global)] root: Option, @@ -105,8 +102,8 @@ impl OroCommand for RestoreCmd { if !self.lockfile_only { self.prune(&emoji, &resolved_nm).await?; self.extract(&emoji, &resolved_nm).await?; - } else if !self.quiet { - eprintln!( + } else { + tracing::info!( "{}Skipping prune and extract, only writing lockfile", emoji.package() ); @@ -116,18 +113,14 @@ impl OroCommand for RestoreCmd { .write_lockfile(root.join("package-lock.kdl")) .await?; - if !self.quiet { - eprintln!("{}Wrote lockfile to package-lock.kdl.", emoji.writing()); - } + tracing::info!("{}Wrote lockfile to package-lock.kdl.", emoji.writing()); - if !self.quiet { - eprintln!( - "{}Done in {}s. {}", - emoji.tada(), - total_time.elapsed().as_millis() as f32 / 1000.0, - hackerish_encouragement() - ); - } + tracing::info!( + "{}Done in {}s. {}", + emoji.tada(), + total_time.elapsed().as_millis() as f32 / 1000.0, + hackerish_encouragement() + ); Ok(()) } } @@ -141,11 +134,11 @@ impl RestoreCmd { ) -> Result { // Set up progress bar and timing stuff. let resolve_time = std::time::Instant::now(); - let resolve_span = tracing::info_span!("resolving"); + let resolve_span = tracing::debug_span!("resolving"); resolve_span.pb_set_style( &ProgressStyle::default_bar() .template(&format!( - "{}{}", + "{}Resolving {}", emoji.magnifying_glass(), "{bar:40} [{pos}/{len}] {wide_msg:.dim}" )) @@ -162,14 +155,12 @@ impl RestoreCmd { // Wrap up progress bar and print messages. std::mem::drop(resolve_span_enter); std::mem::drop(resolve_span); - if !self.quiet { - eprintln!( - "{}Resolved {} packages in {}s.", - emoji.magnifying_glass(), - resolved_nm.package_count(), - resolve_time.elapsed().as_millis() as f32 / 1000.0 - ); - } + tracing::info!( + "{}Resolved {} packages in {}s.", + emoji.magnifying_glass(), + resolved_nm.package_count(), + resolve_time.elapsed().as_millis() as f32 / 1000.0 + ); Ok(resolved_nm) } @@ -177,11 +168,11 @@ impl RestoreCmd { async fn prune(&self, emoji: &Emoji, maintainer: &NodeMaintainer) -> Result<()> { // Set up progress bar and timing stuff. let prune_time = std::time::Instant::now(); - let prune_span = tracing::info_span!("prune"); + let prune_span = tracing::debug_span!("prune"); prune_span.pb_set_style( &ProgressStyle::default_bar() .template(&format!( - "{}{}", + "{}Pruning extraneous {}", emoji.broom(), "{bar:40} [{pos}] {wide_msg:.dim}" )) @@ -196,13 +187,11 @@ impl RestoreCmd { // Wrap up progress bar and message. std::mem::drop(prune_span_enter); std::mem::drop(prune_span); - if !self.quiet { - eprintln!( - "{}Pruned {pruned} packages in {}s.", - emoji.broom(), - prune_time.elapsed().as_millis() as f32 / 1000.0 - ); - } + tracing::info!( + "{}Pruned {pruned} packages in {}s.", + emoji.broom(), + prune_time.elapsed().as_millis() as f32 / 1000.0 + ); Ok(()) } @@ -210,11 +199,11 @@ impl RestoreCmd { async fn extract(&self, emoji: &Emoji, maintainer: &NodeMaintainer) -> Result<()> { // Set up progress bar and timing stuff. let extract_time = std::time::Instant::now(); - let extract_span = tracing::info_span!("extract"); + let extract_span = tracing::debug_span!("extract"); extract_span.pb_set_style( &ProgressStyle::default_bar() .template(&format!( - "{}{}", + "{}Extracting {}", emoji.package(), "{bar:40} [{pos}/{len}] {wide_msg:.dim}" )) @@ -229,14 +218,12 @@ impl RestoreCmd { // Wrap up progress bar and message. std::mem::drop(extract_span_enter); std::mem::drop(extract_span); - if !self.quiet { - eprintln!( - "{}Extracted {extracted} package{} in {}s.", - emoji.package(), - if extracted == 1 { "" } else { "s" }, - extract_time.elapsed().as_millis() as f32 / 1000.0 - ); - } + tracing::info!( + "{}Extracted {extracted} package{} in {}s.", + emoji.package(), + if extracted == 1 { "" } else { "s" }, + extract_time.elapsed().as_millis() as f32 / 1000.0 + ); Ok(()) } diff --git a/src/lib.rs b/src/lib.rs index e311e663..7cc0f205 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -114,14 +114,14 @@ pub struct Orogene { } impl Orogene { - fn setup_logging(&self) -> Result> { + fn setup_logging(&self, log_file: Option<&Path>) -> 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 dir_str = self.loglevel.clone().unwrap_or_else(|| "info".to_owned()); let directives = dir_str .split(',') .filter(|s| !s.is_empty()) @@ -139,10 +139,10 @@ impl Orogene { filter }; - let ilayer = IndicatifLayer::new().with_max_progress_bars(1, None); + let ilayer = IndicatifLayer::new(); let builder = tracing_subscriber::registry(); - if let Some(cache) = self.cache.as_deref() { + if let Some(log_file) = &log_file { let targets = Targets::new() .with_target("hyper", LevelFilter::WARN) .with_target("reqwest", LevelFilter::WARN) @@ -151,28 +151,49 @@ impl Orogene { .with_target("want", LevelFilter::WARN) .with_target("async_std", LevelFilter::WARN) .with_target("mio", LevelFilter::WARN) + .with_target("polling", LevelFilter::WARN) .with_default(LevelFilter::TRACE); - clean_old_logs(cache)?; + let logs_dir = log_file.parent().expect("must have parent"); + clean_old_logs(logs_dir)?; - let file_appender = - tracing_appender::rolling::never(cache.join("_logs"), log_file_name()); + let file_appender = tracing_appender::rolling::never( + logs_dir, + log_file.file_name().expect("must have file name"), + ); let (non_blocking, guard) = tracing_appender::non_blocking(file_appender); if self.quiet || self.no_progress { builder - .with(tracing_subscriber::fmt::layer().with_filter(filter)) - .with(fmt::layer().with_writer(non_blocking).with_filter(targets)) + .with( + tracing_subscriber::fmt::layer() + .without_time() + .with_target(false) + .with_filter(filter), + ) + .with( + fmt::layer() + .with_timer(tracing_subscriber::fmt::time::uptime()) + .with_writer(non_blocking) + .with_filter(targets), + ) .init(); } else { builder .with( tracing_subscriber::fmt::layer() + .without_time() + .with_target(false) .with_writer(ilayer.get_stderr_writer()) .with_filter(filter), ) - .with(ilayer) - .with(fmt::layer().with_writer(non_blocking).with_filter(targets)) + .with(ilayer.with_filter(LevelFilter::DEBUG)) + .with( + fmt::layer() + .with_timer(tracing_subscriber::fmt::time::uptime()) + .with_writer(non_blocking) + .with_filter(targets), + ) .init(); }; @@ -180,12 +201,19 @@ impl Orogene { } else { if self.quiet || self.no_progress { builder - .with(tracing_subscriber::fmt::layer().with_filter(filter)) + .with( + tracing_subscriber::fmt::layer() + .without_time() + .with_target(false) + .with_filter(filter), + ) .init(); } else { builder .with( tracing_subscriber::fmt::layer() + .without_time() + .with_target(false) .with_writer(ilayer.get_stderr_writer()) .with_filter(filter), ) @@ -207,7 +235,7 @@ impl Orogene { let mut cfg_builder = OroConfigOptions::new() .set_default("registry", "https://registry.npmjs.org")? - .set_default("loglevel", "warn")? + .set_default("loglevel", "info")? .set_default( "no_emoji", &format!( @@ -238,9 +266,19 @@ impl Orogene { let mut oro = Orogene::from_arg_matches(&matches).into_diagnostic()?; 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); + let log_file = oro + .cache + .clone() + .or_else(|| config.get::("cache").ok().map(PathBuf::from)) + .map(|c| c.join("_logs").join(log_file_name())); + let _guard = oro.setup_logging(log_file.as_deref())?; + oro.execute().await.map_err(|e| { + if let Some(log_file) = log_file.as_deref() { + tracing::error!("A debug log was written to {}", log_file.display()); + } + e + })?; + tracing::debug!("Ran in {}s", start.elapsed().as_millis() as f32 / 1000.0); Ok(()) } } @@ -271,8 +309,8 @@ fn log_file_name() -> PathBuf { PathBuf::from(format!("{}-0.log", prefix)) } -fn clean_old_logs(cache: &Path) -> Result<()> { - if let Ok(readdir) = cache.join("_logs").read_dir() { +fn clean_old_logs(logs_dir: &Path) -> Result<()> { + if let Ok(readdir) = logs_dir.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 { @@ -293,7 +331,7 @@ fn log_command_line() { cmd.push(' '); cmd.push_str(&arg); } - tracing::info!("Running command: {cmd}"); + tracing::debug!("Running command: {cmd}"); } #[derive(Debug, Subcommand)]