From 3841762a5bc595294910aec44a3614285dc1f81e Mon Sep 17 00:00:00 2001 From: Jiahao XU Date: Fri, 11 Nov 2022 10:05:09 +1100 Subject: [PATCH] Replace `simplelog` with `tracing_subscriber::fmt` (#525) * Disable feat log-always of dep tracing * Add dep tracing-log 0.1.3 with no feat * Add new dep tracing-appender v0.2.2 * Add dep tracing-subscriber 0.3.16 with feat fmt and json * Fix `MainExit::report`: Do not use `log::{error, warn}` since `MainExit::report` might be called with no `log`ger, it can only use `println!` and `eprintln!`. * Use `tracing_subscriber::fmt` instead of `simple_log` * Rm unused dep simplelog from crates/bin * Fix `BinstallError::report`: Avoid `log::{warn, error}` since they might be called after `tracing_appender::WorkerGuard` is dropped. * Make tracing output more readable to end users * Add new dep tracing-core v0.1.30 * Add new dep once_cell v1.16.0 * Refactor: Extract new mod `logging` * Add new option `Args::json_output` * Fix `MainExit::report`: Ignore io error * Fix `BinstallError::report`: Ignore IO error Signed-off-by: Jiahao XU --- Cargo.lock | 103 +++++++++++++++---- crates/bin/Cargo.toml | 8 +- crates/bin/src/args.rs | 4 + crates/bin/src/bin_util.rs | 6 +- crates/bin/src/lib.rs | 1 + crates/bin/src/logging.rs | 183 ++++++++++++++++++++++++++++++++++ crates/bin/src/main.rs | 5 +- crates/bin/src/ui.rs | 29 +----- crates/binstalk/src/errors.rs | 8 +- 9 files changed, 289 insertions(+), 58 deletions(-) create mode 100644 crates/bin/src/logging.rs diff --git a/Cargo.lock b/Cargo.lock index c5d5d2c67..727df5f05 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -267,11 +267,15 @@ dependencies = [ "log", "miette", "mimalloc", + "once_cell", "semver", - "simplelog", "tempfile", "tokio", "tracing", + "tracing-appender", + "tracing-core", + "tracing-log", + "tracing-subscriber", ] [[package]] @@ -430,6 +434,16 @@ dependencies = [ "cfg-if", ] +[[package]] +name = "crossbeam-channel" +version = "0.5.6" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "c2dd04ddaf88237dc3b8d8f9a3c1004b506b54b3313403944054d23c0870c521" +dependencies = [ + "cfg-if", + "crossbeam-utils", +] + [[package]] name = "crossbeam-utils" version = "0.8.11" @@ -1808,23 +1822,21 @@ dependencies = [ ] [[package]] -name = "signal-hook-registry" -version = "1.4.0" +name = "sharded-slab" +version = "0.1.4" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "e51e73328dc4ac0c7ccbda3a494dfa03df1de2f46018127f60c693f2648455b0" +checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31" dependencies = [ - "libc", + "lazy_static", ] [[package]] -name = "simplelog" -version = "0.12.0" +name = "signal-hook-registry" +version = "1.4.0" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "48dfff04aade74dd495b007c831cd6f4e0cee19c344dd9dc0884c0289b70a786" +checksum = "e51e73328dc4ac0c7ccbda3a494dfa03df1de2f46018127f60c693f2648455b0" dependencies = [ - "log", - "termcolor", - "time", + "libc", ] [[package]] @@ -1992,6 +2004,15 @@ dependencies = [ "syn", ] +[[package]] +name = "thread_local" +version = "1.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5516c27b78311c50bf42c071425c560ac799b11c30b31f87e3081965fe5e0180" +dependencies = [ + "once_cell", +] + [[package]] name = "time" version = "0.3.14" @@ -2001,15 +2022,8 @@ dependencies = [ "itoa", "libc", "num_threads", - "time-macros", ] -[[package]] -name = "time-macros" -version = "0.2.4" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "42657b1a6f4d817cda8e7a0ace261fe0cc946cf3a80314390b22cc61ae080792" - [[package]] name = "tinytemplate" version = "1.2.1" @@ -2173,6 +2187,17 @@ dependencies = [ "tracing-core", ] +[[package]] +name = "tracing-appender" +version = "0.2.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "09d48f71a791638519505cefafe162606f706c25592e4bde4d97600c0195312e" +dependencies = [ + "crossbeam-channel", + "time", + "tracing-subscriber", +] + [[package]] name = "tracing-core" version = "0.1.30" @@ -2180,6 +2205,42 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "24eb03ba0eab1fd845050058ce5e616558e8f8d8fca633e6b163fe25c797213a" dependencies = [ "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "78ddad33d2d10b1ed7eb9d1f518a5674713876e97e5bb9b7345a7984fbb4f922" +dependencies = [ + "lazy_static", + "log", + "tracing-core", +] + +[[package]] +name = "tracing-serde" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bc6b213177105856957181934e4920de57730fc69bf42c37ee5bb664d406d9e1" +dependencies = [ + "serde", + "tracing-core", +] + +[[package]] +name = "tracing-subscriber" +version = "0.3.16" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a6176eae26dd70d0c919749377897b54a9276bd7061339665dd68777926b5a70" +dependencies = [ + "serde", + "serde_json", + "sharded-slab", + "thread_local", + "tracing-core", + "tracing-serde", ] [[package]] @@ -2308,6 +2369,12 @@ dependencies = [ "serde", ] +[[package]] +name = "valuable" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d" + [[package]] name = "vcpkg" version = "0.2.15" diff --git a/crates/bin/Cargo.toml b/crates/bin/Cargo.toml index d8b8f80e4..27560eca6 100644 --- a/crates/bin/Cargo.toml +++ b/crates/bin/Cargo.toml @@ -29,11 +29,15 @@ dirs = "4.0.0" log = "0.4.17" miette = "5.4.1" mimalloc = { version = "0.1.31", default-features = false, optional = true } +once_cell = "1.16.0" semver = "1.0.14" -simplelog = "0.12.0" tempfile = "3.3.0" tokio = { version = "1.21.2", features = ["rt-multi-thread"], default-features = false } -tracing = { version = "0.1.37", features = ["log-always"], default-features = false } +tracing-core = "0.1.30" +tracing = { version = "0.1.37", default-features = false } +tracing-log = { version = "0.1.3", default-features = false } +tracing-appender = "0.2.2" +tracing-subscriber = { version = "0.3.16", features = ["fmt", "json"], default-features = false } [build-dependencies] embed-resource = "1.7.4" diff --git a/crates/bin/src/args.rs b/crates/bin/src/args.rs index 0f2af0f76..9ca2ae30f 100644 --- a/crates/bin/src/args.rs +++ b/crates/bin/src/args.rs @@ -188,6 +188,10 @@ pub struct Args { #[clap(help_heading = "Options", long, value_enum, value_name = "VERSION")] pub min_tls_version: Option, + /// Print logs in json format to be parsable. + #[clap(help_heading = "Options", long)] + pub json_output: bool, + /// Print version information #[clap(help_heading = "Meta", short = 'V')] pub version: bool, diff --git a/crates/bin/src/bin_util.rs b/crates/bin/src/bin_util.rs index 1fe6f6aef..e1732dc9f 100644 --- a/crates/bin/src/bin_util.rs +++ b/crates/bin/src/bin_util.rs @@ -1,12 +1,12 @@ use std::{ future::Future, + io::{self, Write}, process::{ExitCode, Termination}, time::Duration, }; use binstalk::errors::BinstallError; use binstalk::helpers::{signal::cancel_on_user_sig_term, tasks::AutoAbortJoinHandle}; -use log::{error, info}; use miette::Result; use tokio::runtime::Runtime; @@ -21,13 +21,13 @@ impl Termination for MainExit { match self { Self::Success(spent) => { if let Some(spent) = spent { - info!("Done in {spent:?}"); + writeln!(io::stdout(), "Done in {spent:?}").ok(); } ExitCode::SUCCESS } Self::Error(err) => err.report(), Self::Report(err) => { - error!("Fatal error:\n{err:?}"); + writeln!(io::stderr(), "Fatal error:\n{err:?}").ok(); ExitCode::from(16) } } diff --git a/crates/bin/src/lib.rs b/crates/bin/src/lib.rs index 4f443dbe1..d32215954 100644 --- a/crates/bin/src/lib.rs +++ b/crates/bin/src/lib.rs @@ -2,4 +2,5 @@ pub mod args; pub mod bin_util; pub mod entry; pub mod install_path; +pub mod logging; pub mod ui; diff --git a/crates/bin/src/logging.rs b/crates/bin/src/logging.rs new file mode 100644 index 000000000..6787d0d6f --- /dev/null +++ b/crates/bin/src/logging.rs @@ -0,0 +1,183 @@ +use std::{cmp::min, io, iter::repeat}; + +use log::{LevelFilter, Log, STATIC_MAX_LEVEL}; +use once_cell::sync::Lazy; +use tracing::{ + callsite::Callsite, + dispatcher, field, + subscriber::{self, set_global_default}, + Event, Level, Metadata, +}; +use tracing_appender::non_blocking::{NonBlockingBuilder, WorkerGuard}; +use tracing_core::{identify_callsite, metadata::Kind, subscriber::Subscriber}; +use tracing_log::AsTrace; +use tracing_subscriber::{filter::targets::Targets, fmt::fmt, layer::SubscriberExt}; + +use crate::args::Args; + +// Shamelessly taken from tracing-log + +struct Fields { + message: field::Field, +} + +static FIELD_NAMES: &[&str] = &["message"]; + +impl Fields { + fn new(cs: &'static dyn Callsite) -> Self { + let fieldset = cs.metadata().fields(); + let message = fieldset.field("message").unwrap(); + Fields { message } + } +} + +macro_rules! log_cs { + ($level:expr, $cs:ident, $meta:ident, $fields:ident, $ty:ident) => { + struct $ty; + static $cs: $ty = $ty; + static $meta: Metadata<'static> = Metadata::new( + "log event", + "log", + $level, + None, + None, + None, + field::FieldSet::new(FIELD_NAMES, identify_callsite!(&$cs)), + Kind::EVENT, + ); + static $fields: Lazy = Lazy::new(|| Fields::new(&$cs)); + + impl Callsite for $ty { + fn set_interest(&self, _: subscriber::Interest) {} + fn metadata(&self) -> &'static Metadata<'static> { + &$meta + } + } + }; +} + +log_cs!( + Level::TRACE, + TRACE_CS, + TRACE_META, + TRACE_FIELDS, + TraceCallsite +); +log_cs!( + Level::DEBUG, + DEBUG_CS, + DEBUG_META, + DEBUG_FIELDS, + DebugCallsite +); +log_cs!(Level::INFO, INFO_CS, INFO_META, INFO_FIELDS, InfoCallsite); +log_cs!(Level::WARN, WARN_CS, WARN_META, WARN_FIELDS, WarnCallsite); +log_cs!( + Level::ERROR, + ERROR_CS, + ERROR_META, + ERROR_FIELDS, + ErrorCallsite +); + +fn loglevel_to_cs(level: log::Level) -> (&'static Fields, &'static Metadata<'static>) { + match level { + log::Level::Trace => (&*TRACE_FIELDS, &TRACE_META), + log::Level::Debug => (&*DEBUG_FIELDS, &DEBUG_META), + log::Level::Info => (&*INFO_FIELDS, &INFO_META), + log::Level::Warn => (&*WARN_FIELDS, &WARN_META), + log::Level::Error => (&*ERROR_FIELDS, &ERROR_META), + } +} + +struct Logger; + +impl Logger { + fn init(log_level: LevelFilter) { + log::set_max_level(log_level); + log::set_logger(&Self).unwrap(); + } +} + +impl Log for Logger { + fn enabled(&self, metadata: &log::Metadata<'_>) -> bool { + if metadata.level() > log::max_level() { + // First, check the log record against the current max level enabled. + false + } else { + // Check if the current `tracing` dispatcher cares about this. + dispatcher::get_default(|dispatch| dispatch.enabled(&metadata.as_trace())) + } + } + + fn log(&self, record: &log::Record<'_>) { + // Dispatch manually instead of using methods provided by tracing-log + // to avoid having fields "log.target = ..." in the log message, + // which makes the log really hard to read. + if self.enabled(record.metadata()) { + dispatcher::get_default(|dispatch| { + let (keys, meta) = loglevel_to_cs(record.level()); + + dispatch.event(&Event::new( + meta, + &meta + .fields() + .value_set(&[(&keys.message, Some(record.args() as &dyn field::Value))]), + )); + }); + } + } + + fn flush(&self) {} +} + +pub fn logging(args: &Args) -> WorkerGuard { + // Calculate log_level + let log_level = min(args.log_level, STATIC_MAX_LEVEL); + + let allowed_targets = + (log_level != LevelFilter::Trace).then_some(["binstalk", "cargo_binstall"]); + + // Forward log to tracing + Logger::init(log_level); + + // Setup non-blocking stdout + let (non_blocking, guard) = NonBlockingBuilder::default() + .lossy(false) + .finish(io::stdout()); + + // Build fmt subscriber + let log_level = log_level.as_trace(); + let subscriber_builder = fmt().with_writer(non_blocking).with_max_level(log_level); + + let subscriber: Box = if args.json_output { + Box::new(subscriber_builder.json().finish()) + } else { + Box::new( + subscriber_builder + .compact() + // Disable time, target, file, line_num, thread name/ids to make the + // output more readable + .without_time() + .with_target(false) + .with_file(false) + .with_line_number(false) + .with_thread_names(false) + .with_thread_ids(false) + .finish(), + ) + }; + + // Builder layer for filtering + let filter_layer = allowed_targets.map(|allowed_targets| { + Targets::new().with_targets(allowed_targets.into_iter().zip(repeat(log_level))) + }); + + // Builder final subscriber with filtering + let subscriber = subscriber.with(filter_layer); + + // Setup global subscriber + set_global_default(subscriber).unwrap(); + + guard +} diff --git a/crates/bin/src/main.rs b/crates/bin/src/main.rs index b80cd006f..fff42ee55 100644 --- a/crates/bin/src/main.rs +++ b/crates/bin/src/main.rs @@ -6,7 +6,8 @@ use log::debug; use cargo_binstall::{ args, bin_util::{run_tokio_main, MainExit}, - entry, ui, + entry, + logging::logging, }; #[cfg(feature = "mimalloc")] @@ -26,7 +27,7 @@ fn main() -> MainExit { println!("{}", env!("CARGO_PKG_VERSION")); MainExit::Success(None) } else { - ui::logging(&args); + let _guard = logging(&args); let start = Instant::now(); diff --git a/crates/bin/src/ui.rs b/crates/bin/src/ui.rs index 715cc7b61..19667e0c5 100644 --- a/crates/bin/src/ui.rs +++ b/crates/bin/src/ui.rs @@ -1,16 +1,10 @@ use std::{ - cmp::min, io::{self, BufRead, Write}, thread, }; -use log::{LevelFilter, STATIC_MAX_LEVEL}; -use simplelog::{ColorChoice, ConfigBuilder, TermLogger, TerminalMode}; -use tokio::sync::mpsc; - use binstalk::errors::BinstallError; - -use crate::args::Args; +use tokio::sync::mpsc; #[derive(Debug)] struct UIThreadInner { @@ -102,24 +96,3 @@ impl UIThread { } } } - -pub fn logging(args: &Args) { - let log_level = min(args.log_level, STATIC_MAX_LEVEL); - - // Setup logging - let mut log_config = ConfigBuilder::new(); - - if log_level != LevelFilter::Trace { - log_config.add_filter_allow_str("binstalk"); - log_config.add_filter_allow_str("cargo_binstall"); - } - - log_config.set_location_level(LevelFilter::Off); - TermLogger::init( - log_level, - log_config.build(), - TerminalMode::Mixed, - ColorChoice::Auto, - ) - .unwrap(); -} diff --git a/crates/binstalk/src/errors.rs b/crates/binstalk/src/errors.rs index 0fc369702..b618eba48 100644 --- a/crates/binstalk/src/errors.rs +++ b/crates/binstalk/src/errors.rs @@ -1,11 +1,10 @@ use std::{ - io, + io::{self, Write}, path::PathBuf, process::{ExitCode, ExitStatus, Termination}, }; use compact_str::CompactString; -use log::{error, warn}; use miette::{Diagnostic, Report}; use thiserror::Error; use tokio::task; @@ -383,10 +382,9 @@ impl Termination for BinstallError { fn report(self) -> ExitCode { let code = self.exit_code(); if let BinstallError::UserAbort = self { - warn!("Installation cancelled"); + writeln!(io::stdout(), "Installation cancelled").ok(); } else { - error!("Fatal error:"); - eprintln!("{:?}", Report::new(self)); + writeln!(io::stderr(), "Fatal error:\n{:?}", Report::new(self)).ok(); } code