mirrors/uv
1
0
Fork 0
mirror of https://github.com/astral-sh/uv.git synced 2025-11-01 20:31:12 +00:00
Code Issues Projects Releases Packages Wiki Activity Actions 3

Add a -vv log level and make -v more readable (#2301)

Browse source 
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](75f5cfd1-da7b-432e-b090-2f3916930dd1)

Best read commit-by-commit.
This commit is contained in:
konsti 2024-03-11 08:58:31 +01:00 • committed by GitHub
parent b9b4109ad8
commit f70ae72874
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
7 changed files with 158 additions and 31 deletions
Download patch file Download diff file Expand all files Collapse all files

13
Cargo.lock generated
View file

@ -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]]

2
Cargo.toml
View file

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

8
crates/uv-interpreter/src/interpreter.rs
View file

@ -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());
}

6
crates/uv-resolver/src/resolver/mod.rs
View file

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

2
crates/uv/Cargo.toml
View file

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

139
crates/uv/src/logging.rs
View file

@ -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 <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
@ -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<Registry> + Send + Sync) {
match level {
pub(crate) fn setup_logging(
level: Level,
duration: impl Layer<Registry> + 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<Registry> + Send
.init();
}
}
Ok(())
}
/// Setup the `TRACING_DURATIONS_FILE` environment variable to enable tracing durations.

19
crates/uv/src/main.rs
View file

@ -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.
/// (<https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html#directives>)
#[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<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