use a custom log layer

Cargo.toml

@@ -106,6 +106,7 @@ os_pipe = "1.1.5"
 reqwest-middleware = "0.2.4"
 rattler_installs_packages = { version = "0.8.0", default-features = false }
 async-once-cell = "0.5.3"
+terminal_size = "0.3.0"
 
 [dev-dependencies]
 insta = { version = "1.34.0", features = ["yaml"] }

src/build.rs

@@ -206,6 +206,10 @@ pub async fn run_build(
     output: &Output,
     tool_configuration: tool_configuration::Configuration,
 ) -> miette::Result<PathBuf> {
+    let name = &output.name().as_normalized();
+    let span = tracing::span!(tracing::Level::INFO, "Running build for {recipe}", recipe = %name);
+    let _enter = span.enter();
+
     let directories = &output.build_configuration.directories;
 
     index(
@@ -218,6 +222,8 @@ pub async fn run_build(
     let mut channels = vec![directories.output_dir.to_string_lossy().to_string()];
     channels.extend(output.build_configuration.channels.clone());
 
+    let my_span = tracing::span!(tracing::Level::INFO, "Fetch source code");
+    let enter = my_span.enter();
     let output = if let Some(finalized_sources) = &output.finalized_sources {
         fetch_sources(
             finalized_sources,
@@ -244,7 +250,10 @@ pub async fn run_build(
             ..output.clone()
         }
     };
+    drop(enter);
 
+    let my_span = tracing::span!(tracing::Level::INFO, "Resolving environments");
+    let enter = my_span.enter();
     let output = if output.finalized_dependencies.is_some() {
         tracing::info!("Using finalized dependencies");
 
@@ -265,7 +274,10 @@ pub async fn run_build(
             ..output.clone()
         }
     };
+    drop(enter);
 
+    let my_span = tracing::span!(tracing::Level::INFO, "Building package");
+    let enter = my_span.enter();
     let build_script = get_conda_build_script(&output, directories).into_diagnostic()?;
     tracing::info!("Work dir: {:?}", &directories.work_dir);
     tracing::info!("Build script: {:?}", build_script);
@@ -300,6 +312,7 @@ pub async fn run_build(
             ),
         ],
     )?;
+    drop(enter);
 
     let files_after = Files::from_prefix(
         &directories.host_prefix,

src/console_utils.rs

@@ -1,16 +1,19 @@
-use indicatif::{MultiProgress};
 use console::style;
+use indicatif::MultiProgress;
 use std::{
-    io,
+    io::{self, Write},
     sync::{Arc, Mutex},
 };
-use tracing_core::{Event, Subscriber};
+use tracing::field;
+use tracing_core::{span::Id, Event, Field, Subscriber};
 use tracing_subscriber::{
     fmt::{
         format::{self, Format},
         FmtContext, FormatEvent, FormatFields, MakeWriter,
     },
+    layer::Context,
     registry::LookupSpan,
+    Layer,
 };
 
 #[derive(Clone)]
@@ -80,6 +83,9 @@ where
         event: &Event<'_>,
     ) -> std::fmt::Result {
         let metadata = event.metadata();
+        // println!("metadata: {:?}", metadata);
+        // println!("full event: {:?}", event);
+        println!("span: {:?}", ctx.current_span());
 
         fn indent_levels(indent: usize) -> String {
             let mut s = String::new();
@@ -94,7 +100,12 @@ where
             let splitted = metadata.target().split("::").collect::<Vec<&str>>();
             if splitted.len() < inner.indentation_level {
                 // print section footer
-                writeln!(writer, "{} {} ", indent_levels(inner.indentation_level - 1), style("╰─").cyan())?;
+                writeln!(
+                    writer,
+                    "{} {} ",
+                    indent_levels(inner.indentation_level - 1),
+                    style("╰─").cyan()
+                )?;
             } else {
                 inner.indentation_level = splitted.len();
                 // print section header
@@ -118,12 +129,7 @@ where
 
             let lines = temp.lines();
             for l in lines {
-                writeln!(
-                    writer,
-                    "{} {}",
-                    indent_levels(inner.indentation_level),
-                    l
-                )?;
+                writeln!(writer, "{} {}", indent_levels(inner.indentation_level), l)?;
             }
             Ok(())
         } else {
@@ -132,3 +138,170 @@ where
         }
     }
 }
+
+pub struct CustomLayer {
+    shared_state: Arc<Mutex<SharedState>>,
+    writer: IndicatifWriter,
+}
+
+impl CustomLayer {
+    pub fn new(writer: IndicatifWriter) -> Self {
+        Self {
+            shared_state: Arc::new(Mutex::new(SharedState::new())),
+            writer,
+        }
+    }
+}
+
+struct SharedState {
+    indentation_level: usize,
+}
+
+impl SharedState {
+    fn new() -> Self {
+        Self {
+            indentation_level: 0,
+        }
+    }
+}
+
+struct CustomVisitor<'a> {
+    writer: &'a mut dyn io::Write,
+    result: io::Result<()>,
+}
+
+impl<'a> CustomVisitor<'a> {
+    fn new(writer: &'a mut dyn io::Write) -> Self {
+        Self {
+            writer,
+            result: Ok(()),
+        }
+    }
+}
+
+impl<'a> field::Visit for CustomVisitor<'a> {
+    fn record_str(&mut self, field: &Field, value: &str) {
+        // if self.result.is_err() {
+        //     return;
+        // }
+
+        if field.name() == "message" {
+            self.record_debug(field, &format_args!("{}", value))
+        }
+    }
+    fn record_debug(&mut self, field: &Field, value: &dyn std::fmt::Debug) {
+        if self.result.is_err() {
+            return;
+        }
+
+        // self.maybe_pad();
+        self.result = match field.name() {
+            "message" => write!(self.writer, "{:?}", value),
+            _ => Ok(()),
+            // name => write!(self.writer, "{}{}{:?}", name, "=", value),
+        };
+    }
+}
+
+fn chunk_string_without_ansi(input: &str, max_chunk_length: usize) -> Vec<String> {
+    let mut chunks: Vec<String> = vec![];
+    let mut current_chunk = String::new();
+    let mut current_length = 0;
+    let mut chars = input.chars().peekable();
+
+    while let Some(c) = chars.next() {
+        if c == '\x1B' {
+            // Beginning of an ANSI escape sequence
+            current_chunk.push(c);
+            while let Some(&next_char) = chars.peek() {
+                current_chunk.push(chars.next().unwrap()); // Add to current chunk
+                if ('a'..='z').contains(&next_char) || ('A'..='Z').contains(&next_char) {
+                    break; // End of ANSI escape sequence
+                }
+            }
+        } else {
+            // Regular character
+            current_length += 1;
+            current_chunk.push(c);
+            if current_length == max_chunk_length {
+                // Current chunk is full
+                chunks.push(current_chunk);
+                current_chunk = String::new();
+                current_length = 0;
+            }
+        }
+    }
+
+    // Add the last chunk if it's not empty
+    if !current_chunk.is_empty() {
+        chunks.push(current_chunk);
+    }
+
+    chunks
+}
+
+fn indent_levels(indent: usize) -> String {
+    let mut s = String::new();
+    for _ in 0..indent {
+        s.push_str(" │");
+    }
+    format!("{}", style(s).cyan())
+}
+
+impl<S> Layer<S> for CustomLayer
+where
+    S: Subscriber + for<'a> LookupSpan<'a>,
+{
+    fn on_enter(&self, id: &Id, ctx: Context<'_, S>) {
+        let mut state = self.shared_state.lock().unwrap();
+
+        let span = ctx.span(id);
+        let ind = indent_levels(state.indentation_level);
+
+        if let Some(span) = span {
+            println!("{ind}\n{ind} {} {}", style("╭─").cyan(), span.name());
+        }
+
+        state.indentation_level += 1;
+    }
+
+    fn on_exit(&self, _id: &Id, _ctx: Context<'_, S>) {
+        let mut state = self.shared_state.lock().unwrap();
+
+        if state.indentation_level > 0 {
+            state.indentation_level -= 1;
+        }
+
+        let ind = indent_levels(state.indentation_level);
+        println!("{ind} {}", style("╰───────────────────").cyan());
+    }
+
+    fn on_event(&self, event: &Event<'_>, _ctx: Context<'_, S>) {
+        let state = self.shared_state.lock().unwrap();
+
+        let indent_str = indent_levels(state.indentation_level);
+        let mut s = Vec::new();
+        let mut w = io::Cursor::new(&mut s);
+        event.record(&mut CustomVisitor::new(&mut w));
+        let s = String::from_utf8_lossy(&w.get_ref());
+
+        let width: usize = terminal_size::terminal_size()
+            .map(|(w, _)| w.0)
+            .unwrap_or(80) as usize;
+
+        let max_width = width - (state.indentation_level * 2) - 1;
+        let mut writer = self.writer.make_writer();
+        for line in s.lines() {
+            // split line into max_width chunks
+            if line.len() <= max_width {
+                writeln!(writer, "{} {}", indent_str, line).unwrap();
+            } else {
+                chunk_string_without_ansi(line, max_width)
+                    .iter()
+                    .for_each(|chunk| {
+                        writeln!(writer, "{} {}", indent_str, chunk).unwrap();
+                    });
+            }
+        }
+    }
+}

src/main.rs

@@ -3,6 +3,7 @@
 use clap::{arg, crate_version, CommandFactory, Parser};
 
 use clap_verbosity_flag::{InfoLevel, Verbosity};
+use console_utils::CustomLayer;
 use dunce::canonicalize;
 use fs_err as fs;
 use indicatif::MultiProgress;
@@ -17,7 +18,6 @@ use std::{
 };
 use tracing_subscriber::{
     filter::{Directive, ParseError},
-    fmt,
     prelude::*,
     EnvFilter,
 };
@@ -43,7 +43,7 @@ mod console_utils;
 mod rebuild;
 mod upload;
 
-use crate::console_utils::{IndicatifWriter, TracingFormatter};
+use crate::console_utils::IndicatifWriter;
 
 #[derive(Parser)]
 enum SubCommands {
@@ -424,11 +424,14 @@ async fn main() -> miette::Result<()> {
     // Setup tracing subscriber
     tracing_subscriber::registry()
         .with(get_default_env_filter(args.verbose.log_level_filter()).into_diagnostic()?)
-        .with(
-            fmt::layer()
-                .with_writer(IndicatifWriter::new(multi_progress.clone()))
-                .event_format(TracingFormatter::default()),
-        )
+        .with(CustomLayer::new(IndicatifWriter::new(
+            multi_progress.clone(),
+        )))
+        // .with(
+        //     fmt::layer()
+        //         .with_writer(IndicatifWriter::new(multi_progress.clone()))
+        //         .event_format(TracingFormatter::default()),
+        // )
         .init();
 
     match args.subcommand {

src/post_process/checks.rs

@@ -361,7 +361,7 @@ pub fn perform_linking_checks(
                 });
                 linked_packages.push(link_info);
                 linked_packages.iter().for_each(|linked_package| {
-                    println!("\n{linked_package}");
+                    tracing::info!("\n{linked_package}");
                 });
 
                 return Err(LinkingCheckError::Overlinking {
@@ -380,9 +380,8 @@ pub fn perform_linking_checks(
         linked_packages.push(link_info);
     }
 
-    println!();
     linked_packages.iter().for_each(|linked_package| {
-        println!("{linked_package}");
+        tracing::info!("{linked_package}");
     });
 
     // If there are any unused run dependencies then it is "overdepending".

src/source/mod.rs

@@ -92,8 +92,6 @@ pub async fn fetch_sources(
     system_tools: &SystemTools,
     tool_configuration: &tool_configuration::Configuration,
 ) -> Result<Vec<Source>, SourceError> {
-    tracing::info!(target = "rattler_build.source", "Starting to fetch sources");
-
     if sources.is_empty() {
         return Ok(Vec::new());
     }
@@ -236,8 +234,6 @@ pub async fn fetch_sources(
             }
         }
     }
-
-    tracing::info!(target = "rattler_build.source", "Finished fetching sources");
     Ok(rendered_sources)
 }