Split into -q, default, -v, -vv

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)

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" }

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?;
                     }
 

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 }

crates/uv/src/logging.rs

@@ -1,12 +1,21 @@
-use anyhow::Context;
+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;
@@ -19,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 <https://docs.rs/tracing-subscriber/0.3.18/src/tracing_subscriber/fmt/format/mod.rs.html#1026-1156>
+impl<S, N> FormatEvent<S, N> 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
@@ -31,33 +117,48 @@ pub(crate) fn setup_logging(
     level: Level,
     duration: impl Layer<Registry> + Send + Sync,
 ) -> anyhow::Result<()> {
-    match level {
+    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()
-                .context("Invalid RUST_LOG directives")?;
+            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::stderr),
+                        .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::builder()
-                .with_default_directive(Directive::from_str("uv=debug").unwrap())
-                .from_env()
-                .context("Invalid RUST_LOG directives")?;
-
+        Level::ExtraVerbose => {
             // Regardless of the tracing level, include the uptime and target for each message.
             tracing_subscriber::registry()
                 .with(duration)

crates/uv/src/main.rs

@@ -71,8 +71,8 @@ struct Cli {
     ///
     /// You can configure fine-grained logging using the `RUST_LOG` environment variable.
     /// (<https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html#directives>)
-    #[arg(global = true, long, short, conflicts_with = "quiet")]
-    verbose: bool,
+    #[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")]
@@ -1258,18 +1258,18 @@ async fn run() -> Result<ExitStatus> {
     #[cfg(not(feature = "tracing-durations-export"))]
     let duration_layer = None::<tracing_subscriber::layer::Identity>;
     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