diff --git a/Cargo.toml b/Cargo.toml index 455bacdb25..59fde87f47 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -32,7 +32,6 @@ no-self-update = [] otel = [ "dep:opentelemetry-otlp", "dep:tracing-opentelemetry", - "dep:tracing-subscriber", "dep:opentelemetry", "dep:opentelemetry_sdk", ] @@ -87,7 +86,7 @@ tokio.workspace = true tokio-stream.workspace = true toml = "0.8" tracing-opentelemetry = { workspace = true, optional = true } -tracing-subscriber = { workspace = true, optional = true, features = ["env-filter"] } +tracing-subscriber = { workspace = true, features = ["env-filter"] } tracing.workspace = true url.workspace = true wait-timeout = "0.2" diff --git a/doc/user-guide/src/environment-variables.md b/doc/user-guide/src/environment-variables.md index b9df8736a6..9c8c961ad9 100644 --- a/doc/user-guide/src/environment-variables.md +++ b/doc/user-guide/src/environment-variables.md @@ -1,5 +1,10 @@ # Environment variables +- `RUST_LOG` (default: none). Enables Rustup's "custom logging mode". In this mode, + the verbosity of Rustup's log lines can be specified with `tracing_subscriber`'s + [directive syntax]. For example, set `RUST_LOG=rustup=DEBUG` to receive log lines + from `rustup` itself with a maximal verbosity of `DEBUG`. + - `RUSTUP_HOME` (default: `~/.rustup` or `%USERPROFILE%/.rustup`). Sets the root `rustup` folder, used for storing installed toolchains and configuration options. @@ -29,8 +34,6 @@ determines the directory that traces will be written too. Traces are of the form PID.trace. Traces can be read by the Catapult project [tracing viewer]. -- `RUSTUP_DEBUG` *unstable*. When set, enables rustup's debug logging. - - `RUSTUP_TERM_COLOR` (default: `auto`). Controls whether colored output is used in the terminal. Set to `auto` to use colors only in tty streams, to `always` to always enable colors, or to `never` to disable colors. @@ -47,6 +50,7 @@ feature sacrifices some transactions protections and may be removed at any point. Linux only. +[directive syntax]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html#directives [dc]: https://docs.docker.com/storage/storagedriver/overlayfs-driver/#modifying-files-or-directories [override]: overrides.md [tracing viewer]: https://github.com/catapult-project/catapult/blob/master/tracing/README.md diff --git a/rustup-macros/src/lib.rs b/rustup-macros/src/lib.rs index 70048983cd..1dfe6800c8 100644 --- a/rustup-macros/src/lib.rs +++ b/rustup-macros/src/lib.rs @@ -95,7 +95,7 @@ fn test_inner(mod_path: String, mut input: ItemFn) -> syn::Result { let name = input.sig.ident.clone(); let new_block: Block = parse_quote! { { - let _guard = #before_ident().await; + #before_ident().await; // Define a function with same name we can instrument inside the // tracing enablement logic. #[cfg_attr(feature = "otel", tracing::instrument(skip_all))] @@ -118,7 +118,6 @@ fn test_inner(mod_path: String, mut input: ItemFn) -> syn::Result { input.block = Box::new(new_block); Ok(quote! { - #[cfg_attr(feature = "otel", tracing::instrument(skip_all))] #[::tokio::test(flavor = "multi_thread", worker_threads = 1)] #input }) diff --git a/src/bin/rustup-init.rs b/src/bin/rustup-init.rs index b05cbdaade..248198f469 100644 --- a/src/bin/rustup-init.rs +++ b/src/bin/rustup-init.rs @@ -54,29 +54,17 @@ fn main() { } async fn maybe_trace_rustup() -> Result { - #[cfg(not(feature = "otel"))] - { - run_rustup().await - } #[cfg(feature = "otel")] - { - use tracing_subscriber::{layer::SubscriberExt, Registry}; - - let telemetry = { - use opentelemetry::global; - use opentelemetry_sdk::propagation::TraceContextPropagator; - - global::set_text_map_propagator(TraceContextPropagator::new()); - rustup::cli::log::telemetry() - }; - - let subscriber = Registry::default().with(telemetry); - tracing::subscriber::set_global_default(subscriber)?; - let result = run_rustup().await; - // We're tracing, so block until all spans are exported. - opentelemetry::global::shutdown_tracer_provider(); - result - } + opentelemetry::global::set_text_map_propagator( + opentelemetry_sdk::propagation::TraceContextPropagator::new(), + ); + let subscriber = rustup::cli::log::tracing_subscriber(process()); + tracing::subscriber::set_global_default(subscriber)?; + let result = run_rustup().await; + // We're tracing, so block until all spans are exported. + #[cfg(feature = "otel")] + opentelemetry::global::shutdown_tracer_provider(); + result } #[cfg_attr(feature = "otel", tracing::instrument)] diff --git a/src/cli/log.rs b/src/cli/log.rs index 2a3c68a327..84d7b0b3c2 100644 --- a/src/cli/log.rs +++ b/src/cli/log.rs @@ -1,94 +1,154 @@ use std::{fmt, io::Write}; +use termcolor::{Color, ColorSpec, WriteColor}; +use tracing::{level_filters::LevelFilter, Event, Subscriber}; +use tracing_subscriber::{ + fmt::{ + format::{self, FormatEvent, FormatFields}, + FmtContext, + }, + registry::LookupSpan, + EnvFilter, Layer, +}; + #[cfg(feature = "otel")] use once_cell::sync::Lazy; #[cfg(feature = "otel")] use opentelemetry_sdk::trace::Tracer; -#[cfg(feature = "otel")] -use tracing::Subscriber; -#[cfg(feature = "otel")] -use tracing_subscriber::{registry::LookupSpan, EnvFilter, Layer}; -use crate::currentprocess::{process, terminalsource}; +use crate::{currentprocess::Process, utils::notify::NotificationLevel}; -macro_rules! warn { - ( $ ( $ arg : tt ) * ) => ( $crate::cli::log::warn_fmt ( format_args ! ( $ ( $ arg ) * ) ) ) +macro_rules! debug { + ( $ ( $ arg : tt ) * ) => ( ::tracing::trace ! ( $ ( $ arg ) * ) ) } -macro_rules! err { - ( $ ( $ arg : tt ) * ) => ( $crate::cli::log::err_fmt ( format_args ! ( $ ( $ arg ) * ) ) ) + +macro_rules! verbose { + ( $ ( $ arg : tt ) * ) => ( ::tracing::debug ! ( $ ( $ arg ) * ) ) } + macro_rules! info { - ( $ ( $ arg : tt ) * ) => ( $crate::cli::log::info_fmt ( format_args ! ( $ ( $ arg ) * ) ) ) + ( $ ( $ arg : tt ) * ) => ( ::tracing::info ! ( $ ( $ arg ) * ) ) } -macro_rules! verbose { - ( $ ( $ arg : tt ) * ) => ( $crate::cli::log::verbose_fmt ( format_args ! ( $ ( $ arg ) * ) ) ) +macro_rules! warn { + ( $ ( $ arg : tt ) * ) => ( ::tracing::warn ! ( $ ( $ arg ) * ) ) } -macro_rules! debug { - ( $ ( $ arg : tt ) * ) => ( $crate::cli::log::debug_fmt ( format_args ! ( $ ( $ arg ) * ) ) ) +macro_rules! err { + ( $ ( $ arg : tt ) * ) => ( ::tracing::error ! ( $ ( $ arg ) * ) ) } -pub(crate) fn warn_fmt(args: fmt::Arguments<'_>) { - let mut t = process().stderr().terminal(); - let _ = t.fg(terminalsource::Color::Yellow); - let _ = t.attr(terminalsource::Attr::Bold); - let _ = write!(t.lock(), "warning: "); - let _ = t.reset(); - let _ = t.lock().write_fmt(args); - let _ = writeln!(t.lock()); -} +pub fn tracing_subscriber(process: Process) -> impl tracing::Subscriber { + use tracing_subscriber::{layer::SubscriberExt, Registry}; -pub(crate) fn err_fmt(args: fmt::Arguments<'_>) { - let mut t = process().stderr().terminal(); - let _ = t.fg(terminalsource::Color::Red); - let _ = t.attr(terminalsource::Attr::Bold); - let _ = write!(t.lock(), "error: "); - let _ = t.reset(); - let _ = t.lock().write_fmt(args); - let _ = writeln!(t.lock()); + #[cfg(feature = "otel")] + let telemetry = telemetry(&process); + let console_logger = console_logger(process); + #[cfg(feature = "otel")] + { + Registry::default().with(console_logger).with(telemetry) + } + #[cfg(not(feature = "otel"))] + { + Registry::default().with(console_logger) + } } -pub(crate) fn info_fmt(args: fmt::Arguments<'_>) { - let mut t = process().stderr().terminal(); - let _ = t.attr(terminalsource::Attr::Bold); - let _ = write!(t.lock(), "info: "); - let _ = t.reset(); - let _ = t.lock().write_fmt(args); - let _ = writeln!(t.lock()); +/// A [`tracing::Subscriber`] [`Layer`][`tracing_subscriber::Layer`] that prints out the log +/// lines to the current [`Process`]' `stderr`. +/// +/// When the `RUST_LOG` environment variable is present, a standard [`tracing_subscriber`] +/// formatter will be used according to the filtering directives set in its value. +/// Otherwise, this logger will use [`EventFormatter`] to mimic "classic" Rustup `stderr` output. +fn console_logger(process: Process) -> impl Layer +where + S: Subscriber + for<'span> LookupSpan<'span>, +{ + let has_ansi = match process.var("RUSTUP_TERM_COLOR") { + Ok(s) if s.eq_ignore_ascii_case("always") => true, + Ok(s) if s.eq_ignore_ascii_case("never") => false, + // `RUSTUP_TERM_COLOR` is prioritized over `NO_COLOR`. + _ if process.var("NO_COLOR").is_ok() => false, + _ => process.stderr().is_a_tty(), + }; + let maybe_rust_log_directives = process.var("RUST_LOG"); + let logger = tracing_subscriber::fmt::layer() + .with_writer(move || process.stderr()) + .with_ansi(has_ansi); + if let Ok(directives) = maybe_rust_log_directives { + let env_filter = EnvFilter::builder() + .with_default_directive(LevelFilter::INFO.into()) + .parse_lossy(directives); + logger.compact().with_filter(env_filter).boxed() + } else { + // Receive log lines from Rustup only. + let env_filter = EnvFilter::new("rustup=DEBUG"); + logger + .event_format(EventFormatter) + .with_filter(env_filter) + .boxed() + } } -pub(crate) fn verbose_fmt(args: fmt::Arguments<'_>) { - let mut t = process().stderr().terminal(); - let _ = t.fg(terminalsource::Color::Magenta); - let _ = t.attr(terminalsource::Attr::Bold); - let _ = write!(t.lock(), "verbose: "); - let _ = t.reset(); - let _ = t.lock().write_fmt(args); - let _ = writeln!(t.lock()); +// Adapted from +// https://docs.rs/tracing-subscriber/latest/tracing_subscriber/fmt/trait.FormatEvent.html#examples +struct EventFormatter; + +impl FormatEvent for EventFormatter +where + S: Subscriber + for<'a> LookupSpan<'a>, + N: for<'a> FormatFields<'a> + 'static, +{ + fn format_event( + &self, + ctx: &FmtContext<'_, S, N>, + mut writer: format::Writer<'_>, + event: &Event<'_>, + ) -> fmt::Result { + let has_ansi = writer.has_ansi_escapes(); + let level = NotificationLevel::from(*event.metadata().level()); + { + let mut buf = termcolor::Buffer::ansi(); + if has_ansi { + _ = buf.set_color(ColorSpec::new().set_bold(true).set_fg(level.fg_color())); + } + _ = write!(buf, "{level}: "); + if has_ansi { + _ = buf.reset(); + } + writer.write_str(std::str::from_utf8(buf.as_slice()).unwrap())?; + } + ctx.field_format().format_fields(writer.by_ref(), event)?; + writeln!(writer) + } } -pub(crate) fn debug_fmt(args: fmt::Arguments<'_>) { - if process().var("RUSTUP_DEBUG").is_ok() { - let mut t = process().stderr().terminal(); - let _ = t.fg(terminalsource::Color::Blue); - let _ = t.attr(terminalsource::Attr::Bold); - let _ = write!(t.lock(), "debug: "); - let _ = t.reset(); - let _ = t.lock().write_fmt(args); - let _ = writeln!(t.lock()); +impl NotificationLevel { + fn fg_color(&self) -> Option { + match self { + NotificationLevel::Debug => Some(Color::Blue), + NotificationLevel::Verbose => Some(Color::Magenta), + NotificationLevel::Info => None, + NotificationLevel::Warn => Some(Color::Yellow), + NotificationLevel::Error => Some(Color::Red), + } } } /// A [`tracing::Subscriber`] [`Layer`][`tracing_subscriber::Layer`] that corresponds to Rustup's /// optional `opentelemetry` (a.k.a. `otel`) feature. #[cfg(feature = "otel")] -pub fn telemetry() -> impl Layer +fn telemetry(process: &Process) -> impl Layer where S: Subscriber + for<'span> LookupSpan<'span>, { - // NOTE: This reads from the real environment variables instead of `process().var_os()`. - let env_filter = EnvFilter::try_from_default_env().unwrap_or(EnvFilter::new("INFO")); + let env_filter = if let Ok(directives) = process.var("RUST_LOG") { + EnvFilter::builder() + .with_default_directive(LevelFilter::TRACE.into()) + .parse_lossy(directives) + } else { + EnvFilter::new("rustup=TRACE") + }; tracing_opentelemetry::layer() .with_tracer(TELEMETRY_DEFAULT_TRACER.clone()) .with_filter(env_filter) diff --git a/src/currentprocess.rs b/src/currentprocess.rs index 7b3e383ed1..24d7987bed 100644 --- a/src/currentprocess.rs +++ b/src/currentprocess.rs @@ -17,6 +17,7 @@ use std::{ #[cfg(feature = "test")] use rand::{thread_rng, Rng}; +use tracing_subscriber::util::SubscriberInitExt; pub mod filesource; pub mod terminalsource; @@ -181,7 +182,8 @@ where if let Some(old_p) = &*p.borrow() { panic!("current process already set {old_p:?}"); } - *p.borrow_mut() = Some(process); + *p.borrow_mut() = Some(process.clone()); + let _guard = crate::cli::log::tracing_subscriber(process).set_default(); let result = f(); *p.borrow_mut() = None; result @@ -253,8 +255,11 @@ pub fn with_runtime<'a, R>( if let Some(old_p) = &*p.borrow() { panic!("current process already set {old_p:?}"); } - *p.borrow_mut() = Some(process); - let result = runtime.block_on(fut); + *p.borrow_mut() = Some(process.clone()); + let result = runtime.block_on(async { + let _guard = crate::cli::log::tracing_subscriber(process).set_default(); + fut.await + }); *p.borrow_mut() = None; result }) diff --git a/src/currentprocess/terminalsource.rs b/src/currentprocess/terminalsource.rs index a0092908fc..962e92ca8e 100644 --- a/src/currentprocess/terminalsource.rs +++ b/src/currentprocess/terminalsource.rs @@ -84,12 +84,9 @@ impl ColorableTerminal { /// then color commands will be sent to the stream. /// Otherwise color commands are discarded. pub(super) fn new(stream: StreamSelector) -> Self { - let env_override = process() - .var("RUSTUP_TERM_COLOR") - .map(|it| it.to_lowercase()); - let choice = match env_override.as_deref() { - Ok("always") => ColorChoice::Always, - Ok("never") => ColorChoice::Never, + let choice = match process().var("RUSTUP_TERM_COLOR") { + Ok(s) if s.eq_ignore_ascii_case("always") => ColorChoice::Always, + Ok(s) if s.eq_ignore_ascii_case("never") => ColorChoice::Never, _ if stream.is_a_tty() => ColorChoice::Auto, _ => ColorChoice::Never, }; diff --git a/src/diskio/threaded.rs b/src/diskio/threaded.rs index e2732da231..85906b3b84 100644 --- a/src/diskio/threaded.rs +++ b/src/diskio/threaded.rs @@ -305,13 +305,6 @@ impl<'a> Executor for Threaded<'a> { self.tx .send(Task::Sentinel) .expect("must still be listening"); - if crate::currentprocess::process().var("RUSTUP_DEBUG").is_ok() { - // debug! is in the cli layer. erg. And notification stack is still terrible. - debug!(""); - for (bucket, pool) in &self.vec_pools { - debug!("{:?}: {:?}", bucket, pool); - } - } Box::new(JoinIterator { executor: self, consume_sentinel: false, diff --git a/src/test.rs b/src/test.rs index a7a35719e8..2fbd47d972 100644 --- a/src/test.rs +++ b/src/test.rs @@ -224,25 +224,12 @@ where f(&rustup_home) } -pub async fn before_test_async() -> Option { +pub async fn before_test_async() { #[cfg(feature = "otel")] { - use tracing_subscriber::{layer::SubscriberExt, Registry}; - - let telemetry = { - use opentelemetry::global; - use opentelemetry_sdk::propagation::TraceContextPropagator; - - global::set_text_map_propagator(TraceContextPropagator::new()); - crate::cli::log::telemetry() - }; - - let subscriber = Registry::default().with(telemetry); - Some(tracing::subscriber::set_default(subscriber)) - } - #[cfg(not(feature = "otel"))] - { - None + opentelemetry::global::set_text_map_propagator( + opentelemetry_sdk::propagation::TraceContextPropagator::new(), + ); } } diff --git a/src/utils/notify.rs b/src/utils/notify.rs index e30800404f..9bcc6d86ad 100644 --- a/src/utils/notify.rs +++ b/src/utils/notify.rs @@ -1,8 +1,36 @@ +use std::fmt; + +use tracing::Level; + #[derive(Debug)] pub(crate) enum NotificationLevel { + Debug, Verbose, Info, Warn, Error, - Debug, +} + +impl fmt::Display for NotificationLevel { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> fmt::Result { + f.write_str(match self { + NotificationLevel::Debug => "debug", + NotificationLevel::Verbose => "verbose", + NotificationLevel::Info => "info", + NotificationLevel::Warn => "warning", + NotificationLevel::Error => "error", + }) + } +} + +impl From for NotificationLevel { + fn from(level: Level) -> Self { + match level { + Level::TRACE => Self::Debug, + Level::DEBUG => Self::Verbose, + Level::INFO => Self::Info, + Level::WARN => Self::Warn, + Level::ERROR => Self::Error, + } + } }