Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

rework log verbosity (-vvv) #11758

Open
wants to merge 3 commits into
base: main
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 3 additions & 0 deletions crates/uv-static/src/env_vars.rs
Original file line number Diff line number Diff line change
Expand Up @@ -548,6 +548,9 @@ impl EnvVars {
/// for more.
pub const RUST_LOG: &'static str = "RUST_LOG";

/// Give log messages more detailed context
pub const UV_LOG_CONTEXT: &'static str = "UV_LOG_CONTEXT";
Comment on lines +551 to +552
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Curious, why this name? Should it be UV_LOG_TREE and/or UV_LOG_DURATIONS? Are these separable concepts?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The two modes in the code make several random format changes, and the best I could come up with to describe them all was "more context". This extra granularity seemed a bit excessive?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I guess while we're touching it I'd rather have extra granularity with clear purpose than a catch-all flag that is mysterious. @konstin may have some thoughts, as he added that initial configuration.

Also cc @MichaReiser as I imagine we'll want a shared experience across the tools long-term.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The behavior is already different:

  • no args: info
  • -v: info
  • -vv: debug
  • -vvv`: trace (but Red Knot / Ruff only). Also changes the output format
  • Use KNOT_LOG for getting non ruff/Red Knot debug information

We also strip trace from release builds.

Regarding the option. I don't have a strong opinion on its name. The main difference to me between the tree/flat layout and how we use it in Red Knot is that the tree layout not only logs messages but also includes the spans (with enter and exit events).

I'd also consider this env var to be outside our versioning policy (unlike UV_LOG) so that we can iterate on naming design. E.g. should it be different env vars to switch between tree/flat but have a different env var that enables span logging for the flat layout? Or does the env var use some form of DSL?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

My overall ideal for the log levels is:

  • Default: You get information about your project only, concisely, so you can actually follow it.
  • -v: You get information about uv and what actions it performs, e.g. uv version, current platform, steps such as lock/sync/install. This information is understandable after read the docs, you could turn this on e.g. by default on CI.
  • -vv (or RUST_LOG=uv=debug): You get debug messages. These are detailed information that expose some internals from uv, but usually written in a way that users can understand. It's the "user serviceable" level. You would run uv ... -vv ... and share the gist when creating a bug report
  • RUST_LOG=...=trace you want to get detailed, very verbose output for a specific area of uv. Requires understanding the uv codebase to interpret, targeted at developers.

I like the proposed changes in shifting us towards that, though I'd skip on exposing RUST_LOG=trace to the CLI, some non-uv crates tend to get really noisy at that level and we've barely ever needed that information.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@MichaReiser

no args: info
-v: info

So -v doesn't do anything?

-vvv`: trace (but Red Knot / Ruff only). Also changes the output format

Why this decision?

We also strip trace from release builds.

This seems dubious to me, we do need our trace logs fairly often for debugging user issues. That said, we don't have an info layer :)

we've barely ever needed that information

I don't know if I agree with this, I need these pretty often for debugging network problems. That said, it is noisy and ideally we'd improve our logging coverage instead.

Copy link
Member

@MichaReiser MichaReiser Feb 25, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

So -v doesn't do anything?

It enables info. We only show warnings by default. The ideal Red Knot output is only diagnostics or a simple "Done" if there are no diagnostics. We use the info to explain what python version we inferred etc but that doesn't seem useful to show by default.

Why this decision?

Because we don't support UV_LOG_CONTEXT and we've found the tree layout useful. But it has come up in the past that we want a dedicated way to switch between how the logs are represented that's independent from the verbosity

This seems dubious to me, we do need our trace logs fairly often for debugging user issues. That said, we don't have an info layer :)

Yeah, we'll see if we need it for Red Knot, but the trace level logs are extremely detailed, and we want to avoid the perf cost.

A side note. We haven't fully figured this out on our side. But that's where we're currently at.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It enables info. We only show warnings by default. The ideal Red Knot output is only diagnostics or a simple "Done" if there are no diagnostics

This makes sense. I think you wrote the wrong thing in the initial post.

Because we don't support UV_LOG_CONTEXT and we've found the tree layout useful. But it has come up in the past that we want a dedicated way to switch between how the logs are represented that's independent from the verbosity

This is helpful. We don't support UV_LOG_CONTEXT either today, it's toggled by the verbosity right now. I think it makes sense for us to move towards a separate option. Do you have opinions on how that's done or named? i.e., comments on my suggestions at the top?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This makes sense. I think you wrote the wrong thing in the initial post.

Oh right

Do you have opinions on how that's done or named? i.e., comments on my suggestions at the top?

Not really beyond what I mentioned in my original reply. But @sharkdp has worked with it more than I did, maybe he has some more thoughts?


/// Use to set the stack size used by uv.
///
/// The value is in bytes, and the default is typically 2MB (2097152).
Expand Down
7 changes: 4 additions & 3 deletions crates/uv/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -279,9 +279,10 @@ async fn run(mut cli: Cli) -> Result<ExitStatus> {
let duration_layer = None::<tracing_subscriber::layer::Identity>;
logging::setup_logging(
match globals.verbose {
0 => logging::Level::Default,
1 => logging::Level::Verbose,
2.. => logging::Level::ExtraVerbose,
0 => logging::Level::Off,
1 => logging::Level::DebugUv,
2 => logging::Level::TraceUv,
3.. => logging::Level::TraceAll,
},
duration_layer,
globals.color,
Expand Down
94 changes: 49 additions & 45 deletions crates/uv/src/logging.rs
Original file line number Diff line number Diff line change
Expand Up @@ -20,18 +20,15 @@ use tracing_tree::time::Uptime;
use tracing_tree::HierarchicalLayer;

use uv_cli::ColorChoice;
#[cfg(feature = "tracing-durations-export")]
use uv_static::EnvVars;

#[derive(Debug, Default, Clone, Copy, PartialEq, Eq)]
pub(crate) enum Level {
/// Suppress all tracing output by default (overridable by `RUST_LOG`).
#[default]
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,
Off,
DebugUv,
TraceUv,
TraceAll,
}

struct UvFormat {
Expand Down Expand Up @@ -120,15 +117,24 @@ pub(crate) fn setup_logging(
durations: impl Layer<Registry> + Send + Sync,
color: ColorChoice,
) -> anyhow::Result<()> {
// We use directives here to ensure `RUST_LOG` can override them
let default_directive = match level {
Level::Default => {
// Show nothing, but allow `RUST_LOG` to override.
Level::Off => {
// Show nothing
tracing::level_filters::LevelFilter::OFF.into()
}
Level::Verbose | Level::ExtraVerbose => {
// Show `DEBUG` messages from the CLI crate, but allow `RUST_LOG` to override.
Level::DebugUv => {
// Show `DEBUG` messages from the CLI crate (and ERROR/WARN/INFO)
Directive::from_str("uv=debug").unwrap()
}
Level::TraceUv => {
// Show `TRACE` messages from the CLI crate (and ERROR/WARN/INFO/DEBUG)
Directive::from_str("uv=trace").unwrap()
}
Level::TraceAll => {
// Show all `TRACE` messages (and ERROR/WARN/INFO/DEBUG)
Directive::from_str("trace").unwrap()
}
};

// Only record our own spans.
Expand Down Expand Up @@ -160,40 +166,38 @@ pub(crate) fn setup_logging(
};
let writer = std::sync::Mutex::new(anstream::AutoStream::new(std::io::stderr(), color_choice));

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

tracing_subscriber::registry()
.with(durations_layer)
.with(
tracing_subscriber::fmt::layer()
.event_format(format)
.with_writer(writer)
.with_ansi(ansi)
.with_filter(filter),
)
.init();
}
Level::ExtraVerbose => {
// Regardless of the tracing level, include the uptime and target for each message.
tracing_subscriber::registry()
.with(durations_layer)
.with(
HierarchicalLayer::default()
.with_targets(true)
.with_timer(Uptime::default())
.with_writer(writer)
.with_ansi(ansi)
.with_filter(filter),
)
.init();
}
let detailed_logging = std::env::var(EnvVars::UV_LOG_CONTEXT).is_ok();
if detailed_logging {
// Regardless of the tracing level, include the uptime and target for each message.
tracing_subscriber::registry()
.with(durations_layer)
.with(
HierarchicalLayer::default()
.with_targets(true)
.with_timer(Uptime::default())
.with_writer(writer)
.with_ansi(ansi)
.with_filter(filter),
)
.init();
} else {
// Regardless of the tracing level, show messages without any adornment.
let format = UvFormat {
display_timestamp: false,
display_level: true,
show_spans: false,
};

tracing_subscriber::registry()
.with(durations_layer)
.with(
tracing_subscriber::fmt::layer()
.event_format(format)
.with_writer(writer)
.with_ansi(ansi)
.with_filter(filter),
)
.init();
}

Ok(())
Expand Down
4 changes: 4 additions & 0 deletions docs/configuration/environment.md
Original file line number Diff line number Diff line change
Expand Up @@ -173,6 +173,10 @@ a link mode.
Equivalent to the `--locked` command-line argument. If set, uv will assert that the
`uv.lock` remains unchanged.

### `UV_LOG_CONTEXT`

Give log messages more detailed context

### `UV_NATIVE_TLS`

Equivalent to the `--native-tls` command-line argument. If set to `true`, uv will
Expand Down
Loading