refactor(log): reimplement log using tracing

Author: rami3l

src/bin/rustup-init.rs

@@ -105,9 +105,12 @@ async fn maybe_trace_rustup() -> Result<utils::ExitCode> {
                 .parse_lossy(directives.to_string_lossy());
             logger.compact().with_filter(env_filter).boxed()
         } else {
-            let env_filter = EnvFilter::new("DEBUG");
-            // FIXME: Add "classical" formatting
-            logger.with_filter(env_filter).boxed()
+            // Receive log lines from Rustup only.
+            let env_filter = EnvFilter::new("rustup=DEBUG");
+            logger
+                .event_format(rustup::cli::log::EventFormatter)
+                .with_filter(env_filter)
+                .boxed()
         }
     };
     let subscriber = {

src/cli/log.rs

@@ -1,75 +1,76 @@
-use std::fmt;
-use std::io::Write;
+use std::{fmt, io::Write};
 
-use crate::currentprocess::{
-    filesource::StderrSource, process, terminalsource, varsource::VarSource,
+use termcolor::{Color, ColorSpec, WriteColor};
+use tracing::{Event, Subscriber};
+use tracing_subscriber::fmt::{
+    format::{self, FormatEvent, FormatFields},
+    FmtContext,
 };
+use tracing_subscriber::registry::LookupSpan;
 
-macro_rules! warn {
-    ( $ ( $ arg : tt ) * ) => ( $crate::cli::log::warn_fmt ( format_args ! ( $ ( $ arg ) * ) ) )
-}
-macro_rules! err {
-    ( $ ( $ arg : tt ) * ) => ( $crate::cli::log::err_fmt ( format_args ! ( $ ( $ arg ) * ) ) )
-}
-macro_rules! info {
-    ( $ ( $ arg : tt ) * ) => ( $crate::cli::log::info_fmt ( format_args ! ( $ ( $ arg ) * ) ) )
+use crate::utils::notify::NotificationLevel;
+
+macro_rules! debug {
+    ( $ ( $ arg : tt ) * ) => ( ::tracing::trace ! ( $ ( $ 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 ) * ) ) )
+macro_rules! info {
+    ( $ ( $ arg : tt ) * ) => ( ::tracing::info ! ( $ ( $ 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());
+macro_rules! warn {
+    ( $ ( $ arg : tt ) * ) => ( ::tracing::warn ! ( $ ( $ arg ) * )  )
 }
 
-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());
+macro_rules! err {
+    ( $ ( $ arg : tt ) * ) => ( ::tracing::error ! ( $ ( $ arg ) * )  )
 }
 
-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());
-}
+// Adapted from
+// https://docs.rs/tracing-subscriber/latest/tracing_subscriber/fmt/trait.FormatEvent.html#examples
+pub struct EventFormatter;
 
-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());
+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),
+        }
     }
 }

src/currentprocess.rs

@@ -169,6 +169,8 @@ pub fn with_runtime<'a, R>(
     mut runtime_builder: tokio::runtime::Builder,
     fut: impl Future<Output = R> + 'a,
 ) -> R {
+    use tracing::instrument::WithSubscriber;
+
     ensure_hook();
 
     let start_process = process.clone();
@@ -215,7 +217,7 @@ pub fn with_runtime<'a, R>(
             panic!("current process already set {old_p:?}");
         }
         *p.borrow_mut() = Some(process);
-        let result = runtime.block_on(fut);
+        let result = runtime.block_on(fut.with_subscriber(console_logger()));
         *p.borrow_mut() = None;
         result
     })

src/utils/notify.rs

@@ -1,8 +1,34 @@
+use std::fmt;
+
 #[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<tracing::Level> for NotificationLevel {
+    fn from(level: tracing::Level) -> Self {
+        match level {
+            tracing::Level::TRACE => Self::Debug,
+            tracing::Level::DEBUG => Self::Verbose,
+            tracing::Level::INFO => Self::Info,
+            tracing::Level::WARN => Self::Warn,
+            tracing::Level::ERROR => Self::Error,
+        }
+    }
 }