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 <Jiahao_XU@outlook.com>

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"
@@ -1807,6 +1821,15 @@ dependencies = [
  "serde",
 ]
 
+[[package]]
+name = "sharded-slab"
+version = "0.1.4"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31"
+dependencies = [
+ "lazy_static",
+]
+
 [[package]]
 name = "signal-hook-registry"
 version = "1.4.0"
@@ -1816,17 +1839,6 @@ dependencies = [
  "libc",
 ]
 
-[[package]]
-name = "simplelog"
-version = "0.12.0"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "48dfff04aade74dd495b007c831cd6f4e0cee19c344dd9dc0884c0289b70a786"
-dependencies = [
- "log",
- "termcolor",
- "time",
-]
-
 [[package]]
 name = "slab"
 version = "0.4.7"
@@ -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"

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"

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<TLSVersion>,
 
+    /// 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,

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

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;

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<Fields> = 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<dyn Subscriber + Send + Sync> = 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
+}

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();
 

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 tokio::sync::mpsc;
-use crate::args::Args;
 
 #[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();
-}

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:");
+            writeln!(io::stderr(), "Fatal error:\n{:?}", Report::new(self)).ok();
-            eprintln!("{:?}", Report::new(self));
         }
 
         code