[Rust] Update examples to use tracing

Author: emesare

plugins/warp/examples/headless/Cargo.toml

@@ -5,10 +5,10 @@ edition = "2021"
 
 [dependencies]
 clap = { version = "4.5", features = ["derive"] }
-indicatif = "0.18.2"
 warp_ninja.workspace = true
 binaryninjacore-sys.workspace = true
 binaryninja.workspace = true
-log = "0.4"
-env_logger = "0.11"
-ctrlc = "3.5"
+ctrlc = "3.5"
+tracing = "0.1"
+tracing-subscriber = "0.3"
+tracing-indicatif = "0.3"

plugins/warp/examples/headless/src/main.rs

@@ -1,10 +1,16 @@
 use binaryninja::headless::Session;
+use binaryninja::tracing::TracingLogListener;
 use clap::Parser;
-use indicatif::{ProgressBar, ProgressStyle};
 use std::collections::HashMap;
 use std::path::PathBuf;
+use std::sync::atomic::{AtomicBool, Ordering};
 use std::sync::Arc;
 use std::time::Duration;
+use tracing_indicatif::span_ext::IndicatifSpanExt;
+use tracing_indicatif::style::ProgressStyle;
+use tracing_indicatif::IndicatifLayer;
+use tracing_subscriber::layer::SubscriberExt;
+use tracing_subscriber::util::SubscriberInitExt;
 use warp_ninja::processor::{
     CompressionTypeField, ProcessingFileState, ProcessingState, WarpFileProcessor,
 };
@@ -50,9 +56,15 @@ struct Args {
 }
 
 fn main() {
+    let indicatif_layer = IndicatifLayer::new();
+    tracing_subscriber::registry()
+        .with(tracing_subscriber::fmt::layer().with_writer(indicatif_layer.get_stderr_writer()))
+        .with(indicatif_layer)
+        .init();
+    let _listener = TracingLogListener::new().register();
+
     let _session = Session::new().expect("Failed to create session");
     let args = Args::parse();
-    env_logger::init();
 
     let compression_ty = match args.compressed {
         true => CompressionTypeField::Zstd,
@@ -72,22 +84,27 @@ fn main() {
     })
     .expect("Error setting Ctrl-C handler");
 
-    let progress_guard = run_progress_bar(processor.state());
+    let finished_signal = Arc::new(AtomicBool::new(false));
+    // Report progress to the terminal.
+    let progress_state = processor.state();
+    let progress_finished_signal = finished_signal.clone();
+    let progress_thread =
+        std::thread::spawn(|| run_progress_bar(progress_state, progress_finished_signal));
 
     let outputs: HashMap<PathBuf, WarpFile<'static>> = args
         .input
         .into_iter()
         .filter_map(|i| match processor.process(i.clone()) {
             Ok(o) => Some((i, o)),
             Err(err) => {
-                log::error!("{}", err);
+                tracing::error!("{}", err);
                 None
             }
         })
         .collect();
 
-    // Stop progress UI
-    progress_guard.finish();
+    finished_signal.store(true, Ordering::Relaxed);
+    progress_thread.join().expect("Progress thread exited");
 
     match args.output.is_dir() {
         true => {
@@ -98,85 +115,56 @@ fn main() {
                     None => input.components().last().unwrap().as_os_str(),
                 };
                 let output_path = args.output.join(output_name).with_extension("warp");
-                log::info!("Writing to {:?}", output_path);
+                tracing::info!("Writing to {:?}", output_path);
                 std::fs::write(output_path, output.to_bytes()).unwrap();
             }
         }
         false => {
             // Given a non-existing directory, merge all outputs and place at the output path.
             match processor.merge_files(outputs.values().cloned().collect()) {
                 Ok(output) => {
-                    log::info!("Writing to {:?}", args.output);
+                    tracing::info!("Writing to {:?}", args.output);
                     std::fs::write(args.output, output.to_bytes()).unwrap();
                 }
                 Err(err) => {
-                    log::error!("{}", err);
+                    tracing::error!("{}", err);
                 }
             }
         }
     }
 }
 
 // TODO: Also poll for background tasks and display them as independent progress bars.
-fn run_progress_bar(state: Arc<ProcessingState>) -> ProgressGuard {
-    let pb = ProgressBar::new(0);
-    pb.set_style(
-        ProgressStyle::with_template(
-            "{spinner} {bar:40.cyan/blue} {pos}/{len} ({percent}%) [{elapsed_precise}] {msg}",
-        )
-        .unwrap()
-        .progress_chars("=>-"),
-    );
-
-    let pb_clone = pb.clone();
-    let state_clone = state.clone();
-    let handle = std::thread::spawn(move || loop {
-        let total = state_clone.total_files() as u64;
-        let done = state_clone.files_with_state(ProcessingFileState::Processed) as u64;
-        let unprocessed = state_clone.files_with_state(ProcessingFileState::Unprocessed);
-        let analyzing = state_clone.files_with_state(ProcessingFileState::Analyzing);
-        let processing = state_clone.files_with_state(ProcessingFileState::Processing);
-
-        if pb_clone.length().unwrap_or(0) != total {
-            pb_clone.set_length(total);
-        }
-        pb_clone.set_position(done.min(total));
-        pb_clone.set_message(format!(
+fn run_progress_bar(state: Arc<ProcessingState>, finished: Arc<AtomicBool>) {
+    let progress_span = tracing::info_span!("loading");
+    let progress_style = ProgressStyle::with_template("{msg} {elapsed} {wide_bar}").unwrap();
+    progress_span.pb_set_style(&progress_style);
+    progress_span.pb_set_message("Processing files");
+    progress_span.pb_set_finish_message("Files processed");
+
+    let elapsed = std::time::Instant::now();
+    progress_span.in_scope(|| loop {
+        let total = state.total_files() as u64;
+        let done = state.files_with_state(ProcessingFileState::Processed) as u64;
+        let unprocessed = state.files_with_state(ProcessingFileState::Unprocessed);
+        let analyzing = state.files_with_state(ProcessingFileState::Analyzing);
+        let processing = state.files_with_state(ProcessingFileState::Processing);
+
+        progress_span.pb_set_length(total);
+        progress_span.pb_set_position(done.min(total));
+        progress_span.pb_set_message(&format!(
             "{{u:{}|a:{}|p:{}|d:{}}}",
             unprocessed, analyzing, processing, done
         ));
 
-        if pb_clone.is_finished() {
+        if state.is_cancelled() || finished.load(Ordering::Relaxed) {
             break;
         }
         std::thread::sleep(Duration::from_millis(100));
     });
 
-    ProgressGuard {
-        pb,
-        handle: Some(handle),
-    }
-}
-
-struct ProgressGuard {
-    pb: ProgressBar,
-    handle: Option<std::thread::JoinHandle<()>>,
-}
-
-impl ProgressGuard {
-    fn finish(mut self) {
-        self.pb.finish_and_clear();
-        if let Some(h) = self.handle.take() {
-            let _ = h.join();
-        }
-    }
-}
-
-impl Drop for ProgressGuard {
-    fn drop(&mut self) {
-        self.pb.finish_and_clear();
-        if let Some(h) = self.handle.take() {
-            let _ = h.join();
-        }
-    }
+    tracing::info!(
+        "Finished processing in {:.2} seconds",
+        elapsed.elapsed().as_secs_f32()
+    );
 }

rust/examples/bndb_to_type_library.rs

@@ -1,38 +1,65 @@
 // Usage: cargo run --example bndb_to_type_library <bndb_path> <type_library_path>
 
 use binaryninja::binary_view::BinaryViewExt;
+use binaryninja::tracing::TracingLogListener;
 use binaryninja::types::{QualifiedName, TypeLibrary};
+use tracing_indicatif::span_ext::IndicatifSpanExt;
+use tracing_indicatif::style::ProgressStyle;
+use tracing_subscriber::layer::SubscriberExt;
+use tracing_subscriber::util::SubscriberInitExt;
 
 fn main() {
+    let indicatif_layer = tracing_indicatif::IndicatifLayer::new();
+    tracing_subscriber::registry()
+        .with(tracing_subscriber::fmt::layer().with_writer(indicatif_layer.get_stderr_writer()))
+        .with(indicatif_layer)
+        .init();
+    let _listener = TracingLogListener::new().register();
+
     let bndb_path_str = std::env::args().nth(1).expect("No header provided");
     let bndb_path = std::path::Path::new(&bndb_path_str);
 
     let type_lib_path_str = std::env::args().nth(2).expect("No type library provided");
     let type_lib_path = std::path::Path::new(&type_lib_path_str);
     let type_lib_name = type_lib_path.file_stem().unwrap().to_str().unwrap();
 
-    println!("Starting session...");
     // This loads all the core architecture, platform, etc plugins
     let headless_session =
         binaryninja::headless::Session::new().expect("Failed to initialize session");
 
-    let file = headless_session
-        .load(bndb_path)
-        .expect("Failed to load BNDB");
+    let file = {
+        let loading_span = tracing::info_span!("loading");
+        let progress_style = ProgressStyle::with_template("{msg} {elapsed} {wide_bar}").unwrap();
+        loading_span.pb_set_style(&progress_style);
+        loading_span.pb_set_message("Loading database");
+        loading_span.pb_set_finish_message("Database loaded");
+        loading_span.in_scope(|| {
+            headless_session
+                .load_with_progress(bndb_path, |pos, total| {
+                    loading_span.pb_set_length(total as u64);
+                    loading_span.pb_set_position(pos as u64);
+                    true
+                })
+                .expect("Failed to load BNDB")
+        })
+    };
 
     let type_lib = TypeLibrary::new(file.default_arch().unwrap(), type_lib_name);
 
-    for ty in &file.types() {
-        println!("Adding type: {}", ty.name);
+    let types = file.types();
+    tracing::info!("Adding {} types", types.len());
+    for ty in &types {
         type_lib.add_named_type(ty.name, &ty.ty);
     }
 
-    for func in &file.functions() {
-        println!("Adding function: {}", func.symbol());
+    let functions = file.functions();
+    tracing::info!("Adding {} functions", functions.len());
+    for func in &functions {
         let qualified_name =
             QualifiedName::from(func.symbol().short_name().to_string_lossy().to_string());
         type_lib.add_named_object(qualified_name, &func.function_type());
     }
 
+    tracing::info!("Writing out file... {:?}", type_lib_path);
     type_lib.write_to_file(&type_lib_path);
 }

rust/examples/create_type_library.rs

@@ -1,9 +1,13 @@
 // Usage: cargo run --example create_type_library <header_file_path> <platform> <type_library_path>
 
 use binaryninja::platform::Platform;
+use binaryninja::tracing::TracingLogListener;
 use binaryninja::types::{CoreTypeParser, TypeLibrary, TypeParser};
 
 fn main() {
+    tracing_subscriber::fmt::init();
+    let _listener = TracingLogListener::new().register();
+
     let header_path_str = std::env::args().nth(1).expect("No header provided");
     let header_path = std::path::Path::new(&header_path_str);
     let header_name = header_path.file_stem().unwrap().to_str().unwrap();
@@ -14,7 +18,6 @@ fn main() {
 
     let header_contents = std::fs::read_to_string(header_path).expect("Failed to read header file");
 
-    println!("Starting session...");
     // This loads all the core architecture, platform, etc plugins
     let _headless_session =
         binaryninja::headless::Session::new().expect("Failed to initialize session");
@@ -38,14 +41,19 @@ fn main() {
         .expect("Parsed types");
 
     for ty in parsed_types.types {
-        println!("Adding type: {}", ty.name);
+        tracing::debug!("Adding type: {}", ty.name);
         type_lib.add_named_type(ty.name, &ty.ty);
     }
 
     for func in parsed_types.functions {
-        println!("Adding function: {}", func.name);
+        tracing::debug!("Adding function: {}", func.name);
         type_lib.add_named_object(func.name, &func.ty);
     }
 
+    tracing::info!(
+        "Created type library with {} types and {} functions",
+        type_lib.named_types().len(),
+        type_lib.named_objects().len()
+    );
     type_lib.write_to_file(&type_lib_path);
 }

rust/examples/decompile.rs

@@ -2,6 +2,7 @@ use binaryninja::binary_view::{BinaryView, BinaryViewBase, BinaryViewExt};
 use binaryninja::disassembly::{DisassemblyOption, DisassemblySettings};
 use binaryninja::function::Function;
 use binaryninja::linear_view::LinearViewObject;
+use binaryninja::tracing::TracingLogListener;
 
 fn decompile_to_c(view: &BinaryView, func: &Function) {
     let settings = DisassemblySettings::new();
@@ -22,26 +23,28 @@ fn decompile_to_c(view: &BinaryView, func: &Function) {
     let lines = first.into_iter().chain(&last);
 
     for line in lines {
-        println!("{}", line);
+        tracing::info!("{}", line);
     }
 }
 
 pub fn main() {
+    tracing_subscriber::fmt::init();
+    let _listener = TracingLogListener::new().register();
+
     let filename = std::env::args().nth(1).expect("No filename provided");
 
-    println!("Starting session...");
     // This loads all the core architecture, platform, etc plugins
     let headless_session =
         binaryninja::headless::Session::new().expect("Failed to initialize session");
 
-    println!("Loading binary...");
+    tracing::info!("Loading binary...");
     let bv = headless_session
         .load(&filename)
         .expect("Couldn't open file!");
 
-    println!("Filename:  `{}`", bv.file().filename());
-    println!("File size: `{:#x}`", bv.len());
-    println!("Function count: {}", bv.functions().len());
+    tracing::info!("Filename:  `{}`", bv.file().filename());
+    tracing::info!("File size: `{:#x}`", bv.len());
+    tracing::info!("Function count: {}", bv.functions().len());
 
     for func in &bv.functions() {
         decompile_to_c(bv.as_ref(), func.as_ref());