From 3acba26db2a3ffa0804208af99071521fc0b6353 Mon Sep 17 00:00:00 2001 From: rami3l Date: Fri, 3 May 2024 19:40:30 +0800 Subject: [PATCH 1/7] chore(deps): make `tracing-subscriber` a hard requirement --- Cargo.toml | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) 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" From f00008cdc3026a682cd4a5ad8bd2bc766095b9f2 Mon Sep 17 00:00:00 2001 From: rami3l Date: Fri, 14 Jun 2024 13:47:24 +0800 Subject: [PATCH 2/7] refactor(test): clean up `before_test_async()` --- rustup-macros/src/lib.rs | 3 +-- src/test.rs | 21 ++++----------------- 2 files changed, 5 insertions(+), 19 deletions(-) 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/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(), + ); } } From a4ce5c218aa0187ff3007a52c3849335e600507e Mon Sep 17 00:00:00 2001 From: rami3l Date: Fri, 14 Jun 2024 11:48:27 +0800 Subject: [PATCH 3/7] refactor(log): reimplement `log` using `tracing` --- src/bin/rustup-init.rs | 32 +++----- src/cli/log.rs | 162 +++++++++++++++++++++++++++-------------- src/currentprocess.rs | 11 ++- src/utils/notify.rs | 28 +++++++ 4 files changed, 154 insertions(+), 79 deletions(-) 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..36a688f935 100644 --- a/src/cli/log.rs +++ b/src/cli/log.rs @@ -1,94 +1,148 @@ 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 ) * ) ) ) + ( $ ( $ arg : tt ) * ) => ( ::tracing::warn ! ( $ ( $ arg ) * ) ) } + macro_rules! err { - ( $ ( $ arg : tt ) * ) => ( $crate::cli::log::err_fmt ( format_args ! ( $ ( $ arg ) * ) ) ) + ( $ ( $ arg : tt ) * ) => ( ::tracing::error ! ( $ ( $ 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 ) * ) ) ) + ( $ ( $ arg : tt ) * ) => ( ::tracing::debug ! ( $ ( $ arg ) * ) ) } macro_rules! debug { - ( $ ( $ arg : tt ) * ) => ( $crate::cli::log::debug_fmt ( format_args ! ( $ ( $ arg ) * ) ) ) + ( $ ( $ arg : tt ) * ) => ( ::tracing::trace ! ( $ ( $ 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 = 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/utils/notify.rs b/src/utils/notify.rs index e30800404f..bc374a04f9 100644 --- a/src/utils/notify.rs +++ b/src/utils/notify.rs @@ -1,3 +1,7 @@ +use std::fmt; + +use tracing::Level; + #[derive(Debug)] pub(crate) enum NotificationLevel { Verbose, @@ -6,3 +10,27 @@ pub(crate) enum NotificationLevel { 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, + } + } +} From b87585ff573728d3d5538c2536f40c76cb0a4f57 Mon Sep 17 00:00:00 2001 From: rami3l Date: Fri, 14 Jun 2024 18:35:25 +0800 Subject: [PATCH 4/7] feat(log): make `console_logger()` accept `RUSTUP_TERM_COLOR` and `NO_COLOR` --- src/cli/log.rs | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/src/cli/log.rs b/src/cli/log.rs index 36a688f935..96c83f4c8b 100644 --- a/src/cli/log.rs +++ b/src/cli/log.rs @@ -64,7 +64,13 @@ fn console_logger(process: Process) -> impl Layer where S: Subscriber + for<'span> LookupSpan<'span>, { - let has_ansi = process.stderr().is_a_tty(); + 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()) From 833c3a0d7dbc664b4a77ba748a70a3d760dfbf10 Mon Sep 17 00:00:00 2001 From: rami3l Date: Fri, 14 Jun 2024 18:42:12 +0800 Subject: [PATCH 5/7] chore(env): retire `RUSTUP_DEBUG` in favor of `RUST_LOG` --- doc/user-guide/src/environment-variables.md | 8 ++++++-- src/diskio/threaded.rs | 7 ------- 2 files changed, 6 insertions(+), 9 deletions(-) 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/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, From e07cf4aa301d4b5550ef3dc56c1ceeb3c397671d Mon Sep 17 00:00:00 2001 From: rami3l Date: Sat, 15 Jun 2024 09:30:35 +0800 Subject: [PATCH 6/7] chore(notify): sort logging macros and `NotificationLevel` on verbosity 50216ad 'reorder' --- src/cli/log.rs | 16 ++++++++-------- src/utils/notify.rs | 2 +- 2 files changed, 9 insertions(+), 9 deletions(-) diff --git a/src/cli/log.rs b/src/cli/log.rs index 96c83f4c8b..84d7b0b3c2 100644 --- a/src/cli/log.rs +++ b/src/cli/log.rs @@ -18,24 +18,24 @@ use opentelemetry_sdk::trace::Tracer; use crate::{currentprocess::Process, utils::notify::NotificationLevel}; -macro_rules! warn { - ( $ ( $ arg : tt ) * ) => ( ::tracing::warn ! ( $ ( $ arg ) * ) ) +macro_rules! debug { + ( $ ( $ arg : tt ) * ) => ( ::tracing::trace ! ( $ ( $ arg ) * ) ) } -macro_rules! err { - ( $ ( $ arg : tt ) * ) => ( ::tracing::error ! ( $ ( $ arg ) * ) ) +macro_rules! verbose { + ( $ ( $ arg : tt ) * ) => ( ::tracing::debug ! ( $ ( $ arg ) * ) ) } macro_rules! info { ( $ ( $ arg : tt ) * ) => ( ::tracing::info ! ( $ ( $ arg ) * ) ) } -macro_rules! verbose { - ( $ ( $ arg : tt ) * ) => ( ::tracing::debug ! ( $ ( $ arg ) * ) ) +macro_rules! warn { + ( $ ( $ arg : tt ) * ) => ( ::tracing::warn ! ( $ ( $ arg ) * ) ) } -macro_rules! debug { - ( $ ( $ arg : tt ) * ) => ( ::tracing::trace ! ( $ ( $ arg ) * ) ) +macro_rules! err { + ( $ ( $ arg : tt ) * ) => ( ::tracing::error ! ( $ ( $ arg ) * ) ) } pub fn tracing_subscriber(process: Process) -> impl tracing::Subscriber { diff --git a/src/utils/notify.rs b/src/utils/notify.rs index bc374a04f9..9bcc6d86ad 100644 --- a/src/utils/notify.rs +++ b/src/utils/notify.rs @@ -4,11 +4,11 @@ use tracing::Level; #[derive(Debug)] pub(crate) enum NotificationLevel { + Debug, Verbose, Info, Warn, Error, - Debug, } impl fmt::Display for NotificationLevel { From c95df353630f86072de4aec676b92d54199a5bbc Mon Sep 17 00:00:00 2001 From: rami3l Date: Sat, 15 Jun 2024 09:35:18 +0800 Subject: [PATCH 7/7] refactor(terminalsource): use `.eq_ignore_ascii_case()` in `ColorableTerminal::new` --- src/currentprocess/terminalsource.rs | 9 +++------ 1 file changed, 3 insertions(+), 6 deletions(-) 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, };