chore(dist/features): ship tracing and friends by default

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"

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

rustup-macros/src/lib.rs

@@ -95,7 +95,7 @@ fn test_inner(mod_path: String, mut input: ItemFn) -> syn::Result<TokenStream> {
     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<TokenStream> {
     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
     })

src/bin/rustup-init.rs

@@ -54,29 +54,17 @@ fn main() {
 }
 
 async fn maybe_trace_rustup() -> Result<utils::ExitCode> {
-    #[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)]

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<S>(process: Process) -> impl Layer<S>
+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<S, N> FormatEvent<S, N> 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<Color> {
+        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<S>() -> impl Layer<S>
+fn telemetry<S>(process: &Process) -> impl Layer<S>
 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)

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

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

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,