From a667805a4c577d2c7db2c4298a107cafe2d4d1e3 Mon Sep 17 00:00:00 2001 From: rami3l Date: Fri, 14 Jun 2024 11:48:27 +0800 Subject: [PATCH] refactor(log): reimplement `log` using `tracing` --- src/bin/rustup-init.rs | 33 +++----- src/cli/log.rs | 171 +++++++++++++++++++++++++++-------------- src/currentprocess.rs | 11 ++- src/utils/notify.rs | 28 ++++++- 4 files changed, 159 insertions(+), 84 deletions(-) diff --git a/src/bin/rustup-init.rs b/src/bin/rustup-init.rs index b05cbdaade1..92a175b237d 100644 --- a/src/bin/rustup-init.rs +++ b/src/bin/rustup-init.rs @@ -54,31 +54,20 @@ 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 } +// FIXME: Make `tracing::instrument` always run #[cfg_attr(feature = "otel", tracing::instrument)] async fn run_rustup() -> Result { if let Ok(dir) = process().var("RUSTUP_TRACE_DIR") { diff --git a/src/cli/log.rs b/src/cli/log.rs index 2a3c68a327c..fab2f553f1f 100644 --- a/src/cli/log.rs +++ b/src/cli/log.rs @@ -1,94 +1,149 @@ 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.clone()); + 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 maybe_rust_log_directives = process.var_os("RUST_LOG").clone(); + let has_ansi = process.stderr().is_a_tty(); + let logger = tracing_subscriber::fmt::layer() + .with_writer(move || process.stderr()) + .with_ansi(has_ansi); + if let Some(directives) = maybe_rust_log_directives { + let env_filter = EnvFilter::builder() + .with_default_directive(LevelFilter::INFO.into()) + .parse_lossy(directives.to_string_lossy()); + 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 maybe_rust_log_directives = process.var_os("RUST_LOG").clone(); + let env_filter = if let Some(directives) = maybe_rust_log_directives { + EnvFilter::builder() + .with_default_directive(LevelFilter::INFO.into()) + .parse_lossy(directives.to_string_lossy()) + } else { + EnvFilter::new("rustup=DEBUG") + }; tracing_opentelemetry::layer() .with_tracer(TELEMETRY_DEFAULT_TRACER.clone()) .with_filter(env_filter) diff --git a/src/currentprocess.rs b/src/currentprocess.rs index 7b3e383ed1b..24d7987bed6 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 e30800404f2..7c79f10ec68 100644 --- a/src/utils/notify.rs +++ b/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 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, + } + } }