From f70ae72874feb35e4c8cc17bcc4dd629dc9d9d9b Mon Sep 17 00:00:00 2001 From: konsti Date: Mon, 11 Mar 2024 08:58:31 +0100 Subject: [PATCH] Add a `-vv` log level and make `-v` more readable (#2301) Behind error messages, the debug log is the second most important resource to finding out what and why went wrong when there was a problem with uv. It is important to see which paths it has found and how the decisions in the resolver were made. I'm trying to improve the experience interacting with the debug log. The hierarchical layer is verbose and hard to follow, so it's moved to the `-vv` extra verbose setting, while `-v` works like `RUST_LOG=uv=debug`. For installing jupyter with a warm cache: * Default: https://gist.github.com/konstin/4de6e466127311c5a5fc2f99c56a8e11 * `-v`: https://gist.github.com/konstin/e7bafe0ec7d07e47ba98a3865ae2ef3e * `-vv`: https://gist.github.com/konstin/3ee1aaff37f91cceb6275dd5525f180e Ideally, we would have `-v`, `-vv` and `-vvv`, but we're lacking the the `info!` layer for `-v`, so there's only two layers for now. The `tracing_subcriber` formatter always print the current span, so i replaced it with a custom formatter. ![image](https://github.com/astral-sh/uv/assets/6826232/75f5cfd1-da7b-432e-b090-2f3916930dd1) Best read commit-by-commit. --- Cargo.lock | 13 +++ Cargo.toml | 2 +- crates/uv-interpreter/src/interpreter.rs | 8 +- crates/uv-resolver/src/resolver/mod.rs | 6 +- crates/uv/Cargo.toml | 2 +- crates/uv/src/logging.rs | 139 ++++++++++++++++++++--- crates/uv/src/main.rs | 19 ++-- 7 files changed, 158 insertions(+), 31 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 4b3743590..ae1d4ee6b 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3969,6 +3969,16 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-serde" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bc6b213177105856957181934e4920de57730fc69bf42c37ee5bb664d406d9e1" +dependencies = [ + "serde", + "tracing-core", +] + [[package]] name = "tracing-subscriber" version = "0.3.18" @@ -3979,12 +3989,15 @@ dependencies = [ "nu-ansi-term 0.46.0", "once_cell", "regex", + "serde", + "serde_json", "sharded-slab", "smallvec", "thread_local", "tracing", "tracing-core", "tracing-log", + "tracing-serde", ] [[package]] diff --git a/Cargo.toml b/Cargo.toml index dd50ebb38..1ee58fe71 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -103,7 +103,7 @@ toml = { version = "0.8.8" } tracing = { version = "0.1.40" } tracing-durations-export = { version = "0.2.0", features = ["plot"] } tracing-indicatif = { version = "0.3.6" } -tracing-subscriber = { version = "0.3.18", features = ["env-filter"] } +tracing-subscriber = { version = "0.3.18", features = ["env-filter", "json"] } tracing-tree = { version = "0.3.0" } unicode-width = { version = "0.1.11" } unscanny = { version = "0.1.0" } diff --git a/crates/uv-interpreter/src/interpreter.rs b/crates/uv-interpreter/src/interpreter.rs index 310a7d367..6ff3c326d 100644 --- a/crates/uv-interpreter/src/interpreter.rs +++ b/crates/uv-interpreter/src/interpreter.rs @@ -16,7 +16,7 @@ use platform_host::Platform; use platform_tags::{Tags, TagsError}; use pypi_types::Scheme; use uv_cache::{Cache, CacheBucket, CachedByTimestamp, Freshness, Timestamp}; -use uv_fs::write_atomic_sync; +use uv_fs::{write_atomic_sync, Simplified}; use crate::Error; use crate::Virtualenv; @@ -453,20 +453,20 @@ impl InterpreterInfo { debug!( "Cached interpreter info for Python {}, skipping probing: {}", cached.data.markers.python_full_version, - executable.display() + executable.simplified_display() ); return Ok(cached.data); } debug!( "Ignoring stale cached markers for: {}", - executable.display() + executable.simplified_display() ); } Err(err) => { warn!( "Broken cache entry at {}, removing: {err}", - cache_entry.path().display() + cache_entry.path().simplified_display() ); let _ = fs_err::remove_file(cache_entry.path()); } diff --git a/crates/uv-resolver/src/resolver/mod.rs b/crates/uv-resolver/src/resolver/mod.rs index 8decdf540..1e1e3283e 100644 --- a/crates/uv-resolver/src/resolver/mod.rs +++ b/crates/uv-resolver/src/resolver/mod.rs @@ -809,11 +809,11 @@ impl<'a, Provider: ResolverProvider> Resolver<'a, Provider> { self.markers, )?; - for (package, version) in constraints.iter() { - debug!("Adding transitive dependency: {package}{version}"); + for (dep_package, dep_version) in constraints.iter() { + debug!("Adding transitive dependency for {package}{version}: {dep_package}{dep_version}"); // Emit a request to fetch the metadata for this package. - self.visit_package(package, priorities, request_sink) + self.visit_package(dep_package, priorities, request_sink) .await?; } diff --git a/crates/uv/Cargo.toml b/crates/uv/Cargo.toml index 296983f2b..fa623cae7 100644 --- a/crates/uv/Cargo.toml +++ b/crates/uv/Cargo.toml @@ -67,7 +67,7 @@ tokio = { workspace = true } toml = { workspace = true } tracing = { workspace = true } tracing-durations-export = { workspace = true, features = ["plot"], optional = true } -tracing-subscriber = { workspace = true } +tracing-subscriber = { workspace = true, features = ["json"] } tracing-tree = { workspace = true } unicode-width = { workspace = true } url = { workspace = true } diff --git a/crates/uv/src/logging.rs b/crates/uv/src/logging.rs index 51ab11115..67c491a4d 100644 --- a/crates/uv/src/logging.rs +++ b/crates/uv/src/logging.rs @@ -1,9 +1,21 @@ +use anstream::ColorChoice; +use std::fmt; +use std::str::FromStr; + +use anyhow::Context; +use chrono::Utc; +use owo_colors::OwoColorize; use tracing::level_filters::LevelFilter; +use tracing::{Event, Subscriber}; #[cfg(feature = "tracing-durations-export")] use tracing_durations_export::{ plot::PlotConfig, DurationsLayer, DurationsLayerBuilder, DurationsLayerDropGuard, }; +use tracing_subscriber::filter::Directive; +use tracing_subscriber::fmt::format::Writer; +use tracing_subscriber::fmt::{FmtContext, FormatEvent, FormatFields}; use tracing_subscriber::layer::SubscriberExt; +use tracing_subscriber::registry::LookupSpan; use tracing_subscriber::util::SubscriberInitExt; use tracing_subscriber::{EnvFilter, Layer, Registry}; use tracing_tree::time::Uptime; @@ -16,6 +28,83 @@ pub(crate) enum Level { Default, /// Show debug messages by default (overridable by `RUST_LOG`). Verbose, + /// Show messages in a hierarchical span tree. By default, debug messages are shown (overridable by `RUST_LOG`). + ExtraVerbose, +} + +struct UvFormat { + display_timestamp: bool, + display_level: bool, + show_spans: bool, +} + +/// See +impl FormatEvent for UvFormat +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, +{ + fn format_event( + &self, + ctx: &FmtContext<'_, S, N>, + mut writer: Writer<'_>, + event: &Event<'_>, + ) -> fmt::Result { + let meta = event.metadata(); + let ansi = writer.has_ansi_escapes(); + + if self.display_timestamp { + if ansi { + write!(writer, "{} ", Utc::now().dimmed())?; + } else { + write!(writer, "{} ", Utc::now())?; + } + } + + if self.display_level { + let level = meta.level(); + // Same colors as tracing + if ansi { + match *level { + tracing::Level::TRACE => write!(writer, "{} ", level.purple())?, + tracing::Level::DEBUG => write!(writer, "{} ", level.blue())?, + tracing::Level::INFO => write!(writer, "{} ", level.green())?, + tracing::Level::WARN => write!(writer, "{} ", level.yellow())?, + tracing::Level::ERROR => write!(writer, "{} ", level.red())?, + } + } else { + write!(writer, "{level} ")?; + } + } + + if self.show_spans { + let span = event.parent(); + let mut seen = false; + + let span = span + .and_then(|id| ctx.span(id)) + .or_else(|| ctx.lookup_current()); + + let scope = span.into_iter().flat_map(|span| span.scope().from_root()); + + for span in scope { + seen = true; + if ansi { + write!(writer, "{}:", span.metadata().name().bold())?; + } else { + write!(writer, "{}:", span.metadata().name())?; + } + } + + if seen { + writer.write_char(' ')?; + } + } + + ctx.field_format().format_fields(writer.by_ref(), event)?; + + writeln!(writer) + } } /// Configure `tracing` based on the given [`Level`], taking into account the `RUST_LOG` environment @@ -24,32 +113,52 @@ pub(crate) enum Level { /// The [`Level`] is used to dictate the default filters (which can be overridden by the `RUST_LOG` /// environment variable) along with the formatting of the output. For example, [`Level::Verbose`] /// includes targets and timestamps, along with all `uv=debug` messages by default. -pub(crate) fn setup_logging(level: Level, duration: impl Layer + Send + Sync) { - match level { +pub(crate) fn setup_logging( + level: Level, + duration: impl Layer + Send + Sync, +) -> anyhow::Result<()> { + let default_directive = match level { Level::Default => { // Show nothing, but allow `RUST_LOG` to override. - let filter = EnvFilter::builder() - .with_default_directive(LevelFilter::OFF.into()) - .from_env_lossy(); + LevelFilter::OFF.into() + } + Level::Verbose | Level::ExtraVerbose => { + // Show `DEBUG` messages from the CLI crate, but allow `RUST_LOG` to override. + Directive::from_str("uv=debug").unwrap() + } + }; + let filter = EnvFilter::builder() + .with_default_directive(default_directive) + .from_env() + .context("Invalid RUST_LOG directives")?; + + match level { + Level::Default | Level::Verbose => { // Regardless of the tracing level, show messages without any adornment. + let format = UvFormat { + display_timestamp: false, + display_level: true, + show_spans: false, + }; + let ansi = match anstream::Stderr::choice(&std::io::stderr()) { + ColorChoice::Always | ColorChoice::AlwaysAnsi => true, + ColorChoice::Never => false, + // We just asked anstream for a choice, that can't be auto + ColorChoice::Auto => unreachable!(), + }; tracing_subscriber::registry() .with(duration) .with(filter) .with( tracing_subscriber::fmt::layer() - .without_time() - .with_target(false) - .with_writer(std::io::sink), + .event_format(format) + .with_writer(std::io::stderr) + .with_ansi(ansi), ) .init(); } - Level::Verbose => { - // Show `DEBUG` messages from the CLI crate, but allow `RUST_LOG` to override. - let filter = EnvFilter::try_from_default_env() - .or_else(|_| EnvFilter::try_new("uv=debug")) - .unwrap(); - + Level::ExtraVerbose => { // Regardless of the tracing level, include the uptime and target for each message. tracing_subscriber::registry() .with(duration) @@ -63,6 +172,8 @@ pub(crate) fn setup_logging(level: Level, duration: impl Layer + Send .init(); } } + + Ok(()) } /// Setup the `TRACING_DURATIONS_FILE` environment variable to enable tracing durations. diff --git a/crates/uv/src/main.rs b/crates/uv/src/main.rs index 4b4790452..8271b1ff6 100644 --- a/crates/uv/src/main.rs +++ b/crates/uv/src/main.rs @@ -68,8 +68,11 @@ struct Cli { quiet: bool, /// Use verbose output. - #[arg(global = true, long, short, conflicts_with = "quiet")] - verbose: bool, + /// + /// You can configure fine-grained logging using the `RUST_LOG` environment variable. + /// () + #[arg(global = true, action = clap::ArgAction::Count, long, short, conflicts_with = "quiet")] + verbose: u8, /// Disable colors; provided for compatibility with `pip`. #[arg(global = true, long, hide = true, conflicts_with = "color")] @@ -1255,18 +1258,18 @@ async fn run() -> Result { #[cfg(not(feature = "tracing-durations-export"))] let duration_layer = None::; logging::setup_logging( - if cli.verbose { - logging::Level::Verbose - } else { - logging::Level::Default + match cli.verbose { + 0 => logging::Level::Default, + 1 => logging::Level::Verbose, + 2.. => logging::Level::ExtraVerbose, }, duration_layer, - ); + )?; // Configure the `Printer`, which controls user-facing output in the CLI. let printer = if cli.quiet { printer::Printer::Quiet - } else if cli.verbose { + } else if cli.verbose > 0 { printer::Printer::Verbose } else { printer::Printer::Default