chore: Use tracing instead of log and simplelog

Structured logging from `tracing` meets our needs better, especially
in the parts of bpf-linker which sanitize the debug info.

Fixes #177

Author: vadorovsky

Cargo.toml

@@ -18,7 +18,9 @@ edition = "2021"
 [dependencies]
 # cli deps
 clap = { version = "4.5.0", features = ["derive"] }
-simplelog = { version = "0.12.1" }
+tracing-appender = "0.2"
+tracing-subscriber = { version = "0.3", features = ["env-filter", "registry"] }
+tracing-tree = "0.3"
 
 # lib deps
 ar = { version = "0.9.0" }
@@ -28,6 +30,7 @@ libc = { version = "0.2.153" }
 llvm-sys = { features = ["disable-alltargets-init"], version = "180.0.0-rc2" }
 log = { version = "0.4.20" }
 thiserror = { version = "1.0.57" }
+tracing = "0.1"
 
 [dev-dependencies]
 compiletest_rs = { version = "0.10.1" }

src/bin/bpf-linker.rs

@@ -3,22 +3,15 @@
 #[cfg(feature = "rust-llvm")]
 extern crate aya_rustc_llvm_proxy;
 
-use std::{
-    env,
-    fs::{self, OpenOptions},
-    os::fd::AsRawFd,
-    path::PathBuf,
-    str::FromStr,
-};
+use std::{env, fs, io, path::PathBuf, str::FromStr};
 
 use bpf_linker::{Cpu, Linker, LinkerOptions, OptLevel, OutputType};
 use clap::Parser;
-use libc::dup2;
-use log::info;
-use simplelog::{
-    ColorChoice, Config, LevelFilter, SimpleLogger, TermLogger, TerminalMode, WriteLogger,
-};
 use thiserror::Error;
+use tracing::{info, Level, Subscriber};
+use tracing_appender::non_blocking::WorkerGuard;
+use tracing_subscriber::{fmt::MakeWriter, prelude::*, EnvFilter};
+use tracing_tree::HierarchicalLayer;
 
 #[derive(Debug, Error)]
 enum CliError {
@@ -65,6 +58,7 @@ impl FromStr for CliOutputType {
         }))
     }
 }
+
 #[derive(Debug, Parser)]
 struct CommandLine {
     /// LLVM target triple. When not provided, the target is inferred from the inputs
@@ -109,9 +103,10 @@ struct CommandLine {
     #[clap(long, value_name = "path")]
     log_file: Option<PathBuf>,
 
-    /// Set the log level. Can be one of `off`, `info`, `warn`, `debug`, `trace`.
+    /// Set the log level. If not specified, no logging is used. Can be one of
+    /// `error`, `warn`, `info`, `debug`, `trace`.
     #[clap(long, value_name = "level")]
-    log_level: Option<LevelFilter>,
+    log_level: Option<Level>,
 
     /// Try hard to unroll loops. Useful when targeting kernels that don't support loops
     #[clap(long)]
@@ -155,6 +150,18 @@ struct CommandLine {
     _debug: bool,
 }
 
+/// Returns a [`HierarchicalLayer`](tracing_tree::HierarchicalLayer) for the
+/// given `writer`.
+fn tracing_layer<W>(writer: W) -> HierarchicalLayer<W>
+where
+    W: for<'writer> MakeWriter<'writer> + 'static,
+{
+    const TRACING_IDENT: usize = 2;
+    HierarchicalLayer::new(TRACING_IDENT)
+        .with_indent_lines(true)
+        .with_writer(writer)
+}
+
 fn main() {
     let args = env::args().map(|arg| {
         if arg == "-flavor" {
@@ -191,51 +198,38 @@ fn main() {
         error("no input files", clap::error::ErrorKind::TooFewValues);
     }
 
-    let env_log_level = match env::var("RUST_LOG") {
-        Ok(s) if !s.is_empty() => match s.parse::<LevelFilter>() {
-            Ok(l) => Some(l),
-            Err(e) => error(
-                &format!("invalid RUST_LOG value: {e}"),
-                clap::error::ErrorKind::InvalidValue,
-            ),
-        },
-        _ => None,
-    };
-    let log_level = log_level.or(env_log_level).unwrap_or(LevelFilter::Warn);
-    if let Some(log_file) = log_file {
-        let log_file = match OpenOptions::new().create(true).append(true).open(log_file) {
-            Ok(f) => {
-                // Use dup2 to duplicate stderr fd to the log file fd
-                let result = unsafe { dup2(f.as_raw_fd(), std::io::stderr().as_raw_fd()) };
-
-                if result == -1 {
-                    error(
-                        &format!(
-                            "failed to duplicate stderr: {}",
-                            std::io::Error::last_os_error()
-                        ),
-                        clap::error::ErrorKind::Io,
-                    )
-                }
-                f
-            }
-            Err(e) => {
-                error(
-                    &format!("failed to open log file: {e:?}"),
-                    clap::error::ErrorKind::Io,
+    // Configure tracing.
+    if let Some(log_level) = log_level {
+        let subscriber_registry = tracing_subscriber::registry()
+            .with(EnvFilter::from_default_env().add_directive(log_level.into()));
+        let (subscriber, _guard): (
+            Box<dyn Subscriber + Send + Sync + 'static>,
+            Option<WorkerGuard>,
+        ) = match log_file {
+            Some(log_file) => {
+                let file_appender = tracing_appender::rolling::never(
+                    log_file.parent().unwrap_or_else(|| {
+                        error("invalid log_file", clap::error::ErrorKind::InvalidValue)
+                    }),
+                    log_file.file_name().unwrap_or_else(|| {
+                        error("invalid log_file", clap::error::ErrorKind::InvalidValue)
+                    }),
                 );
+                let (non_blocking, _guard) = tracing_appender::non_blocking(file_appender);
+                let subscriber = subscriber_registry
+                    .with(tracing_layer(io::stdout))
+                    .with(tracing_layer(non_blocking));
+
+                (Box::new(subscriber), Some(_guard))
+            }
+            None => {
+                let subscriber = subscriber_registry.with(tracing_layer(io::stderr));
+                (Box::new(subscriber), None)
             }
         };
-        WriteLogger::init(log_level, Config::default(), log_file).unwrap();
-    } else if TermLogger::init(
-        log_level,
-        Config::default(),
-        TerminalMode::Mixed,
-        ColorChoice::Auto,
-    )
-    .is_err()
-    {
-        SimpleLogger::init(log_level, Config::default()).unwrap();
+        if let Err(e) = tracing::subscriber::set_global_default(subscriber) {
+            error(&e.to_string(), clap::error::ErrorKind::Format);
+        }
     }
 
     info!(

src/linker.rs

@@ -22,8 +22,8 @@ use llvm_sys::{
     prelude::{LLVMContextRef, LLVMModuleRef},
     target_machine::{LLVMCodeGenFileType, LLVMDisposeTargetMachine, LLVMTargetMachineRef},
 };
-use log::{debug, error, info, warn};
 use thiserror::Error;
+use tracing::{debug, error, info, warn};
 
 use crate::llvm;
 

src/llvm/di.rs

@@ -8,7 +8,7 @@ use std::{
 
 use gimli::{DW_TAG_pointer_type, DW_TAG_structure_type, DW_TAG_variant_part};
 use llvm_sys::{core::*, debuginfo::*, prelude::*};
-use log::{trace, warn};
+use tracing::{span, trace, warn, Level};
 
 use super::types::{
     di::DIType,
@@ -204,16 +204,13 @@ impl DISanitizer {
     }
 
     // navigate the tree of LLVMValueRefs (DFS-pre-order)
-    fn visit_item(&mut self, mut item: Item, depth: usize) {
+    fn visit_item(&mut self, mut item: Item) {
         let value_ref = item.value_ref();
         let value_id = item.value_id();
 
-        let log_prefix = "";
-        let log_depth = depth * 4;
-        trace!(
-            "{log_prefix:log_depth$}visiting item: {item:?} id: {} value: {value_ref:?}",
-            item.value_id(),
-        );
+        let item_span = span!(Level::TRACE, "item", value_id);
+        let _enter = item_span.enter();
+        trace!(?item, value = ?value_ref, "visiting item");
 
         let value = match (value_ref, &item) {
             // An operand with no value is valid and means that the operand is
@@ -235,7 +232,7 @@ impl DISanitizer {
 
         let first_visit = self.visited_nodes.insert(value_id);
         if !first_visit {
-            trace!("{log_prefix:log_depth$}already visited");
+            trace!("already visited");
             return;
         }
 
@@ -247,34 +244,31 @@ impl DISanitizer {
 
         if let Some(operands) = value.operands() {
             for (index, operand) in operands.enumerate() {
-                self.visit_item(
-                    Item::Operand(Operand {
-                        parent: value_ref,
-                        value: operand,
-                        index: index as u32,
-                    }),
-                    depth + 1,
-                )
+                self.visit_item(Item::Operand(Operand {
+                    parent: value_ref,
+                    value: operand,
+                    index: index as u32,
+                }))
             }
         }
 
         if let Some(entries) = value.metadata_entries() {
             for (index, (metadata, kind)) in entries.iter().enumerate() {
                 let metadata_value = unsafe { LLVMMetadataAsValue(self.context, metadata) };
-                self.visit_item(Item::MetadataEntry(metadata_value, kind, index), depth + 1);
+                self.visit_item(Item::MetadataEntry(metadata_value, kind, index));
             }
         }
 
         // If an item has sub items that are not operands nor metadata entries, we need to visit
         // those too.
         if let Value::Function(fun) = value {
             for param in fun.params() {
-                self.visit_item(Item::FunctionParam(param), depth + 1);
+                self.visit_item(Item::FunctionParam(param));
             }
 
             for basic_block in fun.basic_blocks() {
                 for instruction in basic_block.instructions_iter() {
-                    self.visit_item(Item::Instruction(instruction), depth + 1);
+                    self.visit_item(Item::Instruction(instruction));
                 }
             }
         }
@@ -288,14 +282,14 @@ impl DISanitizer {
         self.replace_operands = self.fix_subprogram_linkage(exported_symbols);
 
         for value in module.globals_iter() {
-            self.visit_item(Item::GlobalVariable(value), 0);
+            self.visit_item(Item::GlobalVariable(value));
         }
         for value in module.global_aliases_iter() {
-            self.visit_item(Item::GlobalAlias(value), 0);
+            self.visit_item(Item::GlobalAlias(value));
         }
 
         for function in module.functions_iter() {
-            self.visit_item(Item::Function(function), 0);
+            self.visit_item(Item::Function(function));
         }
 
         unsafe { LLVMDisposeDIBuilder(self.builder) };

src/llvm/mod.rs

@@ -48,7 +48,7 @@ use llvm_sys::{
     },
     LLVMAttributeFunctionIndex, LLVMLinkage, LLVMVisibility,
 };
-use log::{debug, error};
+use tracing::{debug, error};
 
 use crate::OptLevel;