feat: use tracing (#195)

Cargo.toml

@@ -38,7 +38,7 @@ url = "2.4.1"
 tracing = "0.1.37"
 clap = { version = "4.4.6", features = ["derive", "env", "cargo"] }
 minijinja = { version = "1.0.8", features = ["unstable_machinery"] }
-tracing-subscriber = { version = "0.3.17", features = ["env-filter"] }
+tracing-subscriber = { version = "0.3.17", features = ["env-filter", "fmt", "ansi"] }
 num_cpus = "1.16.0"
 goblin = "0.7.1"
 scroll = "0.11.0"
@@ -56,6 +56,9 @@ git2 = { version = "0.18.1", features = ["vendored-openssl"] }
 fs_extra = "1.3.0"
 ignore = "0.4.20"
 globset = "0.4.13"
+tracing-indicatif = "0.3.5"
+clap-verbosity-flag = "2.0.1"
+tracing-core = "0.1.31"
 
 [dev-dependencies]
 insta = {version = "1.33.0", features = ["yaml"] }

src/build.rs

@@ -121,9 +121,9 @@ fn run_process_with_replacements(
                 let filtered_line = replacements
                     .iter()
                     .fold(line, |acc, (from, to)| acc.replace(from, to));
-                println!("{}", filtered_line);
+                tracing::info!("{}", filtered_line);
             } else {
-                eprintln!("Error reading output: {:?}", line);
+                tracing::warn!("Error reading output: {:?}", line);
             }
         }
     }
@@ -235,7 +235,7 @@ pub async fn run_build(
     let test_dir = directories.work_dir.join("test");
     fs::create_dir_all(&test_dir)?;
 
-    println!("{}", output);
+    tracing::info!("{}", output);
 
     tracing::info!("Running tests");
 

src/console_utils.rs

@@ -0,0 +1,65 @@
+use indicatif::MultiProgress;
+use std::io;
+use tracing_core::{Event, Subscriber};
+use tracing_subscriber::{
+    fmt::{
+        format::{self, Format},
+        FmtContext, FormatEvent, FormatFields, MakeWriter,
+    },
+    registry::LookupSpan,
+};
+
+#[derive(Clone)]
+pub struct IndicatifWriter {
+    progress_bars: MultiProgress,
+}
+
+impl IndicatifWriter {
+    pub(crate) fn new(pb: MultiProgress) -> Self {
+        Self { progress_bars: pb }
+    }
+}
+
+impl io::Write for IndicatifWriter {
+    fn write(&mut self, buf: &[u8]) -> io::Result<usize> {
+        self.progress_bars.suspend(|| io::stderr().write(buf))
+    }
+
+    fn flush(&mut self) -> io::Result<()> {
+        self.progress_bars.suspend(|| io::stderr().flush())
+    }
+}
+
+impl<'a> MakeWriter<'a> for IndicatifWriter {
+    type Writer = IndicatifWriter;
+
+    fn make_writer(&'a self) -> Self::Writer {
+        self.clone()
+    }
+}
+
+pub struct TracingFormatter;
+
+impl<S, N> FormatEvent<S, N> for TracingFormatter
+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<'_>,
+    ) -> std::fmt::Result {
+        let metadata = event.metadata();
+        if *metadata.level() == tracing_core::metadata::Level::INFO
+            && metadata.target().starts_with("rattler_build")
+        {
+            ctx.format_fields(writer.by_ref(), event)?;
+            writeln!(writer)
+        } else {
+            let default_format = Format::default();
+            default_format.format_event(ctx, writer, event)
+        }
+    }
+}

src/index.rs

@@ -171,7 +171,7 @@ pub fn index(
                             .packages
                             .insert(p.file_name().unwrap().to_string_lossy().into(), record);
                     } else {
-                        println!("Could not read package record from {:?}", p);
+                        tracing::info!("Could not read package record from {:?}", p);
                     }
                 }
                 ArchiveType::Conda => {
@@ -180,7 +180,7 @@ pub fn index(
                             .conda_packages
                             .insert(p.file_name().unwrap().to_string_lossy().to_string(), record);
                     } else {
-                        println!("Could not read package record from {:?}", p);
+                        tracing::info!("Could not read package record from {:?}", p);
                     }
                 }
             };

src/main.rs

@@ -3,6 +3,7 @@
 use anyhow::Ok;
 use clap::{arg, crate_version, Parser};
 
+use clap_verbosity_flag::{InfoLevel, Verbosity};
 use indicatif::MultiProgress;
 use rattler_conda_types::{package::ArchiveType, NoArchType, Platform};
 use rattler_networking::AuthenticatedClient;
@@ -17,10 +18,10 @@ use std::{
     str::{self, FromStr},
 };
 use test::TestConfiguration;
-use tracing::metadata::LevelFilter;
-use tracing_subscriber::{prelude::*, EnvFilter};
+use tracing_subscriber::{filter::Directive, fmt, prelude::*, EnvFilter};
 
 mod build;
+mod console_utils;
 mod env_vars;
 mod hash;
 mod index;
@@ -42,6 +43,7 @@ use build::run_build;
 mod test;
 
 use crate::{
+    console_utils::{IndicatifWriter, TracingFormatter},
     metadata::{BuildConfiguration, Directories, PackageIdentifier},
     render::recipe::render_recipe,
     variant_config::VariantConfig,
@@ -69,8 +71,8 @@ struct App {
     #[clap(subcommand)]
     subcommand: SubCommands,
 
-    #[clap(short, long, global(true))]
-    verbose: bool,
+    #[command(flatten)]
+    verbose: Verbosity<InfoLevel>,
 }
 
 #[derive(clap::ValueEnum, Clone)]
@@ -127,30 +129,22 @@ struct TestOpts {
 async fn main() -> ExitCode {
     let args = App::parse();
 
-    let default_filter = if args.verbose {
-        LevelFilter::DEBUG
-    } else {
-        LevelFilter::WARN
-    };
-
-    let env_filter = EnvFilter::builder()
-        .with_default_directive(default_filter.into())
-        .from_env()
-        .expect("Could not parse RUST_LOG environment variable")
-        .add_directive("apple_codesign=off".parse().unwrap());
+    let multi_progress = MultiProgress::new();
 
-    tracing_subscriber::fmt()
-        .with_env_filter(env_filter)
-        .with_writer(std::io::stderr)
-        .without_time()
-        .finish()
-        .try_init()
-        .unwrap();
+    // Setup tracing subscriber
+    tracing_subscriber::registry()
+        .with(get_default_env_filter(args.verbose.log_level_filter()))
+        .with(
+            fmt::layer()
+                .with_writer(IndicatifWriter::new(multi_progress.clone()))
+                .event_format(TracingFormatter),
+        )
+        .init();
 
     tracing::info!("Starting the build process");
 
     let result = match args.subcommand {
-        SubCommands::Build(args) => run_build_from_args(args).await,
+        SubCommands::Build(args) => run_build_from_args(args, multi_progress).await,
         SubCommands::Test(args) => run_test_from_args(args).await,
     };
 
@@ -175,7 +169,7 @@ async fn run_test_from_args(args: TestOpts) -> anyhow::Result<()> {
     Ok(())
 }
 
-async fn run_build_from_args(args: BuildOpts) -> anyhow::Result<()> {
+async fn run_build_from_args(args: BuildOpts, multi_progress: MultiProgress) -> anyhow::Result<()> {
     let recipe_path = fs::canonicalize(&args.recipe);
     if let Err(e) = &recipe_path {
         match e.kind() {
@@ -249,7 +243,7 @@ async fn run_build_from_args(args: BuildOpts) -> anyhow::Result<()> {
         .find_variants(&recipe_text, &selector_config)
         .expect("Could not compute variants");
 
-    println!("Found variants:");
+    tracing::info!("Found variants:");
     for variant in &variants {
         let mut table = comfy_table::Table::new();
         table
@@ -259,12 +253,12 @@ async fn run_build_from_args(args: BuildOpts) -> anyhow::Result<()> {
         for (key, value) in variant.iter() {
             table.add_row(vec![key, value]);
         }
-        println!("{}\n", table);
+        tracing::info!("{}\n", table);
     }
 
     let tool_config = tool_configuration::Configuration {
         client: AuthenticatedClient::default(),
-        multi_progress_indicator: MultiProgress::new(),
+        multi_progress_indicator: multi_progress,
     };
 
     for variant in variants {
@@ -298,9 +292,9 @@ async fn run_build_from_args(args: BuildOpts) -> anyhow::Result<()> {
         };
 
         if args.render_only {
-            println!("{}", serde_yaml::to_string(&recipe).unwrap());
-            println!("Variant: {:#?}", variant);
-            println!("Hash: {}", recipe.build.string.unwrap());
+            tracing::info!("{}", serde_yaml::to_string(&recipe).unwrap());
+            tracing::info!("Variant: {:#?}", variant);
+            tracing::info!("Hash: {}", recipe.build.string.unwrap());
             continue;
         }
 
@@ -355,3 +349,18 @@ async fn run_build_from_args(args: BuildOpts) -> anyhow::Result<()> {
 
     Ok(())
 }
+
+/// Constructs a default [`EnvFilter`] that is used when the user did not specify a custom RUST_LOG.
+pub fn get_default_env_filter(verbose: clap_verbosity_flag::LevelFilter) -> EnvFilter {
+    let mut result = EnvFilter::new("rattler_build=info");
+
+    if verbose >= clap_verbosity_flag::LevelFilter::Trace {
+        result = result.add_directive(Directive::from_str("resolvo=info").unwrap());
+        result = result.add_directive(Directive::from_str("rattler=info").unwrap());
+    } else {
+        result = result.add_directive(Directive::from_str("resolvo=warn").unwrap());
+        result = result.add_directive(Directive::from_str("rattler=warn").unwrap());
+    }
+
+    result
+}

src/packaging.rs

@@ -744,12 +744,12 @@ pub fn package_conda(
     }
 
     // print sorted files
-    println!("\nFiles in package:\n");
+    tracing::info!("\nFiles in package:\n");
     tmp_files
         .iter()
         .map(|x| x.strip_prefix(tmp_dir_path).unwrap())
         .sorted()
-        .for_each(|f| println!("  - {}", f.to_string_lossy()));
+        .for_each(|f| tracing::info!("  - {}", f.to_string_lossy()));
 
     let output_folder =
         local_channel_dir.join(output.build_configuration.target_platform.to_string());