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