From 93aa1a8aba766b1689626aaf430ecf2e5bcb5e2a Mon Sep 17 00:00:00 2001 From: Mason Reed Date: Wed, 17 Dec 2025 21:23:46 -0500 Subject: [PATCH 1/6] [Rust] WIP: Replace `log` with `tracing` - Added more documentation - Replaced global named logger for plugins, fixing the issue when the CU has multiple (e.g. statically linked demo) - Simplified some misc code This is a breaking change, but I believe there is no better time to make it, we cannot continue to use the `log` crate, it is too limited for our needs. --- Cargo.lock | 68 ++-- arch/msp430/Cargo.toml | 1 - arch/msp430/src/architecture.rs | 7 +- arch/msp430/src/lib.rs | 9 +- arch/msp430/src/lift.rs | 5 +- arch/riscv/Cargo.toml | 1 - arch/riscv/src/lib.rs | 13 +- plugins/dwarf/dwarf_export/Cargo.toml | 1 - plugins/dwarf/dwarf_export/src/lib.rs | 22 +- plugins/dwarf/dwarf_import/Cargo.toml | 1 - plugins/dwarf/dwarf_import/demo/Cargo.toml | 1 - .../dwarf/dwarf_import/src/die_handlers.rs | 31 +- .../dwarf/dwarf_import/src/dwarfdebuginfo.rs | 42 +-- plugins/dwarf/dwarf_import/src/functions.rs | 21 +- plugins/dwarf/dwarf_import/src/helpers.rs | 19 +- plugins/dwarf/dwarf_import/src/lib.rs | 47 ++- plugins/dwarf/dwarf_import/src/types.rs | 34 +- plugins/idb_import/Cargo.toml | 1 - plugins/idb_import/src/lib.rs | 50 ++- plugins/pdb-ng/Cargo.toml | 1 - plugins/pdb-ng/demo/Cargo.toml | 1 - plugins/pdb-ng/src/lib.rs | 25 +- plugins/pdb-ng/src/parser.rs | 2 +- plugins/pdb-ng/src/struct_grouper.rs | 5 +- plugins/pdb-ng/src/type_parser.rs | 2 +- plugins/svd/Cargo.toml | 1 - plugins/svd/demo/Cargo.toml | 1 - plugins/svd/src/lib.rs | 19 +- plugins/svd/src/mapper.rs | 7 +- plugins/warp/Cargo.toml | 1 - plugins/warp/demo/Cargo.toml | 1 - plugins/warp/src/cache.rs | 6 +- plugins/warp/src/container/disk.rs | 3 +- plugins/warp/src/container/network.rs | 15 +- plugins/warp/src/container/network/client.rs | 11 +- plugins/warp/src/convert/types.rs | 5 +- plugins/warp/src/plugin.rs | 30 +- plugins/warp/src/plugin/commit.rs | 17 +- plugins/warp/src/plugin/create.rs | 15 +- plugins/warp/src/plugin/debug.rs | 8 +- plugins/warp/src/plugin/ffi/container.rs | 5 +- plugins/warp/src/plugin/file.rs | 5 +- plugins/warp/src/plugin/function.rs | 25 +- plugins/warp/src/plugin/load.rs | 5 +- plugins/warp/src/plugin/project.rs | 21 +- plugins/warp/src/plugin/workflow.rs | 27 +- plugins/warp/src/processor.rs | 38 +-- plugins/workflow_objc/Cargo.toml | 1 - .../src/activities/objc_msg_send_calls.rs | 3 +- .../rewrite_to_direct_call.rs | 3 +- .../activities/remove_memory_management.rs | 3 +- .../src/activities/super_init.rs | 19 +- plugins/workflow_objc/src/lib.rs | 10 +- .../src/metadata/global_state.rs | 13 +- plugins/workflow_objc/src/workflow.rs | 3 +- rust/Cargo.toml | 6 +- rust/plugin_examples/data_renderer/src/lib.rs | 5 +- rust/src/architecture.rs | 28 +- rust/src/architecture/flag.rs | 8 +- rust/src/architecture/intrinsic.rs | 2 +- rust/src/architecture/register.rs | 4 +- rust/src/command.rs | 183 ++++------- rust/src/custom_binary_view.rs | 52 +-- rust/src/ffi.rs | 40 ++- rust/src/file_accessor.rs | 1 - rust/src/file_metadata.rs | 17 +- rust/src/lib.rs | 1 + rust/src/logger.rs | 288 +++++++++-------- rust/src/low_level_il/expression.rs | 3 +- rust/src/low_level_il/lifting.rs | 6 +- rust/src/low_level_il/operation.rs | 6 +- rust/src/tracing.rs | 303 ++++++++++++++++++ rust/src/workflow/activity.rs | 4 +- view/minidump/Cargo.toml | 1 - view/minidump/src/command.rs | 18 +- view/minidump/src/lib.rs | 12 +- view/minidump/src/view.rs | 67 ++-- 77 files changed, 1028 insertions(+), 758 deletions(-) create mode 100644 rust/src/tracing.rs diff --git a/Cargo.lock b/Cargo.lock index 92577f86c8..d042ef579c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -134,7 +134,6 @@ version = "0.1.0" dependencies = [ "binaryninja", "binaryninjacore-sys", - "log", "msp430-asm", ] @@ -144,7 +143,6 @@ version = "0.1.0" dependencies = [ "binaryninja", "binaryninjacore-sys", - "log", "rayon", "riscv-dis", ] @@ -182,7 +180,6 @@ version = "0.1.0" dependencies = [ "binaryninjacore-sys", "insta", - "log", "rayon", "rstest", "serde", @@ -191,6 +188,8 @@ dependencies = [ "serial_test", "tempfile", "thiserror 2.0.12", + "tracing", + "tracing-subscriber", ] [[package]] @@ -691,7 +690,7 @@ dependencies = [ "libc", "option-ext", "redox_users", - "windows-sys 0.60.2", + "windows-sys 0.61.2", ] [[package]] @@ -713,7 +712,6 @@ dependencies = [ "binaryninja", "binaryninjacore-sys", "gimli", - "log", "object 0.32.2", ] @@ -728,7 +726,6 @@ dependencies = [ "gimli", "indexmap", "iset", - "log", "object 0.36.7", "regex", ] @@ -744,7 +741,6 @@ dependencies = [ "gimli", "indexmap", "iset", - "log", "object 0.36.7", "regex", ] @@ -1111,7 +1107,6 @@ dependencies = [ "binaryninja", "binaryninjacore-sys", "idb-rs", - "log", ] [[package]] @@ -1263,6 +1258,12 @@ dependencies = [ "wasm-bindgen", ] +[[package]] +name = "lazy_static" +version = "1.5.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "bbd2bcb4c963f2ddae06a2efc7e9f3591312473c50c6685e1f298068316e66fe" + [[package]] name = "libc" version = "0.2.174" @@ -1373,7 +1374,6 @@ version = "0.1.0" dependencies = [ "binaryninja", "binaryninjacore-sys", - "log", "minidump", ] @@ -1647,7 +1647,6 @@ dependencies = [ "binaryninja", "binaryninjacore-sys", "itertools 0.14.0", - "log", "pdb", "regex", ] @@ -1660,7 +1659,6 @@ dependencies = [ "binaryninja", "binaryninjacore-sys", "itertools 0.14.0", - "log", "pdb", "regex", ] @@ -2192,6 +2190,15 @@ version = "1.0.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "bbfa15b3dddfee50a0fff136974b3e1bde555604ba463834a7eb7deb6417705d" +[[package]] +name = "sharded-slab" +version = "0.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f40ca3c46823713e0d4209592e8d6e826aa57e928f09752619fc696c499637f6" +dependencies = [ + "lazy_static", +] + [[package]] name = "shlex" version = "1.3.0" @@ -2281,7 +2288,6 @@ dependencies = [ "binaryninja", "binaryninjacore-sys", "insta", - "log", "serde_json", "svd-parser", ] @@ -2293,7 +2299,6 @@ dependencies = [ "binaryninja", "binaryninjacore-sys", "insta", - "log", "serde_json", "svd-parser", ] @@ -2372,6 +2377,15 @@ dependencies = [ "syn", ] +[[package]] +name = "thread_local" +version = "1.1.9" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f60246a4944f24f6e018aa17cdeffb7818b76356965d03b07d6a9886e8962185" +dependencies = [ + "cfg-if", +] + [[package]] name = "tiff" version = "0.9.1" @@ -2443,9 +2457,9 @@ dependencies = [ [[package]] name = "tracing" -version = "0.1.41" +version = "0.1.43" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "784e0ac535deb450455cbfa28a6f0df145ea1bb7ae51b821cf5e7927fdcfbdd0" +checksum = "2d15d90a0b5c19378952d479dc858407149d7bb45a14de0142f6c534b16fc647" dependencies = [ "log", "pin-project-lite", @@ -2455,9 +2469,9 @@ dependencies = [ [[package]] name = "tracing-attributes" -version = "0.1.30" +version = "0.1.31" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "81383ab64e72a7a8b8e13130c49e3dab29def6d0c7d76a03087b3cf71c5c6903" +checksum = "7490cfa5ec963746568740651ac6781f701c9c5ea257c58e057f3ba8cf69e8da" dependencies = [ "proc-macro2", "quote", @@ -2466,13 +2480,26 @@ dependencies = [ [[package]] name = "tracing-core" -version = "0.1.34" +version = "0.1.35" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "b9d12581f227e93f094d3af2ae690a574abb8a2b9b7a96e7cfe9647b2b617678" +checksum = "7a04e24fab5c89c6a36eb8558c9656f30d81de51dfa4d3b45f26b21d61fa0a6c" dependencies = [ "once_cell", ] +[[package]] +name = "tracing-subscriber" +version = "0.3.22" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2f30143827ddab0d256fd843b7a66d164e9f271cfa0dde49142c5ca0ca291f1e" +dependencies = [ + "parking_lot", + "sharded-slab", + "smallvec", + "thread_local", + "tracing-core", +] + [[package]] name = "twox-hash" version = "1.6.3" @@ -2589,7 +2616,6 @@ dependencies = [ "directories", "insta", "itertools 0.14.0", - "log", "minijinja", "minijinja-embed", "rayon", @@ -2619,7 +2645,6 @@ dependencies = [ "directories", "insta", "itertools 0.14.0", - "log", "minijinja", "minijinja-embed", "rayon", @@ -3008,7 +3033,6 @@ dependencies = [ "binaryninjacore-sys", "bstr", "dashmap", - "log", "once_cell", "thiserror 2.0.12", ] diff --git a/arch/msp430/Cargo.toml b/arch/msp430/Cargo.toml index 03940cd873..3e0d34fe1b 100644 --- a/arch/msp430/Cargo.toml +++ b/arch/msp430/Cargo.toml @@ -8,7 +8,6 @@ license = "Apache-2.0" [dependencies] binaryninja.workspace = true binaryninjacore-sys.workspace = true -log = "0.4" msp430-asm = "^0.2" [lib] diff --git a/arch/msp430/src/architecture.rs b/arch/msp430/src/architecture.rs index ef4c503a8e..996d3c4a96 100644 --- a/arch/msp430/src/architecture.rs +++ b/arch/msp430/src/architecture.rs @@ -8,7 +8,7 @@ use binaryninja::{ UnusedIntrinsic, UnusedRegisterStack, }, disassembly::{InstructionTextToken, InstructionTextTokenKind}, - Endianness, + tracing, Endianness, }; use msp430_asm::{ @@ -21,7 +21,6 @@ use binaryninja::architecture::{ }; use binaryninja::low_level_il::expression::ValueExpr; use binaryninja::low_level_il::{LowLevelILMutableExpression, LowLevelILMutableFunction}; -use log::error; const MIN_MNEMONIC: usize = 9; @@ -321,7 +320,7 @@ impl Architecture for Msp430 { match id.try_into() { Ok(flag) => Some(flag), Err(_) => { - error!("invalid flag id {}", id); + tracing::error!("invalid flag id {}", id); None } } @@ -331,7 +330,7 @@ impl Architecture for Msp430 { match id.try_into() { Ok(flag_write) => Some(flag_write), Err(_) => { - error!("invalid flag write id {}", id); + tracing::error!("invalid flag write id {}", id); None } } diff --git a/arch/msp430/src/lib.rs b/arch/msp430/src/lib.rs index b54655547d..892e617dc5 100644 --- a/arch/msp430/src/lib.rs +++ b/arch/msp430/src/lib.rs @@ -1,7 +1,3 @@ -extern crate binaryninja; -extern crate log; -extern crate msp430_asm; - use binaryninja::{ add_optional_plugin_dependency, architecture::ArchitectureExt, @@ -9,7 +5,6 @@ use binaryninja::{ custom_binary_view::{BinaryViewType, BinaryViewTypeExt}, Endianness, }; -use log::LevelFilter; mod architecture; mod flag; @@ -17,12 +12,12 @@ mod lift; mod register; use architecture::Msp430; -use binaryninja::logger::Logger; #[no_mangle] #[allow(non_snake_case)] pub extern "C" fn CorePluginInit() -> bool { - Logger::new("MSP430").with_level(LevelFilter::Info).init(); + binaryninja::tracing_init!("MSP430"); + let arch = binaryninja::architecture::register_architecture("msp430", |custom_handle, handle| { Msp430::new(handle, custom_handle) diff --git a/arch/msp430/src/lift.rs b/arch/msp430/src/lift.rs index 3e69b5a481..480b150b65 100644 --- a/arch/msp430/src/lift.rs +++ b/arch/msp430/src/lift.rs @@ -2,7 +2,7 @@ use crate::architecture::offset_to_absolute; use crate::flag::{Flag, FlagWrite}; use crate::register::Register; -use binaryninja::{architecture::FlagCondition, low_level_il::lifting::LowLevelILLabel}; +use binaryninja::{architecture::FlagCondition, low_level_il::lifting::LowLevelILLabel, tracing}; use msp430_asm::emulate::Emulated; use msp430_asm::instruction::Instruction; @@ -13,7 +13,6 @@ use msp430_asm::two_operand::TwoOperand; use binaryninja::low_level_il::expression::ValueExpr; use binaryninja::low_level_il::{LowLevelILMutableExpression, LowLevelILMutableFunction}; -use log::info; macro_rules! auto_increment { ($src:expr, $il:ident) => { @@ -550,7 +549,7 @@ pub(crate) fn lift_instruction(inst: &Instruction, addr: u64, il: &LowLevelILMut il.set_reg(size, Register::try_from(*r as u32).unwrap(), il.pop(2)) .append(); } else { - info!("pop: invalid destination operand"); + tracing::info!("pop: invalid destination operand"); } } Instruction::Ret(_) => { diff --git a/arch/riscv/Cargo.toml b/arch/riscv/Cargo.toml index a90000dd0b..e247b30167 100644 --- a/arch/riscv/Cargo.toml +++ b/arch/riscv/Cargo.toml @@ -9,7 +9,6 @@ license = "Apache-2.0" binaryninja.workspace = true binaryninjacore-sys.workspace = true riscv-dis = { path = "disasm" } -log = "0.4" rayon = { version = "1.0", optional = true } [features] diff --git a/arch/riscv/src/lib.rs b/arch/riscv/src/lib.rs index 22ecdd6db9..1ebe7fb442 100644 --- a/arch/riscv/src/lib.rs +++ b/arch/riscv/src/lib.rs @@ -26,9 +26,9 @@ use binaryninja::{ RelocationType, }, symbol::{Symbol, SymbolType}, + tracing, types::{NameAndType, Type}, }; -use log::LevelFilter; use std::borrow::Cow; use std::fmt; use std::hash::Hash; @@ -36,7 +36,6 @@ use std::marker::PhantomData; use binaryninja::architecture::{BranchKind, IntrinsicId, RegisterId}; use binaryninja::confidence::{Conf, MAX_CONFIDENCE, MIN_CONFIDENCE}; -use binaryninja::logger::Logger; use binaryninja::low_level_il::expression::{LowLevelILExpressionKind, ValueExpr}; use binaryninja::low_level_il::instruction::LowLevelILInstructionKind; use binaryninja::low_level_il::lifting::{ @@ -228,7 +227,7 @@ impl<'a, D: RiscVDisassembler> LiftableLowLevelILWithSize<'a> for Register { #[cfg(debug_assertions)] { if reg.size() < size { - log::warn!( + tracing::warn!( "il @ {:x} attempted to lift {} byte register as {} byte expr", il.current_address(), reg.size(), @@ -2431,7 +2430,7 @@ impl RelocationHandler } Self::R_RISCV_TLS_TPREL32 => { reloc.type_ = RelocationType::UnhandledRelocation; - log::warn!( + tracing::warn!( "Unhandled relocation type {:?} (R_RISCV_TLS_TPREL32) at {:x?}", reloc.native_type, reloc.address @@ -2439,7 +2438,7 @@ impl RelocationHandler } Self::R_RISCV_TLS_TPREL64 => { reloc.type_ = RelocationType::UnhandledRelocation; - log::warn!( + tracing::warn!( "Unhandled relocation type {:?} (R_RISCV_TLS_TPREL64) at {:x?}", reloc.native_type, reloc.address @@ -2447,7 +2446,7 @@ impl RelocationHandler } _ => { reloc.type_ = RelocationType::UnhandledRelocation; - log::warn!( + tracing::warn!( "Unknown relocation type {:?} at {:x?}", reloc.native_type, reloc.address @@ -3014,7 +3013,7 @@ impl FunctionRecognizer for RiscVELFPLTRecognizer { #[no_mangle] #[allow(non_snake_case)] pub extern "C" fn CorePluginInit() -> bool { - Logger::new("RISCV").with_level(LevelFilter::Trace).init(); + binaryninja::tracing_init!("RISCV"); use riscv_dis::{RiscVIMACDisassembler, Rv32GRegs, Rv64GRegs}; let arch32 = diff --git a/plugins/dwarf/dwarf_export/Cargo.toml b/plugins/dwarf/dwarf_export/Cargo.toml index 570626f60e..81c8a0174b 100644 --- a/plugins/dwarf/dwarf_export/Cargo.toml +++ b/plugins/dwarf/dwarf_export/Cargo.toml @@ -11,5 +11,4 @@ crate-type = ["cdylib"] binaryninja.workspace = true binaryninjacore-sys.workspace = true gimli = "^0.31" -log = "0.4" object = { version = "0.32.1", features = ["write"] } diff --git a/plugins/dwarf/dwarf_export/src/lib.rs b/plugins/dwarf/dwarf_export/src/lib.rs index 333ce83b38..bc7d3c27e2 100644 --- a/plugins/dwarf/dwarf_export/src/lib.rs +++ b/plugins/dwarf/dwarf_export/src/lib.rs @@ -1,13 +1,13 @@ mod edit_distance; use binaryninja::interaction::form::{Form, FormInputField}; -use binaryninja::logger::Logger; use binaryninja::{ binary_view::{BinaryView, BinaryViewBase, BinaryViewExt}, command::{register_command, Command}, confidence::Conf, rc::Ref, symbol::SymbolType, + tracing, types::{MemberAccess, StructureType, Type, TypeClass}, }; use gimli::{ @@ -17,7 +17,6 @@ use gimli::{ UnitEntryId, }, }; -use log::{error, info, warn, LevelFilter}; use object::{write, Architecture, BinaryFormat, SectionKind}; use std::fs; use std::path::{Path, PathBuf}; @@ -148,7 +147,10 @@ fn export_type( ); } None => { - log::warn!("Could not export base struct `{}`", base_struct.ty.name()); + tracing::warn!( + "Could not export base struct `{}`", + base_struct.ty.name() + ); } } } @@ -374,7 +376,7 @@ fn export_type( Some(typedef_die_uid) } } else { - warn!("Could not get target of typedef `{}`", ntr.name()); + tracing::warn!("Could not get target of typedef `{}`", ntr.name()); None } } @@ -703,12 +705,12 @@ fn write_dwarf( if let Ok(out_data) = out_object.write() { if let Err(err) = fs::write(file_path, out_data) { - error!("Failed to write DWARF file: {}", err); + tracing::error!("Failed to write DWARF file: {}", err); } else { - info!("Successfully saved as DWARF to `{:?}`", file_path); + tracing::info!("Successfully saved as DWARF to `{:?}`", file_path); } } else { - error!("Failed to write DWARF with requested settings"); + tracing::error!("Failed to write DWARF with requested settings"); } Ok(()) @@ -785,7 +787,7 @@ fn export_dwarf(bv: &BinaryView) { }; if let Err(e) = write_dwarf(&save_loc_path, arch, endianness, &mut dwarf) { - error!("Error writing DWARF: {}", e); + tracing::error!("Error writing DWARF: {}", e); } } @@ -802,9 +804,7 @@ impl Command for MyCommand { #[no_mangle] pub extern "C" fn CorePluginInit() -> bool { - Logger::new("DWARF Export") - .with_level(LevelFilter::Debug) - .init(); + binaryninja::tracing_init!("DWARF Export"); register_command( "Export as DWARF", diff --git a/plugins/dwarf/dwarf_import/Cargo.toml b/plugins/dwarf/dwarf_import/Cargo.toml index 15f3fda8a6..f71d4cf43d 100644 --- a/plugins/dwarf/dwarf_import/Cargo.toml +++ b/plugins/dwarf/dwarf_import/Cargo.toml @@ -15,7 +15,6 @@ dwarfreader = { path = "../shared/" } binaryninja.workspace = true binaryninjacore-sys.workspace = true gimli = "0.31" -log = "0.4" iset = "0.2.2" cpp_demangle = "0.4.3" regex = "1" diff --git a/plugins/dwarf/dwarf_import/demo/Cargo.toml b/plugins/dwarf/dwarf_import/demo/Cargo.toml index e088fb682a..3a5ad601b1 100644 --- a/plugins/dwarf/dwarf_import/demo/Cargo.toml +++ b/plugins/dwarf/dwarf_import/demo/Cargo.toml @@ -16,7 +16,6 @@ dwarfreader = { path = "../../shared/" } binaryninja = { workspace = true, features = ["demo"]} binaryninjacore-sys.workspace = true gimli = "0.31" -log = "0.4" iset = "0.2.2" cpp_demangle = "0.4.3" regex = "1" diff --git a/plugins/dwarf/dwarf_import/src/die_handlers.rs b/plugins/dwarf/dwarf_import/src/die_handlers.rs index dda47956bf..7f038a5a7a 100644 --- a/plugins/dwarf/dwarf_import/src/die_handlers.rs +++ b/plugins/dwarf/dwarf_import/src/die_handlers.rs @@ -18,6 +18,7 @@ use crate::{helpers::*, ReaderType}; use binaryninja::{ rc::*, + tracing, types::{EnumerationBuilder, FunctionParameter, ReferenceType, Type, TypeBuilder}, }; @@ -109,7 +110,7 @@ pub(crate) fn handle_enum( let mut tree = match unit.entries_tree(Some(entry.offset())) { Ok(x) => x, Err(e) => { - log::error!("Failed to get enum entry tree: {}", e); + tracing::error!("Failed to get enum entry tree: {}", e); return None; } }; @@ -117,7 +118,7 @@ pub(crate) fn handle_enum( let tree_root = match tree.root() { Ok(x) => x, Err(e) => { - log::error!("Failed to get enum entry tree root: {}", e); + tracing::error!("Failed to get enum entry tree root: {}", e); return None; } }; @@ -132,15 +133,15 @@ pub(crate) fn handle_enum( enumeration_builder.insert(&name, value); } else { // Somehow the child entry is not a const value. - log::error!("Unhandled enum member value type for `{}`", name); + tracing::error!("Unhandled enum member value type for `{}`", name); } } Ok(None) => { // Somehow the child entry does not have a const value. - log::error!("Enum member `{}` has no constant value attribute", name); + tracing::error!("Enum member `{}` has no constant value attribute", name); } Err(e) => { - log::error!("Error parsing next attribute entry for `{}`: {}", name, e); + tracing::error!("Error parsing next attribute entry for `{}`: {}", name, e); return None; } } @@ -208,7 +209,7 @@ pub(crate) fn handle_pointer( Some(entry_type_offset) => { let debug_target_type = debug_info_builder.get_type(entry_type_offset).or_else(|| { - log::error!( + tracing::error!( "Failed to get pointer target type at entry offset {}", entry_type_offset ); @@ -255,7 +256,7 @@ pub(crate) fn handle_array( let parent_type = debug_info_builder .get_type(entry_type_offset) .or_else(|| { - log::error!( + tracing::error!( "Failed to get array member type at entry offset {}", entry_type_offset ); @@ -266,14 +267,14 @@ pub(crate) fn handle_array( let mut tree = match unit.entries_tree(Some(entry.offset())) { Ok(x) => x, Err(e) => { - log::error!("Failed to get array entry tree: {}", e); + tracing::error!("Failed to get array entry tree: {}", e); return None; } }; let tree_root = match tree.root() { Ok(x) => x, Err(e) => { - log::error!("Failed to get array entry tree root: {}", e); + tracing::error!("Failed to get array entry tree root: {}", e); return None; } }; @@ -351,7 +352,7 @@ pub(crate) fn handle_function( let mut tree = match unit.entries_tree(Some(entry.offset())) { Ok(x) => x, Err(e) => { - log::error!("Failed to get function entry tree: {}", e); + tracing::error!("Failed to get function entry tree: {}", e); return None; } }; @@ -359,7 +360,7 @@ pub(crate) fn handle_function( let tree_root = match tree.root() { Ok(x) => x, Err(e) => { - log::error!("Failed to get function entry tree root: {}", e); + tracing::error!("Failed to get function entry tree root: {}", e); return None; } }; @@ -374,7 +375,7 @@ pub(crate) fn handle_function( debug_info_builder_context, debug_info_builder, ) else { - log::error!( + tracing::error!( "Failed to get function parameter child type in unit {:?} at offset {:x}", unit.header.offset(), child.entry().offset().0, @@ -384,7 +385,7 @@ pub(crate) fn handle_function( let name = debug_info_builder_context.get_name(dwarf, unit, child.entry()); let child_debug_type = debug_info_builder.get_type(child_uid).or_else(|| { - log::error!( + tracing::error!( "Failed to get function parameter type with uid {}", child_uid ); @@ -439,7 +440,7 @@ pub(crate) fn handle_const( Some(entry_type_offset) => debug_info_builder .get_type(entry_type_offset) .or_else(|| { - log::error!( + tracing::error!( "Failed to get const type with entry offset {}", entry_type_offset ); @@ -469,7 +470,7 @@ pub(crate) fn handle_volatile( Some(entry_type_offset) => debug_info_builder .get_type(entry_type_offset) .or_else(|| { - log::error!( + tracing::error!( "Failed to get volatile type with entry offset {}", entry_type_offset ); diff --git a/plugins/dwarf/dwarf_import/src/dwarfdebuginfo.rs b/plugins/dwarf/dwarf_import/src/dwarfdebuginfo.rs index c65e538746..51888afc5b 100644 --- a/plugins/dwarf/dwarf_import/src/dwarfdebuginfo.rs +++ b/plugins/dwarf/dwarf_import/src/dwarfdebuginfo.rs @@ -25,6 +25,7 @@ use binaryninja::{ rc::*, symbol::SymbolType, template_simplifier::simplify_str_to_fqn, + tracing, types::{FunctionParameter, Type}, variable::NamedVariableWithType, }; @@ -34,7 +35,6 @@ use gimli::{DebuggingInformationEntry, Dwarf, Unit}; use binaryninja::confidence::Conf; use binaryninja::variable::{Variable, VariableSourceType}; use indexmap::{map::Values, IndexMap}; -use log::{debug, error, warn}; use std::{cmp::Ordering, collections::HashMap, hash::Hash}; pub(crate) type TypeUID = usize; @@ -133,7 +133,7 @@ impl DebugInfoBuilderContext { if let Ok(unit) = dwarf.unit(header) { units.push(unit); } else { - error!("Unable to read DWARF information. File may be malformed or corrupted. Not applying debug info."); + tracing::error!("Unable to read DWARF information. File may be malformed or corrupted. Not applying debug info."); return None; } } @@ -145,7 +145,7 @@ impl DebugInfoBuilderContext { if let Ok(unit) = sup_dwarf.unit(header) { sup_units.push(unit); } else { - error!("Unable to read supplementary DWARF information. File may be malformed or corrupted. Not applying debug info."); + tracing::error!("Unable to read supplementary DWARF information. File may be malformed or corrupted. Not applying debug info."); return None; } } @@ -193,7 +193,7 @@ impl DebugInfoBuilderContext { match &entry_unit.entry(entry_offset) { Ok(x) => x, Err(e) => { - log::error!( + tracing::error!( "Failed to get entry {:?} in unit {:?}: {}", entry_offset, entry_unit.header.offset(), @@ -265,7 +265,7 @@ impl DebugInfoBuilder { // if the full name exists, update the stored index for the full name if let Some(idx) = self.raw_function_name_indices.get(ident) { let function = self.functions.get_mut(*idx).or_else(|| { - log::error!("Failed to get function with index {}", idx); + tracing::error!("Failed to get function with index {}", idx); None })?; @@ -298,7 +298,7 @@ impl DebugInfoBuilder { // if the raw name exists, update the stored index for the raw name if let Some(idx) = self.full_function_name_indices.get(ident) { let function = self.functions.get_mut(*idx).or_else(|| { - log::error!("Failed to get function with index {}", idx); + tracing::error!("Failed to get function with index {}", idx); None })?; @@ -325,7 +325,7 @@ impl DebugInfoBuilder { return Some(*idx); } } else { - debug!("Function entry in DWARF without full or raw name."); + tracing::debug!("Function entry in DWARF without full or raw name."); return None; } @@ -387,7 +387,7 @@ impl DebugInfoBuilder { }, ) { if existing_type != t && commit { - warn!("DWARF info contains duplicate type definition. Overwriting type `{}` (named `{:?}`) with `{}` (named `{:?}`)", + tracing::warn!("DWARF info contains duplicate type definition. Overwriting type `{}` (named `{:?}`) with `{}` (named `{:?}`)", existing_type, existing_name, t, @@ -434,7 +434,7 @@ impl DebugInfoBuilder { let Some(function_index) = fn_idx else { // If we somehow lost track of what subprogram we're in or we're not actually in a subprogram - error!( + tracing::error!( "Trying to add a local variable outside of a subprogram. Please report this issue." ); return; @@ -452,12 +452,12 @@ impl DebugInfoBuilder { let Some(func_addr) = function.address else { // If we somehow are processing a function's variables before the function is created - error!("Trying to add a local variable without a known function start. Please report this issue."); + tracing::error!("Trying to add a local variable without a known function start. Please report this issue."); return; }; let Some(frame_base) = &function.frame_base else { - error!("Trying to add a local variable ({}) to a function ({:#x}) without a frame base. Please report this issue.", name, func_addr); + tracing::error!("Trying to add a local variable ({}) to a function ({:#x}) without a frame base. Please report this issue.", name, func_addr); return; }; @@ -480,7 +480,7 @@ impl DebugInfoBuilder { .cloned() else { // Unknown why, but this is happening with MachO + external dSYM - debug!("Refusing to add a local variable ({}@{}) to function at {} without a known CFA adjustment.", name, offset, func_addr); + tracing::debug!("Refusing to add a local variable ({}@{}) to function at {} without a known CFA adjustment.", name, offset, func_addr); return; }; @@ -510,7 +510,7 @@ impl DebugInfoBuilder { if adjusted_offset > 0 { // If we somehow end up with a positive sp offset - error!("Trying to add a local variable \"{}\" in function at {:#x} at positive storage offset {}. Please report this issue.", name, func_addr, adjusted_offset); + tracing::error!("Trying to add a local variable \"{}\" in function at {:#x} at positive storage offset {}. Please report this issue.", name, func_addr, adjusted_offset); return; } @@ -536,7 +536,7 @@ impl DebugInfoBuilder { let existing_type = match self.get_type(existing_type_uid) { Some(x) => x.ty.as_ref(), None => { - log::error!( + tracing::error!( "Failed to find existing type with uid {} for data variable at {:#x}", existing_type_uid, address @@ -548,7 +548,7 @@ impl DebugInfoBuilder { let new_type = match self.get_type(type_uid) { Some(x) => x.ty.as_ref(), None => { - log::error!( + tracing::error!( "Failed to find new type with uid {} for data variable at {:#x}", type_uid, address @@ -558,7 +558,7 @@ impl DebugInfoBuilder { }; if existing_type_uid != type_uid || existing_type != new_type { - warn!("DWARF info contains duplicate data variable definition. Overwriting data variable at {:#08x} (`{}`) with `{}`", + tracing::warn!("DWARF info contains duplicate data variable definition. Overwriting data variable at {:#08x} (`{}`) with `{}`", address, existing_type, new_type @@ -580,7 +580,7 @@ impl DebugInfoBuilder { // Prevent storing two types with the same name and differing definitions if let Some(stored_uid) = type_uids_by_name.get(&debug_type_name) { let Some(stored_debug_type) = self.types.get(stored_uid) else { - error!("Stored type name without storing a type! Please report this error. UID: {}, name: {}", stored_uid, debug_type_name); + tracing::error!("Stored type name without storing a type! Please report this error. UID: {}, name: {}", stored_uid, debug_type_name); continue; }; @@ -624,14 +624,14 @@ impl DebugInfoBuilder { if let Some(target_type) = self.get_type(target_uid) { debug_info.add_type(&debug_type_name, &target_type.get_type(), &[]); } else { - error!( + tracing::error!( "Failed to find typedef {} target for uid {}", debug_type_name, ntr.name() ); } } else { - error!( + tracing::error!( "Failed to find typedef {} target uid for {}", debug_type_name, ntr.name() @@ -650,7 +650,7 @@ impl DebugInfoBuilder { let data_var_type = match self.get_type(*type_uid) { Some(x) => &x.ty, None => { - log::error!("Failed to find type for data variable at {:#x}", address); + tracing::error!("Failed to find type for data variable at {:#x}", address); continue; } }; @@ -752,7 +752,7 @@ impl DebugInfoBuilder { let existing_functions = bv.functions_at(*address); match existing_functions.len().cmp(&1) { Ordering::Greater => { - warn!("Multiple existing functions at address {address:08x}. One or more functions at this address may have the wrong platform information. Please report this binary."); + tracing::warn!("Multiple existing functions at address {address:08x}. One or more functions at this address may have the wrong platform information. Please report this binary."); } Ordering::Equal => { func.platform = Some(existing_functions.get(0).platform()) diff --git a/plugins/dwarf/dwarf_import/src/functions.rs b/plugins/dwarf/dwarf_import/src/functions.rs index 7ed9481032..a699c02b71 100644 --- a/plugins/dwarf/dwarf_import/src/functions.rs +++ b/plugins/dwarf/dwarf_import/src/functions.rs @@ -19,9 +19,9 @@ use crate::types::get_type; use crate::{helpers::*, ReaderType}; use binaryninja::template_simplifier::simplify_str_to_str; +use binaryninja::tracing; use cpp_demangle::DemangleOptions; use gimli::{constants, AttributeValue, DebuggingInformationEntry, Dwarf, Operation, Unit}; -use log::{debug, error}; use regex::Regex; #[derive(PartialEq, Eq, Hash)] @@ -45,14 +45,14 @@ fn get_parameters( let mut sub_die_tree = match unit.entries_tree(Some(entry.offset())) { Ok(x) => x, Err(e) => { - log::error!("Failed to get function parameter entry tree: {}", e); + tracing::error!("Failed to get function parameter entry tree: {}", e); return (vec![], false); } }; let root = match sub_die_tree.root() { Ok(x) => x, Err(e) => { - log::error!("Failed to get function parameter entry tree root: {}", e); + tracing::error!("Failed to get function parameter entry tree root: {}", e); return (vec![], false); } }; @@ -148,7 +148,7 @@ pub(crate) fn parse_function_entry( } if raw_name.is_none() && full_name.is_none() { - debug!( + tracing::debug!( "Function entry in DWARF without full or raw name: .debug_info offset {:?}", entry.offset().to_debug_info_offset(&unit.header) ); @@ -203,13 +203,13 @@ pub(crate) fn parse_lexical_block( let unit_base = match unit.header.offset().as_debug_info_offset() { Some(x) => x.0, None => { - log::warn!("Unable to get unit offset in debug info: {:?}. This may be an indicator of parsing issues.", unit.header.offset()); + tracing::warn!("Unable to get unit offset in debug info: {:?}. This may be an indicator of parsing issues.", unit.header.offset()); 0 } }; let Ok(Some(low_pc)) = dwarf.attr_address(unit, low_pc_value.clone()) else { - error!( + tracing::error!( "Failed to read lexical block low_pc for entry {:#x}, please report this bug.", unit_base + entry.offset().0 ); @@ -217,7 +217,7 @@ pub(crate) fn parse_lexical_block( }; let Ok(Some(high_pc_value)) = entry.attr_value(constants::DW_AT_high_pc) else { - error!("Failed to read lexical block high_pc attribute for entry {:#x}, please report this bug.", unit_base + entry.offset().0); + tracing::error!("Failed to read lexical block high_pc attribute for entry {:#x}, please report this bug.", unit_base + entry.offset().0); return None; }; @@ -226,7 +226,7 @@ pub(crate) fn parse_lexical_block( .and_then(|x| Some(low_pc + x)) .or_else(|| dwarf.attr_address(unit, high_pc_value).unwrap_or(None)) else { - error!( + tracing::error!( "Failed to read lexical block high_pc for entry {:#x}, please report this bug.", unit_base + entry.offset().0 ); @@ -244,9 +244,10 @@ pub(crate) fn parse_lexical_block( // Ranges where start == end may be ignored (DWARFv5 spec, 2.17.3 line 17) return None; } else { - error!( + tracing::error!( "Invalid lexical block range: {:#x} -> {:#x}", - low_pc, high_pc + low_pc, + high_pc ); } } else { diff --git a/plugins/dwarf/dwarf_import/src/helpers.rs b/plugins/dwarf/dwarf_import/src/helpers.rs index 33a7822960..78802f3446 100644 --- a/plugins/dwarf/dwarf_import/src/helpers.rs +++ b/plugins/dwarf/dwarf_import/src/helpers.rs @@ -18,12 +18,12 @@ use std::{str::FromStr, sync::mpsc}; use crate::{DebugInfoBuilderContext, ReaderType}; use binaryninja::binary_view::BinaryViewBase; -use binaryninja::Endianness; use binaryninja::{ binary_view::{BinaryView, BinaryViewExt}, download::{DownloadInstanceInputOutputCallbacks, DownloadProvider}, settings::Settings, }; +use binaryninja::{tracing, Endianness}; use gimli::Dwarf; use gimli::{ constants, Attribute, AttributeValue, @@ -32,7 +32,6 @@ use gimli::{ }; use binaryninja::settings::QueryOptions; -use log::warn; pub(crate) fn get_uid( dwarf: &Dwarf, @@ -111,14 +110,16 @@ pub(crate) fn get_attr_die<'a, R: ReaderType>( let sup: &Dwarf = match dwarf.sup() { Some(x) => x, None => { - log::error!("Trying to get offset in supplmentary dwarf info, but none is present"); + tracing::error!("Trying to get offset in supplmentary dwarf info, but none is present"); return None; } }; return Some(DieReference::UnitAndOffset((sup, source_unit, new_offset))); } } - warn!("Failed to fetch DIE. Supplementary debug information may be incomplete."); + tracing::warn!( + "Failed to fetch DIE. Supplementary debug information may be incomplete." + ); None } _ => None, @@ -143,7 +144,7 @@ pub(crate) fn resolve_specification<'a, R: ReaderType>( if let Ok(entry) = entry_unit.entry(entry_offset) { resolve_specification(dwarf, entry_unit, &entry, debug_info_builder_context) } else { - warn!("Failed to fetch DIE for attr DW_AT_specification. Debug information may be incomplete."); + tracing::warn!("Failed to fetch DIE for attr DW_AT_specification. Debug information may be incomplete."); DieReference::Err } } @@ -161,12 +162,12 @@ pub(crate) fn resolve_specification<'a, R: ReaderType>( if entry_offset == entry.offset() && unit.header.offset() == entry_unit.header.offset() { - warn!("DWARF information is invalid (infinite abstract origin reference cycle). Debug information may be incomplete."); + tracing::warn!("DWARF information is invalid (infinite abstract origin reference cycle). Debug information may be incomplete."); DieReference::Err } else if let Ok(new_entry) = entry_unit.entry(entry_offset) { resolve_specification(dwarf, entry_unit, &new_entry, debug_info_builder_context) } else { - warn!("Failed to fetch DIE for attr DW_AT_abstract_origin. Debug information may be incomplete."); + tracing::warn!("Failed to fetch DIE for attr DW_AT_abstract_origin. Debug information may be incomplete."); DieReference::Err } } @@ -189,7 +190,7 @@ pub(crate) fn get_name( let resolved_entry = match entry_unit.entry(entry_offset) { Ok(x) => x, Err(_) => { - log::error!( + tracing::error!( "Failed to get entry in unit at {:?} at offset {:#x} (get_name)", entry_unit.header.offset(), entry_offset.0 @@ -236,7 +237,7 @@ pub(crate) fn get_raw_name( let resolved_entry = match entry_unit.entry(entry_offset) { Ok(x) => x, Err(_) => { - log::error!( + tracing::error!( "Failed to get entry in unit at {:?} at offset {:#x} (get_raw_name)", entry_unit.header.offset(), entry_offset.0 diff --git a/plugins/dwarf/dwarf_import/src/lib.rs b/plugins/dwarf/dwarf_import/src/lib.rs index c9e6a2413e..50cc85284c 100644 --- a/plugins/dwarf/dwarf_import/src/lib.rs +++ b/plugins/dwarf/dwarf_import/src/lib.rs @@ -34,6 +34,7 @@ use binaryninja::{ debuginfo::{CustomDebugInfoParser, DebugInfo, DebugInfoParser}, settings::Settings, template_simplifier::simplify_str_to_str, + tracing, }; use dwarfreader::create_section_reader_object; @@ -43,10 +44,8 @@ use gimli::{ SectionId, Unit, UnwindContext, UnwindSection, }; -use binaryninja::logger::Logger; use helpers::{get_build_id, load_debug_info_for_build_id}; use iset::IntervalMap; -use log::{debug, error, warn}; use object::read::macho::FatArch; use object::{Object, ObjectSection}; @@ -126,7 +125,7 @@ fn recover_names_internal( while let Ok(Some(header)) = iter.next() { let unit_offset = header.offset().as_debug_info_offset().map_or_else( || { - log::warn!("Failed to get debug info offset for {:?}", header.offset()); + tracing::warn!("Failed to get debug info offset for {:?}", header.offset()); 0 }, |x| x.0, @@ -134,7 +133,7 @@ fn recover_names_internal( let unit = match dwarf.unit(header) { Ok(x) => x, Err(e) => { - log::error!("Failed to get unit at {:#x}: {}", unit_offset, e); + tracing::error!("Failed to get unit at {:#x}: {}", unit_offset, e); continue; } }; @@ -163,7 +162,7 @@ fn recover_names_internal( depth += delta_depth; if depth < 0 { - error!("DWARF information is seriously malformed. Aborting parsing."); + tracing::error!("DWARF information is seriously malformed. Aborting parsing."); return false; } @@ -196,7 +195,7 @@ fn recover_names_internal( let resolved_entry = match entry_unit.entry(entry_offset) { Ok(x) => x, Err(e) => { - log::error!("Failed to resolve entry in unit {:?} at offset {:#x} (resolve_namespace_name): {}", entry_unit.header.offset(), entry_offset.0, e); + tracing::error!("Failed to resolve entry in unit {:?} at offset {:#x} (resolve_namespace_name): {}", entry_unit.header.offset(), entry_offset.0, e); return; } }; @@ -210,7 +209,7 @@ fn recover_names_internal( ) } DieReference::Err => { - warn!( + tracing::warn!( "Failed to fetch DIE when resolving namespace. Debug information may be incomplete." ); } @@ -436,7 +435,7 @@ where }) { Ok(fde) => fde, Err(e) => { - error!("Failed to parse FDE: {}", e); + tracing::error!("Failed to parse FDE: {}", e); continue; } }; @@ -447,7 +446,7 @@ where } if fde.initial_address().overflowing_add(fde.len()).1 { - warn!( + tracing::warn!( "FDE at offset {:?} exceeds bounds of memory space! {:#x} + length {:#x}", fde.offset(), fde.initial_address(), @@ -481,7 +480,7 @@ where cfa_offsets .insert(row.start_address()..row.end_address(), *offset); } else { - debug!( + tracing::debug!( "Invalid FDE table row addresses: {:#x}..{:#x}", row.start_address(), row.end_address() @@ -489,7 +488,7 @@ where } } CfaRule::Expression(_) => { - debug!("Unhandled CFA expression when determining offset"); + tracing::debug!("Unhandled CFA expression when determining offset"); } }; } @@ -548,7 +547,7 @@ fn parse_dwarf( progress: Box Result<(), ()>>, ) -> Result { if debug_file.section_by_name(".gnu_debugaltlink").is_some() && supplementary_data.is_none() { - log::warn!(".gnu_debugaltlink section present but no supplementary data provided. DWARF parsing may fail.") + tracing::warn!(".gnu_debugaltlink section present but no supplementary data provided. DWARF parsing may fail.") } let address_size = match debug_file.architecture().address_size() { @@ -588,7 +587,7 @@ fn parse_dwarf( create_section_reader_object(section_id, &sup_file, sup_endian, sup_dwo_file) }; if let Err(e) = dwarf.load_sup(sup_section_reader) { - error!("Failed to load supplementary file: {}", e); + tracing::error!("Failed to load supplementary file: {}", e); } } @@ -620,7 +619,7 @@ fn parse_dwarf( let sup = match dwarf.sup() { Some(x) => x, None => { - log::error!( + tracing::error!( "Supplemental units found but no supplementary DWARF info available" ); break; @@ -743,7 +742,7 @@ impl CustomDebugInfoParser for DWARFParser { match helpers::load_sibling_debug_file(bv) { Ok(x) => x, Err(e) => { - log::error!("Failed loading sibling debug file: {}", e); + tracing::error!("Failed loading sibling debug file: {}", e); None } } @@ -754,7 +753,7 @@ impl CustomDebugInfoParser for DWARFParser { match load_debug_info_for_build_id(&build_id, bv) { Ok(x) => x, Err(e) => { - log::error!("Failed loading debug info from build id: {}", e); + tracing::error!("Failed loading debug info from build id: {}", e); None } } @@ -771,7 +770,7 @@ impl CustomDebugInfoParser for DWARFParser { let debug_file = match parse_data_to_object(debug_data_vec.as_slice(), bv) { Ok(x) => x, Err(e) => { - log::error!("Failed to parse debug data: {}", e); + tracing::error!("Failed to parse debug data: {}", e); return false; } }; @@ -784,7 +783,7 @@ impl CustomDebugInfoParser for DWARFParser { let sup_data = match load_debug_info_for_build_id(sup_build_id, bv) { Ok(x) => x, Err(e) => { - log::error!("Failed to load supplementary debug file: {}", e); + tracing::error!("Failed to load supplementary debug file: {}", e); None } }; @@ -795,13 +794,13 @@ impl CustomDebugInfoParser for DWARFParser { |sup_file_path| match std::fs::read(sup_file_path) { Ok(sup_data) => Some(sup_data), Err(e) => { - log::error!("Failed reading supplementary file {}: {}", x, e); + tracing::error!("Failed reading supplementary file {}: {}", x, e); None } }, ), Err(e) => { - log::error!("Supplementary file path is invalid utf8: {}", e); + tracing::error!("Supplementary file path is invalid utf8: {}", e); None } }) @@ -812,7 +811,7 @@ impl CustomDebugInfoParser for DWARFParser { match parse_data_to_object(data.as_slice(), bv) { Ok(x) => Some(x), Err(e) => { - log::error!("Failed to parse supplementary debug data: {}", e); + tracing::error!("Failed to parse supplementary debug data: {}", e); None } } @@ -823,7 +822,7 @@ impl CustomDebugInfoParser for DWARFParser { if let Ok(Some((_, expected_build_id))) = debug_file.gnu_debugaltlink() { if let Ok(Some(loaded_sup_build_id)) = sup_file.build_id() { if loaded_sup_build_id != expected_build_id { - log::warn!( + tracing::warn!( "Supplementary debug info build id ({}) does not match expected ({})", loaded_sup_build_id .iter() @@ -845,7 +844,7 @@ impl CustomDebugInfoParser for DWARFParser { true } Err(e) => { - log::error!("Failed to parse DWARF: {}", e); + tracing::error!("Failed to parse DWARF: {}", e); false } }; @@ -855,7 +854,7 @@ impl CustomDebugInfoParser for DWARFParser { } fn plugin_init() { - Logger::new("DWARF").init(); + binaryninja::tracing_init!("DWARF Import"); let settings = Settings::new(); diff --git a/plugins/dwarf/dwarf_import/src/types.rs b/plugins/dwarf/dwarf_import/src/types.rs index f870707bd0..9bcfe171f6 100644 --- a/plugins/dwarf/dwarf_import/src/types.rs +++ b/plugins/dwarf/dwarf_import/src/types.rs @@ -18,6 +18,7 @@ use crate::{die_handlers::*, ReaderType}; use binaryninja::{ rc::*, + tracing, types::{ BaseStructure, MemberAccess, MemberScope, ReferenceType, StructureBuilder, StructureType, Type, TypeClass, @@ -26,8 +27,6 @@ use binaryninja::{ use gimli::{constants, AttributeValue, DebuggingInformationEntry, DwAt, Dwarf, Operation, Unit}; -use log::{debug, error, warn}; - pub(crate) fn parse_variable( dwarf: &Dwarf, unit: &Unit, @@ -79,16 +78,17 @@ pub(crate) fn parse_variable( if let Ok(address) = dwarf.address(unit, index) { debug_info_builder.add_data_variable(address, full_name, uid) } else { - warn!("Invalid index into IAT: {}", index.0); + tracing::warn!("Invalid index into IAT: {}", index.0); } } } Ok(op) => { - debug!("Unhandled operation type for variable: {:?}", op); + tracing::debug!("Unhandled operation type for variable: {:?}", op); } - Err(e) => error!( + Err(e) => tracing::error!( "Error parsing operation type for variable {:?}: {}", - full_name, e + full_name, + e ), } } @@ -179,14 +179,14 @@ fn do_structure_parse( let mut tree = match unit.entries_tree(Some(entry.offset())) { Ok(x) => x, Err(e) => { - log::error!("Failed to get structure entry tree: {}", e); + tracing::error!("Failed to get structure entry tree: {}", e); return None; } }; let tree_root = match tree.root() { Ok(x) => x, Err(e) => { - log::error!("Failed to get structure entry tree root: {}", e); + tracing::error!("Failed to get structure entry tree root: {}", e); return None; } }; @@ -226,7 +226,7 @@ fn do_structure_parse( let Some(struct_offset_bytes) = get_attr_as_u64(&raw_struct_offset) .or_else(|| get_expr_value(unit, raw_struct_offset)) else { - log::warn!( + tracing::warn!( "Failed to get DW_AT_data_member_location for offset {:#x} in unit {:?}", child_entry.offset().0, unit.header.offset() @@ -311,7 +311,7 @@ fn do_structure_parse( debug_info_builder_context, debug_info_builder, ) else { - warn!("Failed to get base type for inheritance"); + tracing::warn!("Failed to get base type for inheritance"); continue; }; let Some(base_dbg_ty) = debug_info_builder.get_type(base_type_id) else { @@ -322,7 +322,7 @@ fn do_structure_parse( let Ok(Some(raw_data_member_location)) = child_entry.attr(constants::DW_AT_data_member_location) else { - warn!("Failed to get DW_AT_data_member_location for inheritance"); + tracing::warn!("Failed to get DW_AT_data_member_location for inheritance"); continue; }; @@ -393,7 +393,7 @@ pub(crate) fn get_type( let resolved_entry = match entry_unit.entry(entry_offset) { Ok(x) => x, Err(e) => { - log::error!( + tracing::error!( "Failed to resolve entry in unit {:?} at offset {:#x}: {}", entry_unit.header.offset(), entry_offset.0, @@ -411,7 +411,7 @@ pub(crate) fn get_type( ) } DieReference::Err => { - warn!("Failed to fetch DIE when getting type through DW_AT_type. Debug information may be incomplete."); + tracing::warn!("Failed to fetch DIE when getting type through DW_AT_type. Debug information may be incomplete."); None } } @@ -428,7 +428,7 @@ pub(crate) fn get_type( let resolved_entry = match entry_unit.entry(entry_offset) { Ok(x) => x, Err(e) => { - log::error!( + tracing::error!( "Failed to resolve entry in unit {:?} at offset {:#x}: {}", entry_unit.header.offset(), entry_offset.0, @@ -446,7 +446,7 @@ pub(crate) fn get_type( ) } DieReference::Err => { - warn!("Failed to fetch DIE when getting type through DW_AT_abstract_origin. Debug information may be incomplete."); + tracing::warn!("Failed to fetch DIE when getting type through DW_AT_abstract_origin. Debug information may be incomplete."); None } } @@ -460,7 +460,7 @@ pub(crate) fn get_type( let resolved_entry = match entry_unit.entry(entry_offset) { Ok(x) => x, Err(e) => { - log::error!( + tracing::error!( "Failed to resolve entry in unit {:?} at offset {:#x}: {}", entry_unit.header.offset(), entry_offset.0, @@ -479,7 +479,7 @@ pub(crate) fn get_type( } DieReference::UnitAndOffset(_) => None, DieReference::Err => { - warn!( + tracing::warn!( "Failed to fetch DIE when getting type. Debug information may be incomplete." ); None diff --git a/plugins/idb_import/Cargo.toml b/plugins/idb_import/Cargo.toml index cad56142d6..4a958106a4 100644 --- a/plugins/idb_import/Cargo.toml +++ b/plugins/idb_import/Cargo.toml @@ -13,4 +13,3 @@ anyhow = { version = "1.0.86", features = ["backtrace"] } binaryninja.workspace = true binaryninjacore-sys.workspace = true idb-rs = { git = "https://github.com/Vector35/idb-rs", tag = "0.1.12" } -log = "0.4" diff --git a/plugins/idb_import/src/lib.rs b/plugins/idb_import/src/lib.rs index b1643ea321..3564df11cd 100644 --- a/plugins/idb_import/src/lib.rs +++ b/plugins/idb_import/src/lib.rs @@ -18,10 +18,8 @@ use idb_rs::id0::{ID0Section, ID0SectionVariants}; use idb_rs::til::section::TILSection; use idb_rs::til::TypeVariant as TILTypeVariant; -use log::{error, trace, warn, LevelFilter}; - use anyhow::{anyhow, Result}; -use binaryninja::logger::Logger; +use binaryninja::tracing; struct IDBDebugInfoParser; impl CustomDebugInfoParser for IDBDebugInfoParser { @@ -45,7 +43,7 @@ impl CustomDebugInfoParser for IDBDebugInfoParser { match parse_idb_info(debug_info, bv, debug_file, progress) { Ok(()) => true, Err(error) => { - error!("Unable to parse IDB file: {error}"); + tracing::error!("Unable to parse IDB file: {error}"); false } } @@ -72,7 +70,7 @@ impl CustomDebugInfoParser for TILDebugInfoParser { match parse_til_info(debug_info, debug_file, progress) { Ok(()) => true, Err(error) => { - error!("Unable to parse TIL file: {error}"); + tracing::error!("Unable to parse TIL file: {error}"); false } } @@ -126,12 +124,12 @@ fn parse_idb_info( debug_file: &BinaryView, progress: Box Result<(), ()>>, ) -> Result<()> { - trace!("Opening a IDB file"); + tracing::trace!("Opening a IDB file"); let file = BinaryViewReader { bv: debug_file, offset: 0, }; - trace!("Parsing a IDB file"); + tracing::trace!("Parsing a IDB file"); let mut file = std::io::BufReader::new(file); let idb_kind = idb_rs::identify_idb_file(&mut file)?; match idb_kind { @@ -173,7 +171,7 @@ fn parse_idb_info_format( let id2_idx = format.id2_location(); if let Some(til_idx) = format.til_location() { - trace!("Parsing the TIL section"); + tracing::trace!("Parsing the TIL section"); let til = format.read_til(&mut idb_data, til_idx)?; // progress 0%-50% import_til_section(debug_info, debug_file, &til, progress)?; @@ -209,13 +207,13 @@ fn parse_til_info( debug_file: &BinaryView, progress: Box Result<(), ()>>, ) -> Result<()> { - trace!("Opening a TIL file"); + tracing::trace!("Opening a TIL file"); let file = BinaryViewReader { bv: debug_file, offset: 0, }; let mut file = std::io::BufReader::new(file); - trace!("Parsing the TIL section"); + tracing::trace!("Parsing the TIL section"); let til = TILSection::read(&mut file)?; import_til_section(debug_info, debug_file, &til, progress) } @@ -239,19 +237,19 @@ pub fn import_til_section( ); } TranslateTypeResult::Error(error) => { - error!( + tracing::error!( "Unable to parse type `{}`: {error}", ty.name.as_utf8_lossy(), ); } TranslateTypeResult::PartiallyTranslated(_, error) => { if let Some(error) = error { - error!( + tracing::error!( "Unable to parse type `{}` correctly: {error}", ty.name.as_utf8_lossy(), ); } else { - warn!( + tracing::warn!( "Type `{}` maybe not be fully translated", ty.name.as_utf8_lossy(), ); @@ -267,7 +265,7 @@ pub fn import_til_section( | TranslateTypeResult::PartiallyTranslated(bn_ty, _) = &ty.ty { if !debug_info.add_type(&ty.name.as_utf8_lossy(), bn_ty, &[/* TODO */]) { - error!("Unable to add type `{}`", ty.name.as_utf8_lossy()) + tracing::error!("Unable to add type `{}`", ty.name.as_utf8_lossy()) } } } @@ -278,7 +276,7 @@ pub fn import_til_section( | TranslateTypeResult::PartiallyTranslated(bn_ty, _) = &ty.ty { if !debug_info.add_type(&ty.name.as_utf8_lossy(), bn_ty, &[/* TODO */]) { - error!("Unable to fix type `{}`", ty.name.as_utf8_lossy()) + tracing::error!("Unable to fix type `{}`", ty.name.as_utf8_lossy()) } } } @@ -322,16 +320,16 @@ fn parse_id0_section_info( .and_then(|ty| match translate_ephemeral_type(debug_file, ty) { TranslateTypeResult::Translated(result) => Some(result), TranslateTypeResult::PartiallyTranslated(result, None) => { - warn!("Unable to fully translate the type at {addr:#x}"); + tracing::warn!("Unable to fully translate the type at {addr:#x}"); Some(result) } TranslateTypeResult::NotYet => { - error!("Unable to translate the type at {addr:#x}"); + tracing::error!("Unable to translate the type at {addr:#x}"); None } TranslateTypeResult::PartiallyTranslated(_, Some(bn_type_error)) | TranslateTypeResult::Error(bn_type_error) => { - error!("Unable to translate the type at {addr:#x}: {bn_type_error}",); + tracing::error!("Unable to translate the type at {addr:#x}: {bn_type_error}",); None } }); @@ -341,7 +339,7 @@ fn parse_id0_section_info( match (label, &ty, bnty) { (label, Some(ty), bnty) if matches!(&ty.type_variant, TILTypeVariant::Function(_)) => { if bnty.is_none() { - error!("Unable to convert the function type at {addr:#x}",) + tracing::error!("Unable to convert the function type at {addr:#x}",) } if !debug_info.add_function(&DebugFunctionInfo::new( None, @@ -353,18 +351,18 @@ fn parse_id0_section_info( vec![], vec![], )) { - error!("Unable to add the function at {addr:#x}") + tracing::error!("Unable to add the function at {addr:#x}") } } (label, Some(_ty), Some(bnty)) => { if !debug_info.add_data_variable(addr, &bnty, label.as_ref().map(Cow::as_ref), &[]) { - error!("Unable to add the type at {addr:#x}") + tracing::error!("Unable to add the type at {addr:#x}") } } (label, Some(_ty), None) => { // TODO types come from the TIL sections, can we make all types be just NamedTypes? - error!("Unable to convert type {addr:#x}"); + tracing::error!("Unable to convert type {addr:#x}"); // TODO how to add a label without a type associated with it? if let Some(name) = label { if !debug_info.add_data_variable( @@ -373,7 +371,7 @@ fn parse_id0_section_info( Some(&name), &[], ) { - error!("Unable to add the label at {addr:#x}") + tracing::error!("Unable to add the label at {addr:#x}") } } } @@ -385,7 +383,7 @@ fn parse_id0_section_info( Some(&name), &[], ) { - error!("Unable to add the label at {addr:#x}") + tracing::error!("Unable to add the label at {addr:#x}") } } @@ -402,9 +400,7 @@ fn parse_id0_section_info( #[allow(non_snake_case)] #[no_mangle] pub extern "C" fn CorePluginInit() -> bool { - Logger::new("IDB Import") - .with_level(LevelFilter::Error) - .init(); + binaryninja::tracing_init!("IDB Import"); DebugInfoParser::register("IDB Parser", IDBDebugInfoParser); DebugInfoParser::register("TIL Parser", TILDebugInfoParser); true diff --git a/plugins/pdb-ng/Cargo.toml b/plugins/pdb-ng/Cargo.toml index 3a9017d5cf..e77dac5b8e 100644 --- a/plugins/pdb-ng/Cargo.toml +++ b/plugins/pdb-ng/Cargo.toml @@ -12,7 +12,6 @@ anyhow = "^1.0" binaryninja.workspace = true binaryninjacore-sys.workspace = true itertools = "0.14" -log = "0.4" pdb = { git = "https://github.com/Vector35/pdb-rs", rev = "6016177" } regex = "1" diff --git a/plugins/pdb-ng/demo/Cargo.toml b/plugins/pdb-ng/demo/Cargo.toml index ddde9b9464..bde9b28cd3 100644 --- a/plugins/pdb-ng/demo/Cargo.toml +++ b/plugins/pdb-ng/demo/Cargo.toml @@ -13,7 +13,6 @@ anyhow = "^1.0" binaryninja = { workspace = true, features = ["demo"]} binaryninjacore-sys.workspace = true itertools = "0.14" -log = "0.4" pdb = { git = "https://github.com/Vector35/pdb-rs", rev = "6016177" } regex = "1" diff --git a/plugins/pdb-ng/src/lib.rs b/plugins/pdb-ng/src/lib.rs index c4da40e675..a21e3e7a83 100644 --- a/plugins/pdb-ng/src/lib.rs +++ b/plugins/pdb-ng/src/lib.rs @@ -21,15 +21,14 @@ use std::sync::mpsc; use std::{env, fs}; use anyhow::{anyhow, Result}; -use log::{debug, error, info}; use pdb::PDB; use binaryninja::binary_view::{BinaryView, BinaryViewBase, BinaryViewExt}; use binaryninja::debuginfo::{CustomDebugInfoParser, DebugInfo, DebugInfoParser}; use binaryninja::download::{DownloadInstanceInputOutputCallbacks, DownloadProvider}; use binaryninja::interaction::{MessageBoxButtonResult, MessageBoxButtonSet}; -use binaryninja::logger::Logger; use binaryninja::settings::{QueryOptions, Settings}; +use binaryninja::tracing::{debug, error, info}; use binaryninja::{interaction, user_directory}; use parser::PDBParserInstance; @@ -436,7 +435,9 @@ impl PDBParser { Ok(_) => { info!("Downloaded to: {}", cab_path.to_string_lossy()); } - Err(e) => error!("Could not write PDB to cache: {}", e), + Err(e) => { + error!("Could not write PDB to cache: {}", e) + } } } @@ -471,7 +472,9 @@ impl PDBParser { Ok(_) => { info!("Downloaded to: {}", cab_path.to_string_lossy()); } - Err(e) => error!("Could not write PDB to cache: {}", e), + Err(e) => { + error!("Could not write PDB to cache: {}", e) + } } } } @@ -588,7 +591,9 @@ impl CustomDebugInfoParser for PDBParser { } } Ok(None) => {} - e => error!("Error searching symbol store {}: {:?}", store, e), + e => { + error!("Error searching symbol store {}: {:?}", store, e) + } } } } @@ -649,7 +654,9 @@ impl CustomDebugInfoParser for PDBParser { Err(e) => debug!("Skipping, {}", e.to_string()), }, Err(e) if e.to_string() == "Cancelled" => return false, - Err(e) => debug!("Could not read pdb: {}", e.to_string()), + Err(e) => { + debug!("Could not read pdb: {}", e.to_string()) + } } } } @@ -690,7 +697,9 @@ impl CustomDebugInfoParser for PDBParser { } } Ok(None) => {} - e => error!("Error searching remote symbol server {}: {:?}", server, e), + e => { + error!("Error searching remote symbol server {}: {:?}", server, e) + } } } } @@ -718,7 +727,7 @@ pub extern "C" fn PDBPluginInit() -> bool { } fn init_plugin() -> bool { - Logger::new("PDB").init(); + binaryninja::tracing_init!("PDB Import"); DebugInfoParser::register("PDB", PDBParser {}); let settings = Settings::new(); diff --git a/plugins/pdb-ng/src/parser.rs b/plugins/pdb-ng/src/parser.rs index 2ca8e209ec..90f7fc0648 100644 --- a/plugins/pdb-ng/src/parser.rs +++ b/plugins/pdb-ng/src/parser.rs @@ -18,7 +18,6 @@ use std::fmt::Display; use std::sync::OnceLock; use anyhow::{anyhow, Result}; -use log::{debug, info}; use pdb::*; use crate::symbol_parser::{ParsedDataSymbol, ParsedProcedure, ParsedSymbol}; @@ -31,6 +30,7 @@ use binaryninja::debuginfo::{DebugFunctionInfo, DebugInfo}; use binaryninja::platform::Platform; use binaryninja::rc::Ref; use binaryninja::settings::{QueryOptions, Settings}; +use binaryninja::tracing::{debug, info}; use binaryninja::types::{ EnumerationBuilder, NamedTypeReference, NamedTypeReferenceClass, QualifiedName, StructureBuilder, StructureType, Type, TypeClass, diff --git a/plugins/pdb-ng/src/struct_grouper.rs b/plugins/pdb-ng/src/struct_grouper.rs index 4dc50d3b8e..62f7119813 100644 --- a/plugins/pdb-ng/src/struct_grouper.rs +++ b/plugins/pdb-ng/src/struct_grouper.rs @@ -12,16 +12,15 @@ // See the License for the specific language governing permissions and // limitations under the License. +use crate::type_parser::ParsedMember; use anyhow::{anyhow, Result}; use binaryninja::confidence::{Conf, MAX_CONFIDENCE}; +use binaryninja::tracing::{debug, warn}; use binaryninja::types::{MemberAccess, MemberScope, StructureBuilder, StructureType, Type}; -use log::{debug, warn}; use std::cmp::Ordering; use std::env; use std::fmt::{Debug, Display, Formatter}; -use crate::type_parser::ParsedMember; - #[derive(Debug, Clone, Copy, PartialEq, Eq)] struct MemberSize { index: usize, diff --git a/plugins/pdb-ng/src/type_parser.rs b/plugins/pdb-ng/src/type_parser.rs index dcb7234b7f..3490dfc032 100644 --- a/plugins/pdb-ng/src/type_parser.rs +++ b/plugins/pdb-ng/src/type_parser.rs @@ -24,12 +24,12 @@ use binaryninja::calling_convention::CoreCallingConvention; use binaryninja::confidence::{Conf, MAX_CONFIDENCE}; use binaryninja::platform::Platform; use binaryninja::rc::Ref; +use binaryninja::tracing::warn; use binaryninja::types::{ BaseStructure, EnumerationBuilder, EnumerationMember, FunctionParameter, MemberAccess, MemberScope, NamedTypeReference, NamedTypeReferenceClass, QualifiedName, StructureBuilder, StructureMember, StructureType, Type, TypeBuilder, TypeClass, }; -use log::warn; use pdb::Error::UnimplementedTypeKind; use pdb::{ ArgumentList, ArrayType, BaseClassType, BitfieldType, ClassKind, ClassType, EnumerateType, diff --git a/plugins/svd/Cargo.toml b/plugins/svd/Cargo.toml index e25c410b4e..cd36858580 100644 --- a/plugins/svd/Cargo.toml +++ b/plugins/svd/Cargo.toml @@ -11,7 +11,6 @@ crate-type = ["cdylib", "lib"] binaryninja.workspace = true binaryninjacore-sys.workspace = true svd-parser = { version = "0.14.8", features = ["expand"] } -log = "0.4" serde_json = "1.0" [dev-dependencies] diff --git a/plugins/svd/demo/Cargo.toml b/plugins/svd/demo/Cargo.toml index 0dffba6ee0..811f7d08bb 100644 --- a/plugins/svd/demo/Cargo.toml +++ b/plugins/svd/demo/Cargo.toml @@ -12,7 +12,6 @@ path = "../src/lib.rs" binaryninja = { workspace = true, features = ["demo"]} binaryninjacore-sys.workspace = true svd-parser = { version = "0.14.8", features = ["expand"] } -log = "0.4" serde_json = "1.0" [dev-dependencies] diff --git a/plugins/svd/src/lib.rs b/plugins/svd/src/lib.rs index 3a069056b4..396a9447b1 100644 --- a/plugins/svd/src/lib.rs +++ b/plugins/svd/src/lib.rs @@ -6,9 +6,8 @@ use crate::settings::LoadSettings; use binaryninja::binary_view::{BinaryView, BinaryViewBase, BinaryViewExt}; use binaryninja::command::Command; use binaryninja::interaction::{Form, FormInputField}; -use binaryninja::logger::Logger; +use binaryninja::tracing; use binaryninja::workflow::{activity, Activity, AnalysisContext, Workflow}; -use log::LevelFilter; use std::path::PathBuf; use svd_parser::ValidateLevel; @@ -120,7 +119,7 @@ impl Command for LoadSVDFile { let file_content = match std::fs::read_to_string(&file_path) { Ok(content) => content, Err(e) => { - log::error!("Failed to read file: {:?}", e); + tracing::error!("Failed to read file: {:?}", e); return; } }; @@ -137,7 +136,7 @@ impl Command for LoadSVDFile { view.update_analysis(); } Err(e) => { - log::error!("Failed to parse SVD file: {:?}", e); + tracing::error!("Failed to parse SVD file: {:?}", e); } } } @@ -152,7 +151,7 @@ impl Command for LoadSVDFile { #[cfg(not(feature = "demo"))] pub extern "C" fn CorePluginInit() -> bool { if plugin_init().is_err() { - log::error!("Failed to initialize SVD plug-in"); + tracing::error!("Failed to initialize SVD plug-in"); return false; } true @@ -163,14 +162,14 @@ pub extern "C" fn CorePluginInit() -> bool { #[cfg(feature = "demo")] pub extern "C" fn SVDPluginInit() -> bool { if plugin_init().is_err() { - log::error!("Failed to initialize SVD plug-in"); + tracing::error!("Failed to initialize SVD plug-in"); return false; } true } fn plugin_init() -> Result<(), ()> { - Logger::new("SVD").with_level(LevelFilter::Debug).init(); + binaryninja::tracing_init!("SVD"); binaryninja::command::register_command( "Load SVD File", @@ -185,13 +184,13 @@ fn plugin_init() -> Result<(), ()> { let view = ctx.view(); let load_settings = LoadSettings::from_view_settings(&view); let Some(file) = &load_settings.auto_load_file else { - log::debug!("No SVD file specified, skipping..."); + tracing::debug!("No SVD file specified, skipping..."); return; }; let file_content = match std::fs::read_to_string(file) { Ok(content) => content, Err(e) => { - log::error!("Failed to read file: {}", e); + tracing::error!("Failed to read file: {}", e); return; } }; @@ -204,7 +203,7 @@ fn plugin_init() -> Result<(), ()> { mapper.map_to_view(&view); } Err(e) => { - log::error!("Failed to parse SVD file: {:?}", e); + tracing::error!("Failed to parse SVD file: {:?}", e); } } }; diff --git a/plugins/svd/src/mapper.rs b/plugins/svd/src/mapper.rs index 4c49145be1..2c09eb954d 100644 --- a/plugins/svd/src/mapper.rs +++ b/plugins/svd/src/mapper.rs @@ -6,6 +6,7 @@ use binaryninja::rc::Ref; use binaryninja::section::{SectionBuilder, Semantics}; use binaryninja::segment::{SegmentBuilder, SegmentFlags}; use binaryninja::symbol::{SymbolBuilder, SymbolType}; +use binaryninja::tracing; use binaryninja::types::{ BaseStructure, EnumerationBuilder, MemberAccess, MemberScope, NamedTypeReference, NamedTypeReferenceClass, StructureBuilder, StructureMember, Type, TypeBuilder, @@ -78,7 +79,7 @@ impl DeviceMapper { } pub fn map_to_view(&self, view: &BinaryView) { - log::info!("Mapping device... {}", self.device.name); + tracing::info!("Mapping device... {}", self.device.name); for peripheral in &self.device.peripherals { match peripheral { Peripheral::Single(info) => { @@ -143,7 +144,7 @@ impl DeviceMapper { address_block: &AddressBlock, ) { let block_addr = peripheral.base_address + address_block.offset as u64; - log::info!( + tracing::info!( "Mapping peripheral block @ 0x{:x} for {}", block_addr, peripheral.name @@ -176,7 +177,7 @@ impl DeviceMapper { ); if !added_memory { - log::error!( + tracing::error!( "Failed to add memory for peripheral block! {} @ 0x{:x}", block_name, block_addr diff --git a/plugins/warp/Cargo.toml b/plugins/warp/Cargo.toml index 59f1e607f6..79f7632f10 100644 --- a/plugins/warp/Cargo.toml +++ b/plugins/warp/Cargo.toml @@ -14,7 +14,6 @@ demo = [] binaryninja = { workspace = true, features = ["rayon"] } binaryninjacore-sys.workspace = true warp = { git = "https://github.com/Vector35/warp/", tag = "1.0.1" } -log = "0.4" itertools = "0.14.0" dashmap = { version = "6.1", features = ["rayon"]} rayon = "1.10" diff --git a/plugins/warp/demo/Cargo.toml b/plugins/warp/demo/Cargo.toml index 8e1070e307..5066448301 100644 --- a/plugins/warp/demo/Cargo.toml +++ b/plugins/warp/demo/Cargo.toml @@ -15,7 +15,6 @@ demo = [] binaryninja = { workspace = true, features = ["rayon", "demo"] } binaryninjacore-sys.workspace = true warp = { git = "https://github.com/Vector35/warp/", tag = "1.0.0" } -log = "0.4" itertools = "0.14.0" dashmap = { version = "6.1", features = ["rayon"]} rayon = "1.10" diff --git a/plugins/warp/src/cache.rs b/plugins/warp/src/cache.rs index 09ad14444e..30c7487c0d 100644 --- a/plugins/warp/src/cache.rs +++ b/plugins/warp/src/cache.rs @@ -11,7 +11,7 @@ use binaryninja::binary_view::{BinaryView, BinaryViewExt}; use binaryninja::function::Function as BNFunction; use binaryninja::rc::Guard; use binaryninja::rc::Ref as BNRef; -use binaryninja::ObjectDestructor; +use binaryninja::{tracing, ObjectDestructor}; use std::hash::{DefaultHasher, Hash, Hasher}; pub fn register_cache_destructor() { @@ -31,7 +31,7 @@ impl From<&BinaryView> for ViewID { fn from(value: &BinaryView) -> Self { let mut hasher = DefaultHasher::new(); hasher.write_u64(value.original_image_base()); - hasher.write_usize(value.file().session_id()); + hasher.write_usize(value.file().session_id().0); Self(hasher.finish()) } } @@ -79,6 +79,6 @@ pub struct CacheDestructor; impl ObjectDestructor for CacheDestructor { fn destruct_view(&self, view: &BinaryView) { clear_type_ref_cache(view); - log::debug!("Removed WARP caches for {:?}", view.file().filename()); + tracing::debug!("Removed WARP caches for {:?}", view.file().filename()); } } diff --git a/plugins/warp/src/container/disk.rs b/plugins/warp/src/container/disk.rs index a0400f9dec..5e4a56139b 100644 --- a/plugins/warp/src/container/disk.rs +++ b/plugins/warp/src/container/disk.rs @@ -1,6 +1,7 @@ use crate::container::{ Container, ContainerError, ContainerResult, SourceId, SourcePath, SourceTag, }; +use binaryninja::tracing; use std::collections::{HashMap, HashSet}; use std::fmt::{Debug, Display, Formatter}; use std::hash::{Hash, Hasher}; @@ -42,7 +43,7 @@ impl DiskContainer { match (DiskContainerSource::new_from_path(path.clone()), path_ext) { (Ok(source), _) => Some((source_id, source)), (Err(err), Some("warp")) => { - log::error!("Failed to load source '{}' from disk: {}", path, err); + tracing::error!("Failed to load source '{}' from disk: {}", path, err); None } // We don't care to show errors loading for non-warp files. diff --git a/plugins/warp/src/container/network.rs b/plugins/warp/src/container/network.rs index d0ccd3ea13..0908b103f1 100644 --- a/plugins/warp/src/container/network.rs +++ b/plugins/warp/src/container/network.rs @@ -3,6 +3,7 @@ use crate::container::{ Container, ContainerError, ContainerResult, ContainerSearchQuery, ContainerSearchResponse, SourceId, SourcePath, SourceTag, }; +use binaryninja::tracing; use directories::ProjectDirs; use std::collections::{HashMap, HashSet}; use std::fmt::{Debug, Display, Formatter}; @@ -102,7 +103,7 @@ impl NetworkContainer { guids: &[FunctionGUID], ) -> HashMap> { let Some(target_id) = target.and_then(|t| self.get_target_id(t)) else { - log::debug!("Cannot query functions source without a target, skipping..."); + tracing::debug!("Cannot query functions source without a target, skipping..."); return HashMap::new(); }; @@ -122,7 +123,7 @@ impl NetworkContainer { { Ok(queried_results) => queried_results, Err(e) => { - log::error!("Failed to query functions source: {}", e); + tracing::error!("Failed to query functions source: {}", e); return result; } }; @@ -170,12 +171,12 @@ impl NetworkContainer { { Ok(file) => file, Err(e) => { - log::error!("Failed to query functions: {}", e); + tracing::error!("Failed to query functions: {}", e); return; } }; - log::debug!("Got {} chunks from server", file.chunks.len()); + tracing::debug!("Got {} chunks from server", file.chunks.len()); for chunk in &file.chunks { match &chunk.kind { ChunkKind::Signature(sc) => { @@ -183,12 +184,12 @@ impl NetworkContainer { // Probe the source before attempting to access it, as it might not exist locally. self.probe_source(*source); match self.cache.add_functions(target, source, &functions) { - Ok(_) => log::debug!( + Ok(_) => tracing::debug!( "Added {} functions into cached source '{}'", functions.len(), source ), - Err(err) => log::error!( + Err(err) => tracing::error!( "Failed to add {} function into cached source '{}': {}", functions.len(), source, @@ -227,7 +228,7 @@ impl NetworkContainer { let _ = self.cache.insert_source(source_id, SourcePath(source_path)); } Err(e) => { - log::error!("Failed to probe source '{}': {}", source_id, e); + tracing::error!("Failed to probe source '{}': {}", source_id, e); } } } diff --git a/plugins/warp/src/container/network/client.rs b/plugins/warp/src/container/network/client.rs index 9f68180ba3..d3c94d1a73 100644 --- a/plugins/warp/src/container/network/client.rs +++ b/plugins/warp/src/container/network/client.rs @@ -5,6 +5,7 @@ use crate::container::{ }; use base64::Engine; use binaryninja::download::DownloadProvider; +use binaryninja::tracing; use serde::Deserialize; use serde_json::json; use std::collections::HashMap; @@ -496,14 +497,14 @@ impl NetworkClient { let kind = match item.kind.as_str() { "function" => { let Some(data) = &item.data else { - log::warn!( + tracing::warn!( "Function item {} has no data from network, skipping...", item.id ); continue; }; let Some(func) = Function::from_bytes(&data) else { - log::warn!( + tracing::warn!( "Function item {} has invalid data from network, skipping...", item.id ); @@ -514,7 +515,7 @@ impl NetworkClient { "source" => ContainerSearchItemKind::Source { path: match item.name { None => { - log::warn!("Source item {} has no name", item.id); + tracing::warn!("Source item {} has no name", item.id); continue; } Some(name) => SourcePath(format!("{}/{}", self.server_url, name).into()), @@ -523,14 +524,14 @@ impl NetworkClient { }, "type" => { let Some(data) = &item.data else { - log::warn!( + tracing::warn!( "Type item {} has no data from network, skipping...", item.id ); continue; }; let Some(ty) = Type::from_bytes(&data) else { - log::warn!( + tracing::warn!( "Type item {} has invalid data from network, skipping...", item.id ); diff --git a/plugins/warp/src/convert/types.rs b/plugins/warp/src/convert/types.rs index f8ead6afd3..227df2eac7 100644 --- a/plugins/warp/src/convert/types.rs +++ b/plugins/warp/src/convert/types.rs @@ -6,6 +6,7 @@ use binaryninja::calling_convention::CoreCallingConvention as BNCallingConventio use binaryninja::confidence::Conf as BNConf; use binaryninja::confidence::MAX_CONFIDENCE; use binaryninja::rc::Ref as BNRef; +use binaryninja::tracing; use binaryninja::types::BaseStructure as BNBaseStructure; use binaryninja::types::EnumerationBuilder as BNEnumerationBuilder; use binaryninja::types::FunctionParameter as BNFunctionParameter; @@ -361,7 +362,7 @@ pub fn to_bn_type(arch: Option, ty: &Type) -> BNRef )) } _ => { - log::error!( + tracing::error!( "Adding base {:?} with invalid ty: {:?}", ty.name, member.ty @@ -470,7 +471,7 @@ pub fn to_bn_type(arch: Option, ty: &Type) -> BNRef ntr_name, ), None => { - log::error!("Referrer with no reference! {:?}", c); + tracing::error!("Referrer with no reference! {:?}", c); NamedTypeReference::new( NamedTypeReferenceClass::UnknownNamedTypeClass, "AHHHHHH", diff --git a/plugins/warp/src/plugin.rs b/plugins/warp/src/plugin.rs index 9fe6cd3f32..dec62c2f0f 100644 --- a/plugins/warp/src/plugin.rs +++ b/plugins/warp/src/plugin.rs @@ -12,10 +12,8 @@ use binaryninja::background_task::BackgroundTask; use binaryninja::command::{ register_command, register_command_for_function, register_command_for_project, }; -use binaryninja::is_ui_enabled; -use binaryninja::logger::Logger; use binaryninja::settings::{QueryOptions, Settings}; -use log::LevelFilter; +use binaryninja::{is_ui_enabled, tracing}; mod commit; mod create; @@ -42,16 +40,16 @@ fn load_bundled_signatures() { let mut core_disk_container = DiskContainer::new_from_dir(core_signature_dir()); core_disk_container.name = "Bundled".to_string(); core_disk_container.writable = false; - log::debug!("{:#?}", core_disk_container); + tracing::debug!("{:#?}", core_disk_container); add_cached_container(core_disk_container); } if plugin_settings.load_user_files { let mut user_disk_container = DiskContainer::new_from_dir(user_signature_dir()); user_disk_container.name = "User".to_string(); - log::debug!("{:#?}", user_disk_container); + tracing::debug!("{:#?}", user_disk_container); add_cached_container(user_disk_container); } - log::info!("Loading files took {:?}", start.elapsed()); + tracing::info!("Loading files took {:?}", start.elapsed()); background_task.finish(); } @@ -62,7 +60,7 @@ fn load_network_container() { let network_client = NetworkClient::new(url.clone(), api_key.clone()); // Before constructing the container, let's make sure that the server is OK. if let Err(e) = network_client.status() { - log::warn!("Server '{}' failed to connect: {}", url, e); + tracing::warn!("Server '{}' failed to connect: {}", url, e); return; } @@ -70,7 +68,7 @@ fn load_network_container() { let mut writable_sources = Vec::new(); match network_client.current_user() { Ok((id, username)) => { - log::info!( + tracing::info!( "Server '{}' connected, logged in as user '{}'", url, username @@ -80,19 +78,19 @@ fn load_network_container() { writable_sources = sources; } Err(e) => { - log::error!("Server '{}' failed to get sources for user: {}", url, e); + tracing::error!("Server '{}' failed to get sources for user: {}", url, e); } } } Err(e) if api_key.is_some() => { - log::error!( + tracing::error!( "Server '{}' failed to authenticate with provided API key: {}", url, e ); } Err(_) => { - log::info!("Server '{}' connected, logged in as guest", url); + tracing::info!("Server '{}' connected, logged in as guest", url); } } @@ -100,7 +98,7 @@ fn load_network_container() { let main_cache_path = NetworkContainer::root_cache_location().join("main"); let network_container = NetworkContainer::new(network_client, main_cache_path, &writable_sources); - log::debug!("{:#?}", network_container); + tracing::debug!("{:#?}", network_container); add_cached_container(network_container); }; @@ -114,17 +112,17 @@ fn load_network_container() { add_network_container(second_server_url, plugin_settings.second_server_api_key); } } - log::debug!("Initializing warp server took {:?}", start.elapsed()); + tracing::debug!("Initializing warp server took {:?}", start.elapsed()); background_task.finish(); } fn plugin_init() -> bool { - Logger::new("WARP").with_level(LevelFilter::Debug).init(); + binaryninja::tracing_init!("WARP"); // Create the user signature directory if it does not exist, otherwise we will not be able to write to it. if !user_signature_dir().exists() { if let Err(e) = std::fs::create_dir_all(&user_signature_dir()) { - log::error!("Failed to create user signature directory: {}", e); + tracing::error!("Failed to create user signature directory: {}", e); } } @@ -141,7 +139,7 @@ fn plugin_init() -> bool { HighlightRenderLayer::register(); if workflow::insert_workflow().is_err() { - log::error!("Failed to register WARP workflow"); + tracing::error!("Failed to register WARP workflow"); return false; } diff --git a/plugins/warp/src/plugin/commit.rs b/plugins/warp/src/plugin/commit.rs index 2af5fc3e6d..56a78f9a87 100644 --- a/plugins/warp/src/plugin/commit.rs +++ b/plugins/warp/src/plugin/commit.rs @@ -6,6 +6,7 @@ use crate::plugin::create::OpenFileField; use binaryninja::binary_view::BinaryView; use binaryninja::command::Command; use binaryninja::interaction::{Form, FormInputField}; +use binaryninja::tracing; use warp::chunk::ChunkKind; use warp::WarpFile; @@ -84,11 +85,11 @@ impl CommitFile { let open_file_path = OpenFileField::from_form(&form)?; let source_id = source_field.from_form(&form)?; - log::info!("Committing file to source: {}", source_id); + tracing::info!("Committing file to source: {}", source_id); let bytes = std::fs::read(open_file_path).ok()?; let Some(warp_file) = WarpFile::from_bytes(&bytes) else { - log::error!("Failed to parse warp file!"); + tracing::error!("Failed to parse warp file!"); return None; }; @@ -103,7 +104,7 @@ impl CommitFile { match &chunk.kind { ChunkKind::Signature(sc) => { let functions: Vec<_> = sc.functions().collect(); - log::info!( + tracing::info!( "Adding {} functions to source: {}", functions.len(), source_id @@ -113,22 +114,22 @@ impl CommitFile { &source_id, &functions, ) { - log::error!("Failed to add functions to source: {}", e); + tracing::error!("Failed to add functions to source: {}", e); } } ChunkKind::Type(sc) => { let types: Vec<_> = sc.types().collect(); - log::info!("Adding {} types to source: {}", types.len(), source_id); + tracing::info!("Adding {} types to source: {}", types.len(), source_id); if let Err(e) = container.add_computed_types(&source_id, &types) { - log::error!("Failed to add types to source: {}", e); + tracing::error!("Failed to add types to source: {}", e); } } } } if let Err(e) = container.commit_source(&source_id) { - log::error!("Failed to commit source: {}", e); + tracing::error!("Failed to commit source: {}", e); } - log::info!("Committed file to source: {}", source_id); + tracing::info!("Committed file to source: {}", source_id); return Some(()); } } diff --git a/plugins/warp/src/plugin/create.rs b/plugins/warp/src/plugin/create.rs index d6839ce663..04a3e9b6bd 100644 --- a/plugins/warp/src/plugin/create.rs +++ b/plugins/warp/src/plugin/create.rs @@ -10,6 +10,7 @@ use binaryninja::command::Command; use binaryninja::interaction::form::{Form, FormInputField}; use binaryninja::interaction::{MessageBoxButtonResult, MessageBoxButtonSet, MessageBoxIcon}; use binaryninja::rc::Ref; +use binaryninja::tracing; use std::path::PathBuf; use std::thread; use warp::chunk::Chunk; @@ -131,7 +132,7 @@ impl CreateFromCurrentView { existing_chunks.extend(existing_file.chunks); } MessageBoxButtonResult::CancelButton => { - log::info!( + tracing::info!( "User cancelled signature file creation, no operations were performed." ); return None; @@ -168,7 +169,7 @@ impl CreateFromCurrentView { MessageBoxButtonSet::OKButtonSet, MessageBoxIcon::ErrorIcon, ); - log::error!("Failed to create signature file: {}", err); + tracing::error!("Failed to create signature file: {}", err); return None; } @@ -184,7 +185,9 @@ impl CreateFromCurrentView { // After merging, we should have at least one chunk. If not, merging actually removed data. if file.chunks.len() < 1 { - log::error!("Failed to merge chunks! Please report this, it should not happen."); + tracing::error!( + "Failed to merge chunks! Please report this, it should not happen." + ); return None; } } @@ -192,9 +195,9 @@ impl CreateFromCurrentView { let file_bytes = file.to_bytes(); let file_size = file_bytes.len(); if std::fs::write(&file_path, file_bytes).is_err() { - log::error!("Failed to write data to signature file!"); + tracing::error!("Failed to write data to signature file!"); } - log::info!("Saved signature file to: '{}'", file_path.display()); + tracing::info!("Saved signature file to: '{}'", file_path.display()); background_task.finish(); // Show a report of the generate signatures, if desired. @@ -210,7 +213,7 @@ impl CreateFromCurrentView { // The ReportWidget uses a QTextBrowser, which cannot render large files very well. if file_size > 10000000 { - log::warn!("WARP report file is too large to show in the UI. Please see the report file on disk."); + tracing::warn!("WARP report file is too large to show in the UI. Please see the report file on disk."); } else { match report_kind { ReportKindField::None => {} diff --git a/plugins/warp/src/plugin/debug.rs b/plugins/warp/src/plugin/debug.rs index 399dba50bf..6db491e28d 100644 --- a/plugins/warp/src/plugin/debug.rs +++ b/plugins/warp/src/plugin/debug.rs @@ -3,13 +3,13 @@ use crate::{build_function, cache}; use binaryninja::binary_view::BinaryView; use binaryninja::command::{Command, FunctionCommand}; use binaryninja::function::Function; -use binaryninja::ObjectDestructor; +use binaryninja::{tracing, ObjectDestructor}; pub struct DebugFunction; impl FunctionCommand for DebugFunction { fn action(&self, _view: &BinaryView, func: &Function) { - log::info!( + tracing::info!( "{:#?}", build_function(func, || func.lifted_il().ok(), false) ); @@ -25,7 +25,7 @@ pub struct DebugCache; impl Command for DebugCache { fn action(&self, _view: &BinaryView) { for_cached_containers(|c| { - log::info!("Container: {:#?}", c); + tracing::info!("Container: {:#?}", c); }); } @@ -40,7 +40,7 @@ impl Command for DebugInvalidateCache { fn action(&self, view: &BinaryView) { let destructor = cache::CacheDestructor {}; destructor.destruct_view(view); - log::info!("Invalidated all WARP caches..."); + tracing::info!("Invalidated all WARP caches..."); } fn valid(&self, _view: &BinaryView) -> bool { diff --git a/plugins/warp/src/plugin/ffi/container.rs b/plugins/warp/src/plugin/ffi/container.rs index 72c8536682..6c2551c18c 100644 --- a/plugins/warp/src/plugin/ffi/container.rs +++ b/plugins/warp/src/plugin/ffi/container.rs @@ -10,6 +10,7 @@ use binaryninja::architecture::CoreArchitecture; use binaryninja::binary_view::BinaryView; use binaryninja::rc::Ref; use binaryninja::string::BnString; +use binaryninja::tracing; use binaryninja::types::Type; use binaryninjacore_sys::{BNArchitecture, BNBinaryView, BNType}; use std::ffi::{c_char, CStr}; @@ -219,7 +220,7 @@ pub unsafe extern "C" fn BNWARPContainerFetchFunctions( let guids = unsafe { std::slice::from_raw_parts(guids, count) }; if let Err(e) = container.fetch_functions(&target, &source_tags, guids) { - log::error!("Failed to fetch functions: {}", e); + tracing::error!("Failed to fetch functions: {}", e); } } @@ -586,7 +587,7 @@ pub unsafe extern "C" fn BNWARPContainerSearch( let result = match container.search(&query) { Ok(result) => result, Err(err) => { - log::error!("Failed to search container {:?}: {}", query.deref(), err); + tracing::error!("Failed to search container {:?}: {}", query.deref(), err); return std::ptr::null_mut(); } }; diff --git a/plugins/warp/src/plugin/file.rs b/plugins/warp/src/plugin/file.rs index ec61bd788d..899e3f4653 100644 --- a/plugins/warp/src/plugin/file.rs +++ b/plugins/warp/src/plugin/file.rs @@ -1,6 +1,7 @@ use crate::report::ReportGenerator; use binaryninja::binary_view::{BinaryView, BinaryViewExt}; use binaryninja::command::Command; +use binaryninja::tracing; pub struct ShowFileReport; @@ -15,12 +16,12 @@ impl Command for ShowFileReport { }; let Ok(bytes) = std::fs::read(&path) else { - log::error!("Failed to read file: {:?}", path); + tracing::error!("Failed to read file: {:?}", path); return; }; let Some(file) = warp::WarpFile::from_bytes(&bytes) else { - log::error!("Failed to parse file: {:?}", path); + tracing::error!("Failed to parse file: {:?}", path); return; }; diff --git a/plugins/warp/src/plugin/function.rs b/plugins/warp/src/plugin/function.rs index 6202f9d7fd..3c0dc06c8b 100644 --- a/plugins/warp/src/plugin/function.rs +++ b/plugins/warp/src/plugin/function.rs @@ -10,6 +10,7 @@ use binaryninja::binary_view::{BinaryView, BinaryViewExt}; use binaryninja::command::{Command, FunctionCommand}; use binaryninja::function::{Function, FunctionUpdateType}; use binaryninja::rc::Guard; +use binaryninja::tracing; use rayon::iter::ParallelIterator; use std::thread; use warp::signature::function::FunctionGUID; @@ -24,7 +25,7 @@ impl FunctionCommand for IncludeFunction { let insert_tag_type = get_warp_include_tag_type(view); match should_add_tag { true => { - log::info!( + tracing::info!( "Including selected function '{}' at 0x{:x}", sym_name_str, func.start() @@ -32,7 +33,7 @@ impl FunctionCommand for IncludeFunction { func.add_tag(&insert_tag_type, "", None, false, None); } false => { - log::info!( + tracing::info!( "Removing included function '{}' at 0x{:x}", sym_name_str, func.start() @@ -58,7 +59,7 @@ impl FunctionCommand for IgnoreFunction { let ignore_tag_type = get_warp_ignore_tag_type(view); match should_add_tag { true => { - log::info!( + tracing::info!( "Ignoring function for matching '{}' at 0x{:x}", sym_name_str, func.start() @@ -66,7 +67,7 @@ impl FunctionCommand for IgnoreFunction { func.add_tag(&ignore_tag_type, "", None, false, None); } false => { - log::info!( + tracing::info!( "Including function for matching '{}' at 0x{:x}", sym_name_str, func.start() @@ -87,7 +88,7 @@ impl FunctionCommand for RemoveFunction { fn action(&self, _view: &BinaryView, func: &Function) { let sym_name = func.symbol().short_name(); let sym_name_str = sym_name.to_string_lossy(); - log::info!( + tracing::info!( "Removing matched function '{}' at 0x{:x}", sym_name_str, func.start() @@ -107,10 +108,10 @@ pub struct CopyFunctionGUID; impl FunctionCommand for CopyFunctionGUID { fn action(&self, _view: &BinaryView, func: &Function) { let Some(guid) = cached_function_guid(func, || func.lifted_il().ok()) else { - log::error!("Could not get guid for copied function"); + tracing::error!("Could not get guid for copied function"); return; }; - log::info!( + tracing::info!( "Function GUID for {:?}... {}", func.symbol().short_name(), guid @@ -137,11 +138,11 @@ impl Command for FindFunctionFromGUID { }; let Ok(searched_guid) = guid_str.parse::() else { - log::error!("Failed to parse function guid... {}", guid_str); + tracing::error!("Failed to parse function guid... {}", guid_str); return; }; - log::info!("Searching functions for GUID... {}", searched_guid); + tracing::info!("Searching functions for GUID... {}", searched_guid); let funcs = view.functions(); let view = view.to_owned(); thread::spawn(move || { @@ -159,7 +160,7 @@ impl Command for FindFunctionFromGUID { .collect(); if matched.is_empty() { - log::info!("No matches found for GUID... {}", searched_guid); + tracing::info!("No matches found for GUID... {}", searched_guid); } else { for func in &matched { // Also navigate the user, as that is probably what they want. @@ -170,14 +171,14 @@ impl Command for FindFunctionFromGUID { .navigate_to(¤t_view, func.start()) .is_err() { - log::error!( + tracing::error!( "Failed to navigate to found function 0x{:0x} in view {}", func.start(), current_view ); } } - log::info!("Match found at function... 0x{:0x}", func.start()); + tracing::info!("Match found at function... 0x{:0x}", func.start()); } } diff --git a/plugins/warp/src/plugin/load.rs b/plugins/warp/src/plugin/load.rs index 0b8d1672d9..bd0e483841 100644 --- a/plugins/warp/src/plugin/load.rs +++ b/plugins/warp/src/plugin/load.rs @@ -10,6 +10,7 @@ use binaryninja::interaction::{ MessageBoxIcon, }; use binaryninja::rc::Ref; +use binaryninja::tracing; use std::collections::HashMap; use std::path::PathBuf; use std::sync::atomic::AtomicBool; @@ -130,7 +131,7 @@ impl LoadSignatureFile { let file = match LoadSignatureFile::read_file(&view, source_file_path.clone()) { Ok(file) => file, Err(e) => { - log::error!("Failed to read signature file: {}", e); + tracing::error!("Failed to read signature file: {}", e); return; } }; @@ -156,7 +157,7 @@ impl LoadSignatureFile { } let container_source = DiskContainerSource::new(source_file_path.clone(), file); - log::info!("Loading container source: '{}'", container_source.path); + tracing::info!("Loading container source: '{}'", container_source.path); let mut map = HashMap::new(); map.insert(source_file_path.to_source_id(), container_source); let container = DiskContainer::new("Loaded signatures".to_string(), map); diff --git a/plugins/warp/src/plugin/project.rs b/plugins/warp/src/plugin/project.rs index 725d164c6e..8862c00a6e 100644 --- a/plugins/warp/src/plugin/project.rs +++ b/plugins/warp/src/plugin/project.rs @@ -9,6 +9,7 @@ use binaryninja::interaction::{Form, FormInputField}; use binaryninja::project::folder::ProjectFolder; use binaryninja::project::Project; use binaryninja::rc::Ref; +use binaryninja::tracing; use binaryninja::worker_thread::{set_worker_thread_count, worker_thread_count}; use rayon::ThreadPoolBuilder; use regex::Regex; @@ -157,7 +158,7 @@ impl CreateSignatures { .create_file(&warp_file.to_bytes(), folder, name, "") .is_err() { - log::error!("Failed to create project file!"); + tracing::error!("Failed to create project file!"); } let report = ReportGenerator::new(); @@ -168,7 +169,7 @@ impl CreateSignatures { .create_file(&generated.into_bytes(), folder, &file_name, "Warp file") .is_err() { - log::error!("Failed to create project file!"); + tracing::error!("Failed to create project file!"); } } }; @@ -177,12 +178,12 @@ impl CreateSignatures { let callback_project = project.clone(); let save_individual_files_cb = move |path: &Path, file: &WarpFile| { if file.chunks.is_empty() { - log::debug!("Skipping empty file: {}", path.display()); + tracing::debug!("Skipping empty file: {}", path.display()); return; } // The path returned will be the one on disk, so we will go and grab the project for it. let Some(project_file) = callback_project.file_by_path(path) else { - log::error!("Failed to find project file for path: {}", path.display()); + tracing::error!("Failed to find project file for path: {}", path.display()); return; }; let project_file = project_file.to_owned(); @@ -214,8 +215,8 @@ impl CreateSignatures { processor = processor.with_file_filter(f); } Err(err) => { - log::error!("Failed to parse file filter: {}", err); - log::error!( + tracing::error!("Failed to parse file filter: {}", err); + tracing::error!( "Consider using a substring instead of a glob pattern, e.g. *.exe => exe" ); return; @@ -231,7 +232,7 @@ impl CreateSignatures { .num_threads(processing_thread_count) .build() else { - log::error!("Failed to create processing thread pool!"); + tracing::error!("Failed to create processing thread pool!"); return; }; @@ -240,7 +241,7 @@ impl CreateSignatures { let previous_worker_thread_count = worker_thread_count(); let upgraded_thread_count = previous_worker_thread_count * 3; if upgraded_thread_count > previous_worker_thread_count { - log::info!( + tracing::info!( "Setting worker thread count to {} for the duration of processing...", upgraded_thread_count ); @@ -253,14 +254,14 @@ impl CreateSignatures { save_warp_file(&project, None, "generated.warp", &warp_file); } Err(e) => { - log::error!("Failed to process project: {}", e); + tracing::error!("Failed to process project: {}", e); } }); let processed_file_count = processor .state() .files_with_state(ProcessingFileState::Processed); - log::info!( + tracing::info!( "Processing {} project files took: {:?}", processed_file_count, start.elapsed() diff --git a/plugins/warp/src/plugin/workflow.rs b/plugins/warp/src/plugin/workflow.rs index e5ce9b7650..a51c739932 100644 --- a/plugins/warp/src/plugin/workflow.rs +++ b/plugins/warp/src/plugin/workflow.rs @@ -15,6 +15,7 @@ use binaryninja::command::Command; use binaryninja::function::Function as BNFunction; use binaryninja::rc::Ref as BNRef; use binaryninja::settings::{QueryOptions, Settings}; +use binaryninja::tracing; use binaryninja::workflow::{activity, Activity, AnalysisContext, Workflow, WorkflowBuilder}; use dashmap::DashSet; use itertools::Itertools; @@ -39,7 +40,7 @@ impl Command for RunMatcher { // Alert the user if we have no actual regions (+1 comes from the synthetic section). let regions = relocatable_regions(&view); if regions.len() <= 1 && view.memory_map().is_activated() { - log::warn!( + tracing::warn!( "No relocatable regions found, for best results please define sections for the binary!" ); } @@ -90,13 +91,15 @@ impl FunctionSet { .workflow() .expect("Function has no workflow"); if function_workflow.contains(GUID_ACTIVITY_NAME) { - log::error!("No function guids in database, please reanalyze the database."); + tracing::error!( + "No function guids in database, please reanalyze the database." + ); } else { - log::error!( - "Activity '{}' is not in workflow '{}', create function guids manually to run matcher...", - GUID_ACTIVITY_NAME, - function_workflow.name() - ) + tracing::error!( + "Activity '{}' is not in workflow '{}', create function guids manually to run matcher...", + GUID_ACTIVITY_NAME, + function_workflow.name() + ) } } return None; @@ -169,7 +172,7 @@ pub fn run_matcher(view: &BinaryView) { .maximum_possible_functions .is_some_and(|max| max < matched_functions.len() as u64) { - log::warn!( + tracing::warn!( "Skipping {}, too many possible functions: {}", guid, matched_functions.len() @@ -244,10 +247,10 @@ pub fn run_matcher(view: &BinaryView) { } if background_task.is_cancelled() { - log::info!("Matcher was cancelled by user, you may run it again by running the 'Run Matcher' command."); + tracing::info!("Matcher was cancelled by user, you may run it again by running the 'Run Matcher' command."); } - log::info!( + tracing::info!( "Function matching took {:.3} seconds and matched {} functions after {} rounds", start.elapsed().as_secs_f64(), matcher_results.len(), @@ -290,12 +293,12 @@ pub fn run_fetcher(view: &BinaryView) { }); if background_task.is_cancelled() { - log::info!( + tracing::info!( "Fetcher was cancelled by user, you may run it again by running the 'Fetch' command." ); } - log::info!("Fetching took {:?}", start.elapsed()); + tracing::info!("Fetching took {:?}", start.elapsed()); background_task.finish(); } diff --git a/plugins/warp/src/processor.rs b/plugins/warp/src/processor.rs index 693f085218..3076ddcade 100644 --- a/plugins/warp/src/processor.rs +++ b/plugins/warp/src/processor.rs @@ -26,6 +26,10 @@ use binaryninja::project::file::ProjectFile; use binaryninja::project::Project; use binaryninja::rc::{Guard, Ref}; +use crate::cache::cached_type_references; +use crate::convert::platform_to_target; +use crate::{build_function, INCLUDE_TAG_ICON, INCLUDE_TAG_NAME}; +use binaryninja::tracing; use warp::chunk::{Chunk, ChunkKind, CompressionType}; use warp::r#type::chunk::TypeChunk; use warp::signature::chunk::SignatureChunk; @@ -33,10 +37,6 @@ use warp::signature::function::Function; use warp::target::Target; use warp::{WarpFile, WarpFileHeader}; -use crate::cache::cached_type_references; -use crate::convert::platform_to_target; -use crate::{build_function, INCLUDE_TAG_ICON, INCLUDE_TAG_NAME}; - /// Ensure we never exceed these many functions per signature chunk. /// /// This was added to fix running into the max table limit on certain files. @@ -538,15 +538,15 @@ impl WarpFileProcessor { Ok(result) => Some(Ok(result)), Err(ProcessingError::Cancelled) => Some(Err(ProcessingError::Cancelled)), Err(ProcessingError::NoPathToProjectFile(path)) => { - log::debug!("Skipping non-pulled project file: {:?}", path); + tracing::debug!("Skipping non-pulled project file: {:?}", path); None } Err(ProcessingError::SkippedFile(path)) => { - log::debug!("Skipping project file: {:?}", path); + tracing::debug!("Skipping project file: {:?}", path); None } Err(e) => { - log::error!("Project file processing error: {:?}", e); + tracing::error!("Project file processing error: {:?}", e); None } }) @@ -615,14 +615,14 @@ impl WarpFileProcessor { .with_extension("bndb"); if file_cache_path.exists() { // TODO: Update analysis and wait option - log::debug!("Analysis database found in cache: {:?}", file_cache_path); + tracing::debug!("Analysis database found in cache: {:?}", file_cache_path); binaryninja::load_with_options( &file_cache_path, self.request_analysis, Some(settings_str), ) } else { - log::debug!("No database found in cache: {:?}", file_cache_path); + tracing::debug!("No database found in cache: {:?}", file_cache_path); binaryninja::load_with_options(&path, self.request_analysis, Some(settings_str)) } } @@ -645,13 +645,13 @@ impl WarpFileProcessor { // TODO: We should also update the cache if analysis has changed! if !view.file().is_database_backed() { // Update the cache. - log::debug!("Saving analysis database to {:?}", file_cache_path); + tracing::debug!("Saving analysis database to {:?}", file_cache_path); if !view.file().create_database(&file_cache_path) { // TODO: We might want to error here... - log::warn!("Failed to save analysis database to {:?}", file_cache_path); + tracing::warn!("Failed to save analysis database to {:?}", file_cache_path); } } else { - log::debug!( + tracing::debug!( "Analysis database unchanged, skipping save to {:?}", file_cache_path ); @@ -699,7 +699,7 @@ impl WarpFileProcessor { // Process all the files. let unmerged_files: Result, _> = files .into_par_iter() - .inspect(|path| log::debug!("Processing file: {:?}", path)) + .inspect(|path| tracing::debug!("Processing file: {:?}", path)) .map(|path| { self.check_cancelled()?; self.process(path) @@ -707,12 +707,12 @@ impl WarpFileProcessor { .filter_map(|res| match res { Ok(result) => Some(Ok(result)), Err(ProcessingError::SkippedFile(path)) => { - log::debug!("Skipping directory file: {:?}", path); + tracing::debug!("Skipping directory file: {:?}", path); None } Err(ProcessingError::Cancelled) => Some(Err(ProcessingError::Cancelled)), Err(e) => { - log::error!("Directory file processing error: {:?}", e); + tracing::error!("Directory file processing error: {:?}", e); None } }) @@ -752,7 +752,7 @@ impl WarpFileProcessor { std::io::copy(&mut entry, &mut output_file).map_err(ProcessingError::FileRead)?; entry_files.insert(output_path); } else { - log::debug!("Skipping already inserted entry: {}", normalized_name); + tracing::debug!("Skipping already inserted entry: {}", normalized_name); } } @@ -765,7 +765,7 @@ impl WarpFileProcessor { // Process all the entries. let unmerged_files: Result, _> = entry_files .into_par_iter() - .inspect(|path| log::debug!("Processing entry: {:?}", path)) + .inspect(|path| tracing::debug!("Processing entry: {:?}", path)) .map(|path| { self.check_cancelled()?; self.process_file(path) @@ -773,12 +773,12 @@ impl WarpFileProcessor { .filter_map(|res| match res { Ok(result) => Some(Ok(result)), Err(ProcessingError::SkippedFile(path)) => { - log::debug!("Skipping archive file: {:?}", path); + tracing::debug!("Skipping archive file: {:?}", path); None } Err(ProcessingError::Cancelled) => Some(Err(ProcessingError::Cancelled)), Err(e) => { - log::error!("Archive file processing error: {:?}", e); + tracing::error!("Archive file processing error: {:?}", e); None } }) diff --git a/plugins/workflow_objc/Cargo.toml b/plugins/workflow_objc/Cargo.toml index 024d9d9a2b..da8ae2c6e9 100644 --- a/plugins/workflow_objc/Cargo.toml +++ b/plugins/workflow_objc/Cargo.toml @@ -13,7 +13,6 @@ demo = [] [dependencies] binaryninja = { workspace = true } binaryninjacore-sys.workspace = true -log = "0.4" dashmap = { version = "6.1", features = ["rayon"]} once_cell = "1.20" thiserror = "2.0" diff --git a/plugins/workflow_objc/src/activities/objc_msg_send_calls.rs b/plugins/workflow_objc/src/activities/objc_msg_send_calls.rs index b39c843c75..860240477c 100644 --- a/plugins/workflow_objc/src/activities/objc_msg_send_calls.rs +++ b/plugins/workflow_objc/src/activities/objc_msg_send_calls.rs @@ -7,6 +7,7 @@ use binaryninja::{ instruction::{InstructionHandler as _, LowLevelILInstruction, LowLevelILInstructionKind}, operation::{CallSsa, Operation}, }, + tracing, variable::PossibleValueSet, workflow::AnalysisContext, }; @@ -53,7 +54,7 @@ pub fn process(ac: &AnalysisContext) -> Result<(), Error> { Ok(true) => function_changed = true, Ok(_) => {} Err(err) => { - log::error!( + tracing::error!( "Error processing instruction at {:#x}: {}", insn.address(), err diff --git a/plugins/workflow_objc/src/activities/objc_msg_send_calls/rewrite_to_direct_call.rs b/plugins/workflow_objc/src/activities/objc_msg_send_calls/rewrite_to_direct_call.rs index 0ddf294561..56c2aa5255 100644 --- a/plugins/workflow_objc/src/activities/objc_msg_send_calls/rewrite_to_direct_call.rs +++ b/plugins/workflow_objc/src/activities/objc_msg_send_calls/rewrite_to_direct_call.rs @@ -4,6 +4,7 @@ use binaryninja::{ function::{LowLevelILFunction, Mutable, NonSSA, SSA}, instruction::{InstructionHandler as _, LowLevelILInstruction, LowLevelILInstructionKind}, }, + tracing, }; use super::MessageSendType; @@ -48,7 +49,7 @@ pub fn process_call( Ok(()) } _ => { - log::error!( + tracing::error!( "Unexpected LLIL operation for objc_msgSend call at {:#x}", insn.address() ); diff --git a/plugins/workflow_objc/src/activities/remove_memory_management.rs b/plugins/workflow_objc/src/activities/remove_memory_management.rs index 3990f01097..fdd766502e 100644 --- a/plugins/workflow_objc/src/activities/remove_memory_management.rs +++ b/plugins/workflow_objc/src/activities/remove_memory_management.rs @@ -11,6 +11,7 @@ use binaryninja::{ lifting::LowLevelILLabel, LowLevelILRegisterKind, }, + tracing, variable::PossibleValueSet, workflow::AnalysisContext, }; @@ -176,7 +177,7 @@ pub fn process(ac: &AnalysisContext) -> Result<(), Error> { Ok(true) => function_changed = true, Ok(_) => {} Err(err) => { - log::error!( + tracing::error!( "Error processing instruction at {:#x}: {}", insn.address(), err diff --git a/plugins/workflow_objc/src/activities/super_init.rs b/plugins/workflow_objc/src/activities/super_init.rs index cfd3ecdc79..1cdf8825e5 100644 --- a/plugins/workflow_objc/src/activities/super_init.rs +++ b/plugins/workflow_objc/src/activities/super_init.rs @@ -10,6 +10,7 @@ use binaryninja::{ MediumLevelILFunction, MediumLevelILLiftedInstruction, MediumLevelILLiftedInstructionKind, }, rc::Ref, + tracing, types::Type, variable::{RegisterValueType, SSAVariable}, workflow::AnalysisContext, @@ -148,7 +149,7 @@ fn return_type_for_super_init(call: &Call, view: &BinaryView) -> Option Option Option src, _ => { // The Swift compiler generates code that conditionally assigns to the receiver field of `objc_super`. - log::debug!( + tracing::debug!( "Unexpected variable definition kind at {:#0x} {:#x?}", super_param_def.address, super_param_def @@ -184,7 +185,7 @@ fn return_type_for_super_init(call: &Call, view: &BinaryView) -> Option src_var, _ => { // The Swift compiler generates code that initializes the `objc_super` variable in more varied ways. - log::debug!( + tracing::debug!( " found non-address-of variable definition of `objc_super` variable at {:#0x} {:?}", super_param_def.address, super_param_def @@ -223,7 +224,7 @@ fn return_type_for_super_init(call: &Call, view: &BinaryView) -> Option Option Option bool { - Logger::new("Plugin.Objective-C") - .with_level(LevelFilter::Debug) - .init(); + binaryninja::tracing_init!("Plugin.Objective-C"); if workflow::register_activities().is_err() { - log::warn!("Failed to register Objective-C workflow"); + tracing::warn!("Failed to register Objective-C workflow"); return false; }; diff --git a/plugins/workflow_objc/src/metadata/global_state.rs b/plugins/workflow_objc/src/metadata/global_state.rs index 6110445169..c6682a5ff3 100644 --- a/plugins/workflow_objc/src/metadata/global_state.rs +++ b/plugins/workflow_objc/src/metadata/global_state.rs @@ -1,10 +1,11 @@ +use binaryninja::file_metadata::SessionId; use binaryninja::{ binary_view::{BinaryView, BinaryViewBase, BinaryViewExt}, file_metadata::FileMetadata, metadata::Metadata, rc::Ref, settings::{QueryOptions, Settings}, - ObjectDestructor, + tracing, ObjectDestructor, }; use dashmap::DashMap; use once_cell::sync::Lazy; @@ -31,8 +32,8 @@ struct SelectorImplementations { sel_to_impl: HashMap>, } -static VIEW_INFOS: Lazy>> = Lazy::new(DashMap::new); -static IGNORED_VIEWS: Lazy> = Lazy::new(DashMap::new); +static VIEW_INFOS: Lazy>> = Lazy::new(DashMap::new); +static IGNORED_VIEWS: Lazy> = Lazy::new(DashMap::new); struct ObjectLifetimeObserver; @@ -69,7 +70,7 @@ impl GlobalState { observer.register(); } - fn id(bv: &BinaryView) -> usize { + fn id(bv: &BinaryView) -> SessionId { bv.file().session_id() } @@ -159,7 +160,7 @@ impl AnalysisInfo { }; let version_meta = meta.get("version")?; if version_meta.get_unsigned_integer()? != 1 { - log::error!( + tracing::error!( "workflow_objc: Unexpected Objective-C metadata version. Expected 1, got {}.", version_meta.get_unsigned_integer()? ); @@ -192,7 +193,7 @@ impl AnalysisInfo { for item in &array { let item = item.get_array()?; if item.len() != 2 { - log::warn!( + tracing::warn!( "Expected selector implementation metadata to have 2 items, found {}", item.len() ); diff --git a/plugins/workflow_objc/src/workflow.rs b/plugins/workflow_objc/src/workflow.rs index 08a3904242..13e3a71e19 100644 --- a/plugins/workflow_objc/src/workflow.rs +++ b/plugins/workflow_objc/src/workflow.rs @@ -1,3 +1,4 @@ +use binaryninja::tracing; use binaryninja::workflow::{activity, Activity, AnalysisContext, Workflow}; use crate::{activities, error::WorkflowRegistrationError}; @@ -15,7 +16,7 @@ fn run( ) -> impl Fn(&AnalysisContext) { move |ac| { if let Err(err) = func(ac) { - log::debug!("Error occurred while running activity: {err:#x?}"); + tracing::debug!("Error occurred while running activity: {err:#x?}"); } } } diff --git a/rust/Cargo.toml b/rust/Cargo.toml index 4856f97b66..2d7aa6a53e 100644 --- a/rust/Cargo.toml +++ b/rust/Cargo.toml @@ -18,14 +18,16 @@ demo = ["no_exports"] core = ["binaryninjacore-sys/core"] [dependencies] -log = { version = "0.4", features = ["std"] } rayon = { version = "1.10", optional = true } -binaryninjacore-sys = { path = "binaryninjacore-sys", default-features = false} +binaryninjacore-sys = { path = "binaryninjacore-sys", default-features = false } thiserror = "2.0" serde = "1.0" serde_derive = "1.0" # Parts of the collaboration and workflow APIs consume and produce JSON. serde_json = "1.0" +# Used for tracing compatible logs +tracing = { version = "0.1", default-features = false, features = ["std"] } +tracing-subscriber = { version = "0.3", default-features = false, features = ["std", "registry", "smallvec", "parking_lot"] } [dev-dependencies] rstest = "0.24" diff --git a/rust/plugin_examples/data_renderer/src/lib.rs b/rust/plugin_examples/data_renderer/src/lib.rs index 178402afc7..97b81f23b3 100644 --- a/rust/plugin_examples/data_renderer/src/lib.rs +++ b/rust/plugin_examples/data_renderer/src/lib.rs @@ -100,9 +100,8 @@ impl CustomDataRenderer for UuidDataRenderer { #[unsafe(no_mangle)] pub unsafe extern "C" fn CorePluginInit() -> bool { // Initialize logging - binaryninja::logger::Logger::new("UUID Data Renderer") - .with_level(log::LevelFilter::Debug) - .init(); + binaryninja::tracing_init!(); + binaryninja::tracing::info!("Core plugin initialized"); // Register data renderer register_data_renderer(UuidDataRenderer {}); diff --git a/rust/src/architecture.rs b/rust/src/architecture.rs index 297fabf8e3..fbd09fd4a0 100644 --- a/rust/src/architecture.rs +++ b/rust/src/architecture.rs @@ -68,32 +68,6 @@ pub use instruction::*; pub use intrinsic::*; pub use register::*; -#[macro_export] -macro_rules! new_id_type { - ($name:ident, $inner_type:ty) => { - #[derive(std::fmt::Debug, Clone, Copy, PartialEq, Eq, Hash, PartialOrd, Ord)] - pub struct $name(pub $inner_type); - - impl From<$inner_type> for $name { - fn from(value: $inner_type) -> Self { - Self(value) - } - } - - impl From<$name> for $inner_type { - fn from(value: $name) -> Self { - value.0 - } - } - - impl std::fmt::Display for $name { - fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { - write!(f, "{}", self.0) - } - } - }; -} - /// The [`Architecture`] trait is the backbone of Binary Ninja's analysis capabilities. It tells the /// core how to interpret the machine code into LLIL, a generic intermediate representation for /// program analysis. @@ -1852,7 +1826,7 @@ where return expr.index.0; } } else { - log::warn!( + tracing::warn!( "unable to unpack flag write op: {:?} with {} operands", op, operands.len() diff --git a/rust/src/architecture/flag.rs b/rust/src/architecture/flag.rs index 7c0f5deb1b..4cbd2dc1fb 100644 --- a/rust/src/architecture/flag.rs +++ b/rust/src/architecture/flag.rs @@ -9,11 +9,11 @@ use std::hash::Hash; pub use binaryninjacore_sys::BNFlagRole as FlagRole; pub use binaryninjacore_sys::BNLowLevelILFlagCondition as FlagCondition; -crate::new_id_type!(FlagId, u32); +new_id_type!(FlagId, u32); // TODO: Make this NonZero? -crate::new_id_type!(FlagWriteId, u32); -crate::new_id_type!(FlagClassId, u32); -crate::new_id_type!(FlagGroupId, u32); +new_id_type!(FlagWriteId, u32); +new_id_type!(FlagClassId, u32); +new_id_type!(FlagGroupId, u32); pub trait Flag: Debug + Sized + Clone + Copy + Hash + Eq { type FlagClass: FlagClass; diff --git a/rust/src/architecture/intrinsic.rs b/rust/src/architecture/intrinsic.rs index 5d9827a13e..a00b1e79e2 100644 --- a/rust/src/architecture/intrinsic.rs +++ b/rust/src/architecture/intrinsic.rs @@ -11,7 +11,7 @@ use std::borrow::Cow; use std::ffi::CStr; use std::fmt::{Debug, Formatter}; -crate::new_id_type!(IntrinsicId, u32); +new_id_type!(IntrinsicId, u32); pub trait Intrinsic: Debug + Sized + Clone + Copy { fn name(&self) -> Cow<'_, str>; diff --git a/rust/src/architecture/register.rs b/rust/src/architecture/register.rs index 1f17c78578..0f76084422 100644 --- a/rust/src/architecture/register.rs +++ b/rust/src/architecture/register.rs @@ -6,7 +6,7 @@ use std::ffi::CStr; use std::fmt::{Debug, Formatter}; use std::hash::Hash; -crate::new_id_type!(RegisterId, u32); +new_id_type!(RegisterId, u32); impl RegisterId { pub fn is_temporary(&self) -> bool { @@ -14,7 +14,7 @@ impl RegisterId { } } -crate::new_id_type!(RegisterStackId, u32); +new_id_type!(RegisterStackId, u32); #[derive(Debug, Copy, Clone, Eq, PartialEq, Hash)] pub enum ImplicitRegisterExtend { diff --git a/rust/src/command.rs b/rust/src/command.rs index eecdf4a8cc..74128e4e1e 100644 --- a/rust/src/command.rs +++ b/rust/src/command.rs @@ -100,42 +100,31 @@ pub fn register_command(name: &str, desc: &str, command: C) { where C: Command, { - ffi_wrap!("Command::action", unsafe { - let cmd = &*(ctxt as *const C); - - debug_assert!(!view.is_null()); - let view = BinaryView { handle: view }; - - cmd.action(&view); - }) + let cmd = unsafe { &*(ctxt as *const C) }; + debug_assert!(!view.is_null()); + let view = BinaryView { handle: view }; + let _span = ffi_span!("Command::action", view); + cmd.action(&view); } extern "C" fn cb_valid(ctxt: *mut c_void, view: *mut BNBinaryView) -> bool where C: Command, { - ffi_wrap!("Command::valid", unsafe { - let cmd = &*(ctxt as *const C); - - debug_assert!(!view.is_null()); - let view = BinaryView { handle: view }; - - cmd.valid(&view) - }) + let cmd = unsafe { &*(ctxt as *const C) }; + debug_assert!(!view.is_null()); + let view = BinaryView { handle: view }; + let _span = ffi_span!("Command::valid", view); + cmd.valid(&view) } let name = name.to_cstr(); let desc = desc.to_cstr(); - - let name_ptr = name.as_ptr(); - let desc_ptr = desc.as_ptr(); - let ctxt = Box::into_raw(Box::new(command)); - unsafe { BNRegisterPluginCommand( - name_ptr, - desc_ptr, + name.as_ptr(), + desc.as_ptr(), Some(cb_action::), Some(cb_valid::), ctxt as *mut _, @@ -197,42 +186,31 @@ pub fn register_command_for_address(name: &str, desc: &str, c where C: AddressCommand, { - ffi_wrap!("AddressCommand::action", unsafe { - let cmd = &*(ctxt as *const C); - - debug_assert!(!view.is_null()); - let view = BinaryView { handle: view }; - - cmd.action(&view, addr); - }) + let cmd = unsafe { &*(ctxt as *const C) }; + debug_assert!(!view.is_null()); + let view = BinaryView { handle: view }; + let _span = ffi_span!("AddressCommand::action", view); + cmd.action(&view, addr); } extern "C" fn cb_valid(ctxt: *mut c_void, view: *mut BNBinaryView, addr: u64) -> bool where C: AddressCommand, { - ffi_wrap!("AddressCommand::valid", unsafe { - let cmd = &*(ctxt as *const C); - - debug_assert!(!view.is_null()); - let view = BinaryView { handle: view }; - - cmd.valid(&view, addr) - }) + let cmd = unsafe { &*(ctxt as *const C) }; + debug_assert!(!view.is_null()); + let view = BinaryView { handle: view }; + let _span = ffi_span!("AddressCommand::valid", view); + cmd.valid(&view, addr) } let name = name.to_cstr(); let desc = desc.to_cstr(); - - let name_ptr = name.as_ptr(); - let desc_ptr = desc.as_ptr(); - let ctxt = Box::into_raw(Box::new(command)); - unsafe { BNRegisterPluginCommandForAddress( - name_ptr, - desc_ptr, + name.as_ptr(), + desc.as_ptr(), Some(cb_action::), Some(cb_valid::), ctxt as *mut _, @@ -298,14 +276,11 @@ where where C: RangeCommand, { - ffi_wrap!("RangeCommand::action", unsafe { - let cmd = &*(ctxt as *const C); - - debug_assert!(!view.is_null()); - let view = BinaryView { handle: view }; - - cmd.action(&view, addr..addr.wrapping_add(len)); - }) + let cmd = unsafe { &*(ctxt as *const C) }; + debug_assert!(!view.is_null()); + let view = BinaryView { handle: view }; + let _span = ffi_span!("RangeCommand::action", view); + cmd.action(&view, addr..addr.wrapping_add(len)); } extern "C" fn cb_valid( @@ -317,28 +292,20 @@ where where C: RangeCommand, { - ffi_wrap!("RangeCommand::valid", unsafe { - let cmd = &*(ctxt as *const C); - - debug_assert!(!view.is_null()); - let view = BinaryView { handle: view }; - - cmd.valid(&view, addr..addr.wrapping_add(len)) - }) + let cmd = unsafe { &*(ctxt as *const C) }; + debug_assert!(!view.is_null()); + let view = BinaryView { handle: view }; + let _span = ffi_span!("RangeCommand::valid", view); + cmd.valid(&view, addr..addr.wrapping_add(len)) } let name = name.to_cstr(); let desc = desc.to_cstr(); - - let name_ptr = name.as_ptr(); - let desc_ptr = desc.as_ptr(); - let ctxt = Box::into_raw(Box::new(command)); - unsafe { BNRegisterPluginCommandForRange( - name_ptr, - desc_ptr, + name.as_ptr(), + desc.as_ptr(), Some(cb_action::), Some(cb_valid::), ctxt as *mut _, @@ -401,17 +368,13 @@ pub fn register_command_for_function(name: &str, desc: &str, where C: FunctionCommand, { - ffi_wrap!("FunctionCommand::action", unsafe { - let cmd = &*(ctxt as *const C); - - debug_assert!(!view.is_null()); - let view = BinaryView { handle: view }; - - debug_assert!(!func.is_null()); - let func = Function { handle: func }; - - cmd.action(&view, &func); - }) + let cmd = unsafe { &*(ctxt as *const C) }; + debug_assert!(!view.is_null()); + let view = BinaryView { handle: view }; + debug_assert!(!func.is_null()); + let func = Function { handle: func }; + let _span = ffi_span!("FunctionCommand::action", view); + cmd.action(&view, &func); } extern "C" fn cb_valid( @@ -422,31 +385,22 @@ pub fn register_command_for_function(name: &str, desc: &str, where C: FunctionCommand, { - ffi_wrap!("FunctionCommand::valid", unsafe { - let cmd = &*(ctxt as *const C); - - debug_assert!(!view.is_null()); - let view = BinaryView { handle: view }; - - debug_assert!(!func.is_null()); - let func = Function { handle: func }; - - cmd.valid(&view, &func) - }) + let cmd = unsafe { &*(ctxt as *const C) }; + debug_assert!(!view.is_null()); + let view = BinaryView { handle: view }; + debug_assert!(!func.is_null()); + let func = Function { handle: func }; + let _span = ffi_span!("FunctionCommand::valid", view); + cmd.valid(&view, &func) } let name = name.to_cstr(); let desc = desc.to_cstr(); - - let name_ptr = name.as_ptr(); - let desc_ptr = desc.as_ptr(); - let ctxt = Box::into_raw(Box::new(command)); - unsafe { BNRegisterPluginCommandForFunction( - name_ptr, - desc_ptr, + name.as_ptr(), + desc.as_ptr(), Some(cb_action::), Some(cb_valid::), ctxt as *mut _, @@ -464,42 +418,29 @@ pub fn register_command_for_project(name: &str, desc: &str, c where C: ProjectCommand, { - ffi_wrap!("Command::action", unsafe { - let cmd = &*(ctxt as *const C); - - let handle = NonNull::new(project).expect("project handle is null"); - let project = Project { handle }; - - cmd.action(&project); - }) + let cmd = unsafe { &*(ctxt as *const C) }; + let handle = NonNull::new(project).expect("project handle is null"); + let project = Project { handle }; + cmd.action(&project); } extern "C" fn cb_valid(ctxt: *mut c_void, project: *mut BNProject) -> bool where C: ProjectCommand, { - ffi_wrap!("Command::valid", unsafe { - let cmd = &*(ctxt as *const C); - - let handle = NonNull::new(project).expect("project handle is null"); - let project = Project { handle }; - - cmd.valid(&project) - }) + let cmd = unsafe { &*(ctxt as *const C) }; + let handle = NonNull::new(project).expect("project handle is null"); + let project = Project { handle }; + cmd.valid(&project) } let name = name.to_cstr(); let desc = desc.to_cstr(); - - let name_ptr = name.as_ptr(); - let desc_ptr = desc.as_ptr(); - let ctxt = Box::into_raw(Box::new(command)); - unsafe { BNRegisterPluginCommandForProject( - name_ptr, - desc_ptr, + name.as_ptr(), + desc.as_ptr(), Some(cb_action::), Some(cb_valid::), ctxt as *mut _, diff --git a/rust/src/custom_binary_view.rs b/rust/src/custom_binary_view.rs index a0b1df2142..12fd12a6f2 100644 --- a/rust/src/custom_binary_view.rs +++ b/rust/src/custom_binary_view.rs @@ -96,10 +96,7 @@ where // to the core -- we're transferring ownership of the Ref here Ref::into_raw(bv.handle).handle } - Err(_) => { - log::error!("CustomBinaryViewType::create_custom_view returned Err"); - ptr::null_mut() - } + Err(_) => ptr::null_mut(), } }) } @@ -124,10 +121,7 @@ where // to the core -- we're transferring ownership of the Ref here Ref::into_raw(bv.handle).handle } - Err(_) => { - log::error!("CustomBinaryViewType::parse returned Err"); - ptr::null_mut() - } + Err(_) => ptr::null_mut(), } }) } @@ -173,7 +167,6 @@ where // be one since view types live for the life of the process) as // MaybeUninit suppress the Drop implementation of it's inner type drop(Box::from_raw(ctxt)); - panic!("bvt registration failed"); } @@ -303,10 +296,7 @@ pub trait BinaryViewTypeExt: BinaryViewTypeBase { let handle = unsafe { BNCreateBinaryViewOfType(self.as_ref().handle, data.handle) }; if handle.is_null() { - log::error!( - "failed to create BinaryView of BinaryViewType '{}'", - self.name() - ); + // TODO: Proper Result, possibly introduce BNSetError to populate. return Err(()); } @@ -317,10 +307,7 @@ pub trait BinaryViewTypeExt: BinaryViewTypeBase { let handle = unsafe { BNParseBinaryViewOfType(self.as_ref().handle, data.handle) }; if handle.is_null() { - log::error!( - "failed to parse BinaryView of BinaryViewType '{}'", - self.name() - ); + // TODO: Proper Result, possibly introduce BNSetError to populate. return Err(()); } @@ -503,7 +490,7 @@ impl<'a, T: CustomBinaryViewType> CustomViewBuilder<'a, T> { if let Some(bv) = file.view_of_type(&view_name) { // while it seems to work most of the time, you can get really unlucky - // if the a free of the existing view of the same type kicks off while + // if a free of the existing view of the same type kicks off while // BNCreateBinaryViewOfType is still running. the freeObject callback // will run for the new view before we've even finished initializing, // and that's all she wrote. @@ -511,7 +498,7 @@ impl<'a, T: CustomBinaryViewType> CustomViewBuilder<'a, T> { // even if we deal with it gracefully in cb_free_object, // BNCreateBinaryViewOfType is still going to crash, so we're just // going to try and stop this from happening in the first place. - log::error!( + tracing::error!( "attempt to create duplicate view of type '{}' (existing: {:?})", view_name, bv.handle @@ -572,12 +559,14 @@ impl<'a, T: CustomBinaryViewType> CustomViewBuilder<'a, T> { true } Err(_) => { - log::error!("CustomBinaryView::init failed; custom view returned Err"); + tracing::error!( + "CustomBinaryView::init failed; custom view returned Err" + ); false } }, Err(_) => { - log::error!("CustomBinaryView::new failed; custom view returned Err"); + tracing::error!("CustomBinaryView::new failed; custom view returned Err"); false } } @@ -607,7 +596,7 @@ impl<'a, T: CustomBinaryViewType> CustomViewBuilder<'a, T> { // // if we're here, it's too late to do anything about it, though we can at least not // run the destructor on the custom view since that memory is uninitialized. - log::error!( + tracing::error!( "BinaryViewBase::freeObject called on partially initialized object! crash imminent!" ); } else if matches!( @@ -626,7 +615,7 @@ impl<'a, T: CustomBinaryViewType> CustomViewBuilder<'a, T> { // // we can't do anything to prevent this, but we can at least have the crash // not be our fault. - log::error!("BinaryViewBase::freeObject called on leaked/never initialized custom view!"); + tracing::error!("BinaryViewBase::freeObject called on leaked/never initialized custom view!"); } }) } @@ -884,20 +873,11 @@ impl<'a, T: CustomBinaryViewType> CustomViewBuilder<'a, T> { parent.handle, &mut bn_obj, ); - - if res.is_null() { - // TODO not sure when this can even happen, let alone what we're supposed to do about - // it. cb_init isn't normally called until later, and cb_free_object definitely won't - // have been called, so we'd at least be on the hook for freeing that stuff... - // probably. - // - // no idea how to force this to fail so I can test this, so just going to do the - // reasonable thing and panic. - panic!("failed to create custom binary view!"); - } - + assert!( + !res.is_null(), + "BNCreateCustomBinaryView cannot return null" + ); (*ctxt).raw_handle = res; - Ok(CustomView { handle: BinaryView::ref_from_raw(res), _builder: PhantomData, diff --git a/rust/src/ffi.rs b/rust/src/ffi.rs index 6b56407f1c..7acba51459 100644 --- a/rust/src/ffi.rs +++ b/rust/src/ffi.rs @@ -20,7 +20,7 @@ macro_rules! ffi_wrap { use std::process; panic::catch_unwind(|| $b).unwrap_or_else(|_| { - log::error!("ffi callback caught panic: {}", $n); + tracing::error!("ffi callback caught panic: {}", $n); process::abort() }) }}; @@ -30,3 +30,41 @@ pub(crate) fn time_from_bn(timestamp: u64) -> SystemTime { let m = Duration::from_secs(timestamp); UNIX_EPOCH + m } + +#[macro_export] +macro_rules! ffi_span { + ($name:expr, $bv:expr) => {{ + use $crate::binary_view::BinaryViewExt; + #[allow(unused_imports)] + use $crate::file_metadata::FileMetadata; + tracing::info_span!($name, session_id = $bv.file().session_id().0).entered() + }}; + ($name:expr) => { + tracing::info_span!($name).entered() + }; +} + +macro_rules! new_id_type { + ($name:ident, $inner_type:ty) => { + #[derive(std::fmt::Debug, Clone, Copy, PartialEq, Eq, Hash, PartialOrd, Ord)] + pub struct $name(pub $inner_type); + + impl From<$inner_type> for $name { + fn from(value: $inner_type) -> Self { + Self(value) + } + } + + impl From<$name> for $inner_type { + fn from(value: $name) -> Self { + value.0 + } + } + + impl std::fmt::Display for $name { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!(f, "{}", self.0) + } + } + }; +} diff --git a/rust/src/file_accessor.rs b/rust/src/file_accessor.rs index 2ba7938ffb..a708a00d51 100644 --- a/rust/src/file_accessor.rs +++ b/rust/src/file_accessor.rs @@ -46,7 +46,6 @@ impl FileAccessor { let dest = unsafe { slice::from_raw_parts_mut(dest as *mut u8, len) }; if f.seek(SeekFrom::Start(offset)).is_err() { - log::debug!("Failed to seek to offset {:x}", offset); 0 } else { f.read(dest).unwrap_or(0) diff --git a/rust/src/file_metadata.rs b/rust/src/file_metadata.rs index dc9d36ff85..1f2d6c7544 100644 --- a/rust/src/file_metadata.rs +++ b/rust/src/file_metadata.rs @@ -16,15 +16,7 @@ use crate::binary_view::BinaryView; use crate::database::Database; use crate::rc::*; use crate::string::*; -use binaryninjacore_sys::{ - BNBeginUndoActions, BNCloseFile, BNCommitUndoActions, BNCreateDatabase, BNCreateFileMetadata, - BNFileMetadata, BNFileMetadataGetSessionId, BNForgetUndoActions, BNFreeFileMetadata, - BNGetCurrentOffset, BNGetCurrentView, BNGetExistingViews, BNGetFileMetadataDatabase, - BNGetFileViewOfType, BNGetFilename, BNGetProjectFile, BNIsAnalysisChanged, - BNIsBackedByDatabase, BNIsFileModified, BNMarkFileModified, BNMarkFileSaved, BNNavigate, - BNNewFileReference, BNOpenDatabaseForConfiguration, BNOpenExistingDatabase, BNRedo, - BNRevertUndoActions, BNSaveAutoSnapshot, BNSetFilename, BNUndo, -}; +use binaryninjacore_sys::*; use binaryninjacore_sys::{BNCreateDatabaseWithProgress, BNOpenExistingDatabaseWithProgress}; use std::ffi::c_void; use std::fmt::{Debug, Display, Formatter}; @@ -34,6 +26,8 @@ use crate::progress::ProgressCallback; use crate::project::file::ProjectFile; use std::ptr::{self, NonNull}; +new_id_type!(SessionId, usize); + #[derive(PartialEq, Eq, Hash)] pub struct FileMetadata { pub(crate) handle: *mut BNFileMetadata, @@ -64,8 +58,9 @@ impl FileMetadata { } } - pub fn session_id(&self) -> usize { - unsafe { BNFileMetadataGetSessionId(self.handle) } + pub fn session_id(&self) -> SessionId { + let raw = unsafe { BNFileMetadataGetSessionId(self.handle) }; + SessionId(raw) } pub fn filename(&self) -> String { diff --git a/rust/src/lib.rs b/rust/src/lib.rs index ba654f099d..be84eea925 100644 --- a/rust/src/lib.rs +++ b/rust/src/lib.rs @@ -82,6 +82,7 @@ pub mod string; pub mod symbol; pub mod tags; pub mod template_simplifier; +pub mod tracing; pub mod types; pub mod update; pub mod variable; diff --git a/rust/src/logger.rs b/rust/src/logger.rs index 2a6db18814..f77cb52cc6 100644 --- a/rust/src/logger.rs +++ b/rust/src/logger.rs @@ -1,114 +1,105 @@ -#![allow(clippy::needless_doctest_main)] - -//! To use logging in your script, do something like: -//! -//! ```no-test -//! use binaryninja::logger::Logger; -//! use log::{info, LevelFilter}; -//! -//! fn main() { -//! Logger::default().init(); -//! info!("The logger has been initialized!"); -//! // Your code here... -//! } -//! ``` -//! -//! or -//! -//!```no-test -//! use binaryninja::logger::Logger; -//! use log::{info, LevelFilter}; -//! -//! #[no_mangle] -//! pub extern "C" fn CorePluginInit() -> bool { -//! Logger::new("My Plugin").with_level(LevelFilter::Warn).init(); -//! info!("The logger has been initialized!"); -//! // Your code here... -//! true -//! } -//! ``` - -pub use binaryninjacore_sys::BNLogLevel as Level; -use binaryninjacore_sys::{ - BNFreeLogger, BNLogCreateLogger, BNLogListener, BNLogger, BNLoggerGetName, - BNLoggerGetSessionId, BNNewLoggerReference, BNUpdateLogListeners, -}; +// TODO: Describe this in terms of the core Logger, but refer to tracing for how to capture rust logs. +use crate::file_metadata::SessionId; use crate::rc::{Ref, RefCountable}; use crate::string::{raw_to_string, BnString, IntoCStr}; -use log; -use log::LevelFilter; +use binaryninjacore_sys::*; use std::ffi::CString; use std::os::raw::{c_char, c_void}; use std::ptr::NonNull; -const LOGGER_DEFAULT_SESSION_ID: usize = 0; +// Used for documentation purposes. +#[allow(unused_imports)] +use crate::binary_view::BinaryView; + +pub use binaryninjacore_sys::BNLogLevel as BnLogLevel; + +pub const LOGGER_DEFAULT_SESSION_ID: SessionId = SessionId(0); + +/// Send a global log message **to the core**. +/// +/// Prefer [`bn_log_with_session`] when a [`SessionId`] is available, via binary views file metadata. +pub fn bn_log(logger: &str, level: BnLogLevel, msg: &str) { + bn_log_with_session(LOGGER_DEFAULT_SESSION_ID, logger, level, msg); +} + +/// Send a session-scoped log message **to the core**. +/// +/// The [`SessionId`] is how you attribute the log to a specific [`BinaryView`]. Without passing +/// a session, logs will be shown in the UI globally, which you should not do if you can avoid it. +pub fn bn_log_with_session(session_id: SessionId, logger: &str, level: BnLogLevel, msg: &str) { + if let Ok(msg) = CString::new(msg) { + let logger_name = logger.to_cstr(); + unsafe { + BNLog( + session_id.0, + level, + logger_name.as_ptr(), + 0, + c"%s".as_ptr(), + msg.as_ptr(), + ) + } + } +} #[derive(Debug, PartialEq, Eq, PartialOrd, Ord, Hash)] pub struct Logger { handle: NonNull, - level: LevelFilter, } impl Logger { + /// Create a logger with the given name. pub fn new(name: &str) -> Ref { Self::new_with_session(name, LOGGER_DEFAULT_SESSION_ID) } - pub fn new_with_session(name: &str, session_id: usize) -> Ref { + /// Create a logger scoped with the specific [`SessionId`], hiding the logs when the session + /// is not active in the UI. + /// + /// # Example + /// + /// Typically, you will want to retrieve the [`SessionId`] from the [`BinaryView`] file metadata + /// + /// ```no_run + /// # use binaryninja::binary_view::BinaryView; + /// # use binaryninja::logger::Logger; + /// # let bv: BinaryView = todo!(); + /// Logger::new_with_session("MyLogger", bv.file().session_id()); + /// ``` + pub fn new_with_session(name: &str, session_id: SessionId) -> Ref { let name_raw = CString::new(name).unwrap(); - let handle = unsafe { BNLogCreateLogger(name_raw.as_ptr(), session_id) }; + let handle = unsafe { BNLogCreateLogger(name_raw.as_ptr(), session_id.0) }; unsafe { Ref::new(Logger { handle: NonNull::new(handle).unwrap(), - level: LevelFilter::Debug, }) } } + /// Name of the logger instance. pub fn name(&self) -> String { unsafe { BnString::into_string(BNLoggerGetName(self.handle.as_ptr())) } } - pub fn session_id(&self) -> usize { - unsafe { BNLoggerGetSessionId(self.handle.as_ptr()) } - } -} - -// NOTE: Due to the ref counted core object, we must impl on the ref counted object. -// NOTE: If we wanted to be less specific than we would need Ref to impl Copy -impl Ref { - pub fn with_level(mut self, level: LevelFilter) -> Ref { - self.level = level; - self - } - - /// Calling this will set the global logger to `self`. + /// The [`SessionId`] associated with the logger instance. /// - /// NOTE: There is no guarantee that logs will be sent to BinaryNinja as another log sink - /// may have already been initialized beforehand. - pub fn init(self) { - log::set_max_level(self.level); - let _ = log::set_boxed_logger(Box::new(self)); + /// The [`SessionId`] is how the core knows to associate logs with a specific opened binary, + /// hiding other sessions (binaries) logs when not active in the UI. + pub fn session_id(&self) -> Option { + let raw = unsafe { BNLoggerGetSessionId(self.handle.as_ptr()) }; + match raw { + 0 => None, + _ => Some(SessionId(raw)), + } } - /// Send a log to the logger instance, if you instead want to use the `log` crate and its facilities, - /// you should use [`Ref::init`] to initialize the `log` compatible logger. - pub fn send_log(&self, level: Level, msg: &str) { - use binaryninjacore_sys::BNLog; - if let Ok(msg) = CString::new(msg) { - let logger_name = self.name().to_cstr(); - unsafe { - BNLog( - self.session_id(), - level, - logger_name.as_ptr(), - 0, - c"%s".as_ptr(), - msg.as_ptr(), - ) - } - } + /// Send a log to the logger instance. + /// + /// If you do not have a [`Logger`] you may call [`bn_log`] or [`bn_log_with_session`]. + pub fn log(&self, level: BnLogLevel, msg: &str) { + let session = self.session_id().unwrap_or(LOGGER_DEFAULT_SESSION_ID); + bn_log_with_session(session, &self.name(), level, msg); } } @@ -130,7 +121,6 @@ unsafe impl RefCountable for Logger { unsafe fn inc_ref(logger: &Self) -> Ref { Ref::new(Self { handle: NonNull::new(BNNewLoggerReference(logger.handle.as_ptr())).unwrap(), - level: logger.level, }) } @@ -139,44 +129,67 @@ unsafe impl RefCountable for Logger { } } -impl log::Log for Ref { - fn enabled(&self, _metadata: &log::Metadata) -> bool { - true - } +unsafe impl Send for Logger {} +unsafe impl Sync for Logger {} - fn log(&self, record: &log::Record) { - use self::Level::*; - let level = match record.level() { - log::Level::Error => ErrorLog, - log::Level::Warn => WarningLog, - log::Level::Info => InfoLog, - log::Level::Debug | log::Level::Trace => DebugLog, - }; - self.send_log(level, &format!("{}", record.args())); +/// Register a [`LogListener`] that will receive log messages **from the core**. +/// +/// This is typically used in headless usage. It can also be used to temporarily log core +/// messages to something like a file while some analysis is occurring, once the [`LogGuard`] is +/// dropped, the listener will be unregistered. +pub fn register_log_listener(listener: L) -> LogGuard { + use binaryninjacore_sys::BNRegisterLogListener; + + let raw = Box::into_raw(Box::new(listener)); + let mut bn_obj = BNLogListener { + context: raw as *mut _, + log: Some(cb_log::), + logWithStackTrace: Some(cb_log_with_stack_trace::), + close: Some(cb_close::), + getLogLevel: Some(cb_level::), + }; + + unsafe { + BNRegisterLogListener(&mut bn_obj); + BNUpdateLogListeners(); } - fn flush(&self) {} + LogGuard { ctxt: raw } } -unsafe impl Send for Logger {} -unsafe impl Sync for Logger {} +/// The context associated with a log message received from the core as part of a [`LogListener`]. +#[derive(Debug, Clone, PartialEq, Eq, PartialOrd, Ord, Hash)] +pub struct LogContext<'a> { + /// The optional [`SessionId`] associated with the log message. + /// + /// This will correspond with a [`BinaryView`] file's [`SessionId`]. + pub session_id: Option, + /// The thread ID associated with the log message. + pub thread_id: usize, + /// The optional stack trace associated with the log message. + pub stack_trace: Option<&'a str>, + /// The target [`Logger`] for the log message. + pub logger_name: &'a str, +} +/// The trait implemented by objects that wish to receive log messages from the core. +/// +/// Currently, we supply one implementation of this trait called [`crate::tracing::TracingLogListener`] +/// which will send the core logs to the registered tracing subscriber. pub trait LogListener: 'static + Sync { - fn log(&self, session: usize, level: Level, msg: &str, logger_name: &str, tid: usize); - fn level(&self) -> Level; - fn close(&self) {} + /// Called when a log message is received from the core. + /// + /// Logs will only be sent that are above the desired [`LogListener::level`]. + fn log(&self, ctx: &LogContext, lvl: BnLogLevel, msg: &str); - fn log_with_stack_trace( - &self, - session: usize, - level: Level, - _stack_trace: &str, - msg: &str, - logger_name: &str, - tid: usize, - ) { - self.log(session, level, msg, logger_name, tid); - } + /// The desired minimum log level, any logs below this level will be ignored. + /// + /// For example, returning [`BnLogLevel::InfoLog`] will result in [`BnLogLevel::DebugLog`] logs + /// being ignored by this listener. + fn level(&self) -> BnLogLevel; + + /// Called when the listener is unregistered. + fn close(&self) {} } pub struct LogGuard { @@ -204,30 +217,10 @@ impl Drop for LogGuard { } } -pub fn register_listener(listener: L) -> LogGuard { - use binaryninjacore_sys::BNRegisterLogListener; - - let raw = Box::into_raw(Box::new(listener)); - let mut bn_obj = BNLogListener { - context: raw as *mut _, - log: Some(cb_log::), - logWithStackTrace: Some(cb_log_with_stack_trace::), - close: Some(cb_close::), - getLogLevel: Some(cb_level::), - }; - - unsafe { - BNRegisterLogListener(&mut bn_obj); - BNUpdateLogListeners(); - } - - LogGuard { ctxt: raw } -} - extern "C" fn cb_log( ctxt: *mut c_void, session: usize, - level: Level, + level: BnLogLevel, msg: *const c_char, logger_name: *const c_char, tid: usize, @@ -238,14 +231,24 @@ extern "C" fn cb_log( let listener = &*(ctxt as *const L); let msg_str = raw_to_string(msg).unwrap(); let logger_name_str = raw_to_string(logger_name).unwrap(); - listener.log(session, level, &msg_str, &logger_name_str, tid); + let session_id = match session { + 0 => None, + _ => Some(SessionId(session)), + }; + let ctx = LogContext { + session_id, + thread_id: tid, + stack_trace: None, + logger_name: &logger_name_str, + }; + listener.log(&ctx, level, &msg_str); }) } extern "C" fn cb_log_with_stack_trace( ctxt: *mut c_void, session: usize, - level: Level, + level: BnLogLevel, stack_trace: *const c_char, msg: *const c_char, logger_name: *const c_char, @@ -258,14 +261,17 @@ extern "C" fn cb_log_with_stack_trace( let stack_trace_str = raw_to_string(stack_trace).unwrap(); let msg_str = raw_to_string(msg).unwrap(); let logger_name_str = raw_to_string(logger_name).unwrap(); - listener.log_with_stack_trace( - session, - level, - &stack_trace_str, - &msg_str, - &logger_name_str, - tid, - ); + let session_id = match session { + 0 => None, + _ => Some(SessionId(session)), + }; + let ctx = LogContext { + session_id, + thread_id: tid, + stack_trace: Some(&stack_trace_str), + logger_name: &logger_name_str, + }; + listener.log(&ctx, level, &msg_str); }) } @@ -279,7 +285,7 @@ where }) } -extern "C" fn cb_level(ctxt: *mut c_void) -> Level +extern "C" fn cb_level(ctxt: *mut c_void) -> BnLogLevel where L: LogListener, { diff --git a/rust/src/low_level_il/expression.rs b/rust/src/low_level_il/expression.rs index de69e1120e..70131ae552 100644 --- a/rust/src/low_level_il/expression.rs +++ b/rust/src/low_level_il/expression.rs @@ -536,8 +536,7 @@ where } _ => { - // #[cfg(debug_assertions)] - log::error!( + tracing::error!( "Got unexpected operation {:?} in value expr at 0x{:x}", op.operation, op.address diff --git a/rust/src/low_level_il/lifting.rs b/rust/src/low_level_il/lifting.rs index 91a3b53e4a..727f5a3c6e 100644 --- a/rust/src/low_level_il/lifting.rs +++ b/rust/src/low_level_il/lifting.rs @@ -533,7 +533,7 @@ macro_rules! prim_int_lifter { }; if !is_safe { - log::error!("il @ {:x} attempted to lift constant 0x{:x} as {} byte expr (won't fit!)", + tracing::error!("il @ {:x} attempted to lift constant 0x{:x} as {} byte expr (won't fit!)", il.current_address(), val, size); } } @@ -660,7 +660,7 @@ impl<'a> LiftableLowLevelILWithSize<'a> for LowLevelILExpression<'a, Mutable, No use crate::low_level_il::ExpressionHandler; if let Some(expr_size) = expr.kind().size() { if expr_size != _size { - log::warn!( + tracing::warn!( "il @ {:x} attempted to lift {} byte expression as {} bytes", il.current_address(), expr_size, @@ -788,7 +788,7 @@ impl<'a> LiftableLowLevelILWithSize<'a> for ExpressionBuilder<'a, ValueExpr> { use binaryninjacore_sys::BNLowLevelILOperation::{LLIL_UNIMPL, LLIL_UNIMPL_MEM}; if expr.size != _size && ![LLIL_UNIMPL, LLIL_UNIMPL_MEM].contains(&expr.op) { - log::warn!( + tracing::warn!( "il @ {:x} attempted to lift {} byte expression builder as {} bytes", il.current_address(), expr.size, diff --git a/rust/src/low_level_il/operation.rs b/rust/src/low_level_il/operation.rs index 2f081b5e2b..de6e15745f 100644 --- a/rust/src/low_level_il/operation.rs +++ b/rust/src/low_level_il/operation.rs @@ -1745,7 +1745,7 @@ where }; if !is_safe { - log::error!( + tracing::error!( "il expr @ {:x} contains constant 0x{:x} as {} byte value (doesn't fit!)", self.op.address, self.op.operands[0], @@ -1810,7 +1810,7 @@ where } _ => { // Log error for unexpected sizes - log::error!( + tracing::error!( "il expr @ {:x} has invalid float size {} (expected 4 or 8 bytes)", self.op.address, self.op.size @@ -1858,7 +1858,7 @@ where }; if !is_safe { - log::error!( + tracing::error!( "il expr @ {:x} contains extern 0x{:x} as {} byte value (doesn't fit!)", self.op.address, self.op.operands[0], diff --git a/rust/src/tracing.rs b/rust/src/tracing.rs new file mode 100644 index 0000000000..3782887778 --- /dev/null +++ b/rust/src/tracing.rs @@ -0,0 +1,303 @@ +// TODO: Add top level docs here. + +use crate::file_metadata::SessionId; +use crate::logger::{ + bn_log_with_session, BnLogLevel, LogContext, LogListener, LOGGER_DEFAULT_SESSION_ID, +}; +use tracing::{Event, Id, Level, Subscriber}; +use tracing_subscriber::prelude::*; + +// Re-export specific things to make it easy for the user +pub use tracing::{debug, error, info, trace, warn}; +use tracing_subscriber::layer::Context; +use tracing_subscriber::registry::LookupSpan; +use tracing_subscriber::Layer; + +/// Helper macro to initialize the [`BinaryNinjaLayer`] tracing layer for plugins. +/// +/// Maps the current crate name to the provided display name and enables target formatting. +/// Use [`init_with_layer`] if you intend on registering a [`BinaryNinjaLayer`] with non-default values. +/// +/// ## Note for Plugins +/// +/// This should **only** be called once, at the start of plugins. +/// +/// ```no_run +/// #[unsafe(no_mangle)] +/// pub unsafe extern "C" fn CorePluginInit() -> bool { +/// binaryninja::tracing_init!("MyPlugin"); +/// binaryninja::tracing::info!("Core plugin initialized"); +/// true +/// } +/// ``` +/// +/// ## Note for Headless +/// +/// This should **never** be called if you are running headlessly and as you will likely be +/// registering a [`LogListener`], which will possibly round-trip back to tracing logs and deadlock +/// the program. +#[macro_export] +macro_rules! tracing_init { + () => { + let layer = $crate::tracing::BinaryNinjaLayer::default(); + $crate::tracing::init_with_layer(layer); + }; + ($name:expr) => { + let layer = $crate::tracing::BinaryNinjaLayer::default() + .with_target_mapping(env!("CARGO_CRATE_NAME"), $name); + $crate::tracing::init_with_layer(layer); + }; +} + +/// Initialize the core tracing subscriber with the given [`BinaryNinjaLayer`]. Collects and sends logs +/// to the core. +pub fn init_with_layer(layer: BinaryNinjaLayer) { + let subscriber = tracing_subscriber::registry().with(layer); + let _ = tracing::subscriber::set_global_default(subscriber); +} + +/// Subscribes to all spans and events emitted by `tracing` and forwards them to the core logging API. +#[derive(Clone)] +pub struct BinaryNinjaLayer { + /// Rewrite mappings for the default target. + /// + /// # Example + /// + /// Given the target "my_crate::commands::analyze" and the mapping ("my_crate", "MyPlugin") the + /// target will be rewritten to "MyPlugin::commands::analyze", assuming no other rewrites occur. + pub target_mappings: Vec<(String, String)>, + /// Whether the default target should be formatted to be displayed in the "common" logger name + /// format for Binary Ninja. This formatting does _not_ apply to targets explicitly set, rather + /// than only when a target is omitted. + /// + /// # Example + /// + /// Given the target "my_crate::commands::analyze" the target will be rewritten to "MyCrate.Commands.Analyze". + pub formatted_target: bool, +} + +impl BinaryNinjaLayer { + pub fn new() -> Self { + Self::default() + } + + /// Add a target mapping which will rewrite the `old` in the default target to `new`. + /// + /// This is typically done when you have a plugin name that is verbose, and you wish to display + /// it in the logs as something else. + pub fn with_target_mapping(mut self, old: &str, new: &str) -> Self { + self.target_mappings + .push((old.to_string(), new.to_string())); + self + } + + /// Whether formatting of the default target should be applied when sending logs to the core. + pub fn with_formatted_target(mut self, formatted: bool) -> Self { + self.formatted_target = formatted; + self + } +} + +impl BinaryNinjaLayer { + /// Rewrite the target so that the logger name will be displayed in the common Binary Ninja format. + pub fn rewrite_target(&self, mut target: String) -> String { + // Formats the target such that "my_crate::commands::analyze" becomes "MyPlugin.Commands.Analyze". + let format_target = |target: &str| -> String { + let mut result = String::with_capacity(target.len()); + let mut capitalize_next = true; + let mut chars = target.chars().peekable(); + + while let Some(c) = chars.next() { + match c { + ':' if chars.peek() == Some(&':') => { + // Found "::", consume the second ':' and treat as a dot separator + chars.next(); + result.push('.'); + capitalize_next = true; + } + '.' => { + result.push('.'); + capitalize_next = true; + } + '_' => { + // Treat underscore as a separator: strip it and capitalize next + capitalize_next = true; + } + _ if capitalize_next => { + for upper in c.to_uppercase() { + result.push(upper); + } + capitalize_next = false; + } + _ => { + result.push(c); + } + } + } + + result + }; + + // Perform "my_crate" -> "MyPlugin" rewrite rules. + for (old, new) in &self.target_mappings { + target = target.replace(old, new); + } + + if self.formatted_target { + target = format_target(&target); + } + + target + } +} + +impl Default for BinaryNinjaLayer { + fn default() -> Self { + Self { + target_mappings: vec![("binaryninja".to_string(), "Binary Ninja".to_string())], + formatted_target: true, + } + } +} + +impl Layer for BinaryNinjaLayer +where + S: Subscriber + for<'a> LookupSpan<'a>, +{ + fn on_new_span(&self, attrs: &tracing::span::Attributes<'_>, id: &Id, ctx: Context<'_, S>) { + let span = ctx.span(id).expect("Span not found in registry"); + + let mut visitor = BnFieldVisitor::default(); + attrs.record(&mut visitor); + + // If this span has a session_id, store it in the span's extensions + if let Some(session_id) = visitor.session_id { + span.extensions_mut().insert(session_id); + } + } + + fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { + let level = match *event.metadata().level() { + Level::ERROR => BnLogLevel::ErrorLog, + Level::WARN => BnLogLevel::WarningLog, + Level::INFO => BnLogLevel::InfoLog, + Level::DEBUG | Level::TRACE => BnLogLevel::DebugLog, + }; + + let mut visitor = BnFieldVisitor::default(); + event.record(&mut visitor); + + // Walk up the span tree to find the session id. + // NOTE: Inserted by `BinaryNinjaLayer::on_new_span`. + let session_from_scope = || { + ctx.event_scope(event).and_then(|scope| { + scope + .from_root() + .find_map(|span| span.extensions().get::().copied()) + }) + }; + + // First we check the log event itself, then we check the scope context. + let session_id = visitor + .session_id + .or_else(session_from_scope) + .unwrap_or(LOGGER_DEFAULT_SESSION_ID); + + let mut logger_name = event.metadata().target().to_string(); + // Target is not overridden, we should try and apply mapping. + if let Some(module_path) = event.metadata().module_path() { + if module_path == logger_name { + // Target is the default module path, rewrite it into a more friendly format. + logger_name = self.rewrite_target(logger_name); + } + } + + bn_log_with_session(session_id, &logger_name, level, &visitor.message); + } +} + +#[derive(Default)] +struct BnFieldVisitor { + message: String, + session_id: Option, +} + +impl tracing::field::Visit for BnFieldVisitor { + fn record_i64(&mut self, field: &tracing::field::Field, value: i64) { + if field.name() == "session_id" { + self.session_id = Some(SessionId(value as usize)); + } + } + + fn record_u64(&mut self, field: &tracing::field::Field, value: u64) { + if field.name() == "session_id" { + self.session_id = Some(SessionId(value as usize)); + } + } + + fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) { + if field.name() == "message" { + use std::fmt::Write; + let _ = write!(self.message, "{:?}", value); + } + } +} + +/// A [`LogListener`] that forwards logs to the registered [`Subscriber`]. +/// +/// This should **never** be registered if the [`BinaryNinjaLayer`] is active. The [`BinaryNinjaLayer`] +/// will consume our events we send in this log listener and send them back to the core, causing a +/// never-ending cycle of sending and receiving the same logs. +/// +/// Typically, you will register this listener for headless applications. You can technically use this +/// in a plugin, but it is likely that you are sending tracing logs to the core, in which case you will +/// run into the problem above. +/// +/// ```no_run +/// use binaryninja::tracing::TracingLogListener; +/// use binaryninja::logger::{register_log_listener, BnLogLevel, bn_log}; +/// use binaryninja::headless::Session; +/// +/// pub fn main() { +/// // Register our tracing subscriber, this will send tracing events to stdout. +/// tracing_subscriber::fmt::init(); +/// // Register our log listener, this will send logs from the core to our tracing subscriber. +/// let _listener = register_log_listener(TracingLogListener::new(BnLogLevel::DebugLog)); +/// // Should see logs from the core in regard to initialization show up. +/// let _session = Session::new().expect("Failed to create session"); +/// bn_log("Test", BnLogLevel::DebugLog, "Hello, world!"); +/// } +/// ``` +pub struct TracingLogListener { + minimum_level: BnLogLevel, +} + +impl TracingLogListener { + pub fn new(minimum_level: BnLogLevel) -> Self { + Self { minimum_level } + } +} + +impl LogListener for TracingLogListener { + fn log(&self, ctx: &LogContext, level: BnLogLevel, message: &str) { + let session = ctx.session_id.map(|s| s.0); + match level { + BnLogLevel::ErrorLog | BnLogLevel::AlertLog => { + error!(session_id = session, target = %ctx.logger_name, "{}", message) + } + BnLogLevel::WarningLog => { + warn!(session_id = session, target = %ctx.logger_name, "{}", message) + } + BnLogLevel::InfoLog => { + info!(session_id = session, target = %ctx.logger_name, "{}", message) + } + BnLogLevel::DebugLog => { + debug!(session_id = session, target = %ctx.logger_name, "{}", message) + } + }; + } + + fn level(&self) -> BnLogLevel { + self.minimum_level + } +} diff --git a/rust/src/workflow/activity.rs b/rust/src/workflow/activity.rs index a9afc2f107..2e5d6e8026 100644 --- a/rust/src/workflow/activity.rs +++ b/rust/src/workflow/activity.rs @@ -69,7 +69,9 @@ impl Activity { ) { let ctxt = &mut *(ctxt as *mut F); if let Some(analysis) = NonNull::new(analysis) { - ctxt(&AnalysisContext::from_raw(analysis)) + let analysis = AnalysisContext::from_raw(analysis); + let _span = ffi_span!("Activity::action", analysis.view()); + ctxt(&analysis) } } let config = config.as_config(); diff --git a/view/minidump/Cargo.toml b/view/minidump/Cargo.toml index aa1ff40ec0..fed4a61195 100644 --- a/view/minidump/Cargo.toml +++ b/view/minidump/Cargo.toml @@ -10,5 +10,4 @@ crate-type = ["cdylib"] [dependencies] binaryninja.workspace = true binaryninjacore-sys.workspace = true -log = "0.4" minidump = "0.23.0" \ No newline at end of file diff --git a/view/minidump/src/command.rs b/view/minidump/src/command.rs index 81629f556e..2f28b8b598 100644 --- a/view/minidump/src/command.rs +++ b/view/minidump/src/command.rs @@ -1,12 +1,12 @@ use std::str; -use log::{debug, error, info}; use minidump::{Minidump, MinidumpMemoryInfoList}; use binaryninja::binary_view::{BinaryView, BinaryViewBase, BinaryViewExt}; +use binaryninja::tracing; pub fn print_memory_information(bv: &BinaryView) { - debug!("Printing memory information"); + tracing::debug!("Printing memory information"); if let Some(minidump_bv) = bv.parent_view() { if let Some(read_buffer) = minidump_bv.read_buffer(0, minidump_bv.len() as usize) { if let Ok(minidump_obj) = Minidump::read(read_buffer.get_data()) { @@ -15,27 +15,27 @@ pub fn print_memory_information(bv: &BinaryView) { match memory_info_list.print(&mut memory_info_list_writer) { Ok(_) => { if let Ok(memory_info_str) = str::from_utf8(&memory_info_list_writer) { - info!("{memory_info_str}"); + tracing::info!("{memory_info_str}"); } else { - error!("Could not convert the memory information description from minidump into a valid string"); + tracing::error!("Could not convert the memory information description from minidump into a valid string"); } } Err(_) => { - error!("Could not get memory information from minidump"); + tracing::error!("Could not get memory information from minidump"); } } } else { - error!( + tracing::error!( "Could not parse a valid MinidumpMemoryInfoList stream from the minidump" ); } } else { - error!("Could not parse a valid minidump file from the parent binary view's data buffer"); + tracing::error!("Could not parse a valid minidump file from the parent binary view's data buffer"); } } else { - error!("Could not read data from parent binary view"); + tracing::error!("Could not read data from parent binary view"); } } else { - error!("Could not get the parent binary view"); + tracing::error!("Could not get the parent binary view"); } } diff --git a/view/minidump/src/lib.rs b/view/minidump/src/lib.rs index 64aaddd606..00fed601af 100644 --- a/view/minidump/src/lib.rs +++ b/view/minidump/src/lib.rs @@ -1,8 +1,7 @@ use binaryninja::binary_view::BinaryView; use binaryninja::command::{register_command, Command}; use binaryninja::custom_binary_view::register_view_type; -use binaryninja::logger::Logger; -use log::{debug, LevelFilter}; +use binaryninja::tracing; mod command; mod view; @@ -22,14 +21,11 @@ impl Command for PrintMemoryInformationCommand { #[no_mangle] #[allow(non_snake_case)] pub extern "C" fn CorePluginInit() -> bool { - Logger::new("Minidump") - .with_level(LevelFilter::Trace) - .init(); - - debug!("Registering minidump binary view type"); + binaryninja::tracing_init!("Minidump"); + tracing::debug!("Registering minidump binary view type"); register_view_type("Minidump", "Minidump", view::MinidumpBinaryViewType::new); - debug!("Registering minidump plugin commands"); + tracing::debug!("Registering minidump plugin commands"); register_command( "Minidump\\[DEBUG] Print Minidump Memory Information", "Print a human-readable description of the contents of the MinidumpMemoryInfoList stream in the loaded minidump", diff --git a/view/minidump/src/view.rs b/view/minidump/src/view.rs index 413fafa151..32fde030f5 100644 --- a/view/minidump/src/view.rs +++ b/view/minidump/src/view.rs @@ -3,7 +3,6 @@ use std::ops::Range; use binaryninja::section::Section; use binaryninja::segment::{Segment, SegmentFlags}; -use log::{debug, error, info, warn}; use minidump::format::MemoryProtection; use minidump::{ Minidump, MinidumpMemory64List, MinidumpMemoryInfoList, MinidumpMemoryList, MinidumpModuleList, @@ -16,7 +15,7 @@ use binaryninja::custom_binary_view::{ CustomViewBuilder, }; use binaryninja::platform::Platform; -use binaryninja::Endianness; +use binaryninja::{tracing, Endianness}; type BinaryViewResult = binaryninja::binary_view::Result; @@ -66,7 +65,7 @@ impl CustomBinaryViewType for MinidumpBinaryViewType { data: &BinaryView, builder: CustomViewBuilder<'builder, Self>, ) -> BinaryViewResult> { - debug!("Creating MinidumpBinaryView from registered MinidumpBinaryViewType"); + tracing::debug!("Creating MinidumpBinaryView from registered MinidumpBinaryViewType"); let binary_view = builder.create::(data, ()); binary_view @@ -131,7 +130,7 @@ impl MinidumpBinaryView { ) { self.set_default_platform(&platform); } else { - error!( + tracing::error!( "Could not parse valid system information from minidump: could not map system information in MinidumpSystemInfo stream (arch {:?}, endian {:?}, os {:?}) to a known architecture", minidump_system_info.cpu, minidump_obj.endian, @@ -140,7 +139,9 @@ impl MinidumpBinaryView { return Err(()); } } else { - error!("Could not parse system information from minidump: could not find a valid MinidumpSystemInfo stream"); + tracing::error!( + "Could not parse system information from minidump: could not find a valid MinidumpSystemInfo stream" + ); return Err(()); } @@ -153,19 +154,19 @@ impl MinidumpBinaryView { if let Ok(raw_stream) = minidump_obj.get_raw_stream(MinidumpMemory64List::STREAM_TYPE) { if let Ok(base_rva_array) = raw_stream[8..16].try_into() { let base_rva = u64::from_le_bytes(base_rva_array); - debug!("Found BaseRVA value {:#x}", base_rva); + tracing::debug!("Found BaseRVA value {:#x}", base_rva); if let Ok(minidump_memory_list) = minidump_obj.get_stream::() { let mut current_rva = base_rva; for memory_segment in minidump_memory_list.iter() { - debug!( - "Found memory segment at RVA {:#x} with virtual address {:#x} and size {:#x}", - current_rva, - memory_segment.base_address, - memory_segment.size, - ); + tracing::debug!( + "Found memory segment at RVA {:#x} with virtual address {:#x} and size {:#x}", + current_rva, + memory_segment.base_address, + memory_segment.size, + ); segment_data.push(SegmentData::from_addresses_and_size( current_rva, memory_segment.base_address, @@ -175,15 +176,19 @@ impl MinidumpBinaryView { } } } else { - error!("Could not parse BaseRVA value shared by all entries in the MinidumpMemory64List stream") + tracing::error!( + "Could not parse BaseRVA value shared by all entries in the MinidumpMemory64List stream" + ) } } else { - warn!("Could not read memory from minidump: could not find a valid MinidumpMemory64List stream. This minidump may not be a full memory dump. Trying to find partial dump memory from a MinidumpMemoryList now..."); + tracing::warn!( + "Could not read memory from minidump: could not find a valid MinidumpMemory64List stream. This minidump may not be a full memory dump. Trying to find partial dump memory from a MinidumpMemoryList now..." + ); // Memory segments in a regular memory dump (MinidumpMemoryList), // i.e. one that does not include the full process memory data. if let Ok(minidump_memory_list) = minidump_obj.get_stream::() { for memory_segment in minidump_memory_list.by_addr() { - debug!( + tracing::debug!( "Found memory segment at RVA {:#x} with virtual address {:#x} and size {:#x}", memory_segment.desc.memory.rva, memory_segment.base_address, @@ -196,7 +201,9 @@ impl MinidumpBinaryView { )); } } else { - error!("Could not read any memory from minidump: could not find a valid MinidumpMemory64List stream or a valid MinidumpMemoryList stream."); + tracing::error!( + "Could not read any memory from minidump: could not find a valid MinidumpMemory64List stream or a valid MinidumpMemoryList stream." + ); } } @@ -208,7 +215,7 @@ impl MinidumpBinaryView { { for memory_info in minidump_memory_info_list.iter() { if let Some(memory_range) = memory_info.memory_range() { - debug!( + tracing::debug!( "Found memory protection info for memory segment ranging from virtual address {:#x} to {:#x}: {:#?}", memory_range.start, memory_range.end, @@ -235,15 +242,15 @@ impl MinidumpBinaryView { let segment_memory_protection = MinidumpBinaryView::translate_memory_protection(*segment_protection); - info!( + tracing::info!( "Adding memory segment at virtual address {:#x} to {:#x}, from data range {:#x} to {:#x}, with protections readable {}, writable {}, executable {}", - segment.mapped_addr_range.start, - segment.mapped_addr_range.end, - segment.rva_range.start, - segment.rva_range.end, - segment_memory_protection.readable, - segment_memory_protection.writable, - segment_memory_protection.executable, + segment.mapped_addr_range.start, + segment.mapped_addr_range.end, + segment.rva_range.start, + segment.rva_range.end, + segment_memory_protection.readable, + segment_memory_protection.writable, + segment_memory_protection.executable, ); let segment_flags = SegmentFlags::new() @@ -258,7 +265,7 @@ impl MinidumpBinaryView { .flags(segment_flags), ); } else { - error!( + tracing::error!( "Could not find memory protection information for memory segment from {:#x} to {:#x}", segment.mapped_addr_range.start, segment.mapped_addr_range.end, ); @@ -271,7 +278,7 @@ impl MinidumpBinaryView { // Sections can be named, and can span multiple segments. if let Ok(minidump_module_list) = minidump_obj.get_stream::() { for module_info in minidump_module_list.by_addr() { - info!( + tracing::info!( "Found module with name {} at virtual address {:#x} with size {:#x}", module_info.name, module_info.base_address(), @@ -287,10 +294,12 @@ impl MinidumpBinaryView { ); } } else { - warn!("Could not find valid module information in minidump: could not find a valid MinidumpModuleList stream"); + tracing::warn!( + "Could not find valid module information in minidump: could not find a valid MinidumpModuleList stream" + ); } } else { - error!("Could not parse data as minidump"); + tracing::error!("Could not parse data as minidump"); return Err(()); } Ok(()) From 13829cdd6d3767ba79ea6a29fc4bc4fed0130179 Mon Sep 17 00:00:00 2001 From: Mason Reed Date: Thu, 18 Dec 2025 17:14:06 -0500 Subject: [PATCH 2/6] [Rust] Enter more session scoped tracing spans for debug info and binary view callbacks --- Cargo.lock | 150 +++++++++++------- arch/msp430/Cargo.toml | 1 + arch/msp430/src/architecture.rs | 2 +- arch/msp430/src/lift.rs | 2 +- arch/riscv/Cargo.toml | 1 + arch/riscv/src/lib.rs | 1 - plugins/dwarf/dwarf_export/Cargo.toml | 1 + plugins/dwarf/dwarf_export/src/lib.rs | 1 - plugins/dwarf/dwarf_import/Cargo.toml | 1 + plugins/dwarf/dwarf_import/demo/Cargo.toml | 1 + .../dwarf/dwarf_import/src/die_handlers.rs | 1 - .../dwarf/dwarf_import/src/dwarfdebuginfo.rs | 1 - plugins/dwarf/dwarf_import/src/functions.rs | 1 - plugins/dwarf/dwarf_import/src/helpers.rs | 2 +- plugins/dwarf/dwarf_import/src/lib.rs | 1 - plugins/dwarf/dwarf_import/src/types.rs | 1 - plugins/idb_import/Cargo.toml | 1 + plugins/idb_import/src/lib.rs | 1 - plugins/pdb-ng/Cargo.toml | 1 + plugins/pdb-ng/demo/Cargo.toml | 1 + plugins/pdb-ng/src/lib.rs | 63 ++++---- plugins/pdb-ng/src/parser.rs | 11 +- plugins/pdb-ng/src/struct_grouper.rs | 5 +- plugins/pdb-ng/src/type_parser.rs | 9 +- plugins/svd/Cargo.toml | 1 + plugins/svd/demo/Cargo.toml | 1 + plugins/svd/src/lib.rs | 1 - plugins/svd/src/mapper.rs | 1 - plugins/warp/Cargo.toml | 1 + plugins/warp/demo/Cargo.toml | 1 + plugins/warp/src/cache.rs | 2 +- plugins/warp/src/container/disk.rs | 1 - plugins/warp/src/container/network.rs | 1 - plugins/warp/src/container/network/client.rs | 1 - plugins/warp/src/convert/types.rs | 1 - plugins/warp/src/plugin.rs | 2 +- plugins/warp/src/plugin/commit.rs | 1 - plugins/warp/src/plugin/create.rs | 1 - plugins/warp/src/plugin/debug.rs | 2 +- plugins/warp/src/plugin/ffi/container.rs | 1 - plugins/warp/src/plugin/file.rs | 1 - plugins/warp/src/plugin/function.rs | 1 - plugins/warp/src/plugin/load.rs | 1 - plugins/warp/src/plugin/project.rs | 1 - plugins/warp/src/plugin/workflow.rs | 1 - plugins/warp/src/processor.rs | 1 - plugins/workflow_objc/Cargo.toml | 1 + plugins/workflow_objc/demo/Cargo.toml | 2 +- .../src/activities/objc_msg_send_calls.rs | 1 - .../rewrite_to_direct_call.rs | 1 - .../activities/remove_memory_management.rs | 1 - .../src/activities/super_init.rs | 1 - plugins/workflow_objc/src/lib.rs | 2 +- .../src/metadata/global_state.rs | 2 +- plugins/workflow_objc/src/workflow.rs | 1 - rust/Cargo.toml | 6 +- rust/plugin_examples/data_renderer/Cargo.toml | 2 +- rust/plugin_examples/data_renderer/src/lib.rs | 2 +- rust/src/custom_binary_view.rs | 13 +- rust/src/debuginfo.rs | 51 +++--- rust/src/ffi.rs | 6 +- rust/src/logger.rs | 1 + rust/src/tracing.rs | 65 ++++++-- view/minidump/Cargo.toml | 3 +- view/minidump/src/command.rs | 1 - view/minidump/src/lib.rs | 1 - view/minidump/src/view.rs | 2 +- 67 files changed, 253 insertions(+), 197 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index d042ef579c..f9401a8a9d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -135,6 +135,7 @@ dependencies = [ "binaryninja", "binaryninjacore-sys", "msp430-asm", + "tracing", ] [[package]] @@ -145,8 +146,15 @@ dependencies = [ "binaryninjacore-sys", "rayon", "riscv-dis", + "tracing", ] +[[package]] +name = "arrayvec" +version = "0.7.6" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7c02d123df017efcdfbd739ef81735b36c5ba83ec3c59c80a9d7ecc718f92e50" + [[package]] name = "autocfg" version = "1.5.0" @@ -189,6 +197,7 @@ dependencies = [ "tempfile", "thiserror 2.0.12", "tracing", + "tracing-indicatif", "tracing-subscriber", ] @@ -713,6 +722,7 @@ dependencies = [ "binaryninjacore-sys", "gimli", "object 0.32.2", + "tracing", ] [[package]] @@ -728,6 +738,7 @@ dependencies = [ "iset", "object 0.36.7", "regex", + "tracing", ] [[package]] @@ -743,6 +754,7 @@ dependencies = [ "iset", "object 0.36.7", "regex", + "tracing", ] [[package]] @@ -788,29 +800,6 @@ dependencies = [ "cfg-if", ] -[[package]] -name = "env_filter" -version = "0.1.4" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "1bf3c259d255ca70051b30e2e95b5446cdb8949ac4cd22c0d7fd634d89f568e2" -dependencies = [ - "log", - "regex", -] - -[[package]] -name = "env_logger" -version = "0.11.8" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "13c863f0904021b108aa8b2f55046443e6b1ebde8fd4a15c399893aae4fa069f" -dependencies = [ - "anstream", - "anstyle", - "env_filter", - "jiff", - "log", -] - [[package]] name = "equivalent" version = "1.0.2" @@ -839,7 +828,7 @@ version = "0.1.0" dependencies = [ "binaryninja", "binaryninjacore-sys", - "log", + "tracing", "uuid", ] @@ -1107,6 +1096,7 @@ dependencies = [ "binaryninja", "binaryninjacore-sys", "idb-rs", + "tracing", ] [[package]] @@ -1148,6 +1138,7 @@ dependencies = [ "portable-atomic", "unicode-width", "unit-prefix", + "vt100", "web-time", ] @@ -1208,30 +1199,6 @@ version = "1.0.15" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "4a5f13b858c8d314ee3e8f639011f7ccefe71f97f96e50151fb991f267928e2c" -[[package]] -name = "jiff" -version = "0.2.15" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "be1f93b8b1eb69c77f24bbb0afdf66f54b632ee39af40ca21c4365a1d7347e49" -dependencies = [ - "jiff-static", - "log", - "portable-atomic", - "portable-atomic-util", - "serde", -] - -[[package]] -name = "jiff-static" -version = "0.2.15" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "03343451ff899767262ec32146f6d559dd759fdadf42ff0e227c7c48f72594b4" -dependencies = [ - "proc-macro2", - "quote", - "syn", -] - [[package]] name = "jobserver" version = "0.1.33" @@ -1375,6 +1342,7 @@ dependencies = [ "binaryninja", "binaryninjacore-sys", "minidump", + "tracing", ] [[package]] @@ -1436,6 +1404,15 @@ dependencies = [ "minimal-lexical", ] +[[package]] +name = "nu-ansi-term" +version = "0.50.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "7957b9740744892f114936ab4a57b3f487491bbeafaf8083688b16841a4240e5" +dependencies = [ + "windows-sys 0.61.2", +] + [[package]] name = "num-conv" version = "0.1.0" @@ -1649,6 +1626,7 @@ dependencies = [ "itertools 0.14.0", "pdb", "regex", + "tracing", ] [[package]] @@ -1661,6 +1639,7 @@ dependencies = [ "itertools 0.14.0", "pdb", "regex", + "tracing", ] [[package]] @@ -1734,15 +1713,6 @@ version = "1.11.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "f84267b20a16ea918e43c6a88433c2d54fa145c92a811b5b047ccbe153674483" -[[package]] -name = "portable-atomic-util" -version = "0.2.4" -source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d8a2f0d8d040d7848a709caf78912debcc3f33ee4b3cac47d73d1e1069e83507" -dependencies = [ - "portable-atomic", -] - [[package]] name = "powerfmt" version = "0.2.0" @@ -2290,6 +2260,7 @@ dependencies = [ "insta", "serde_json", "svd-parser", + "tracing", ] [[package]] @@ -2301,6 +2272,7 @@ dependencies = [ "insta", "serde_json", "svd-parser", + "tracing", ] [[package]] @@ -2485,6 +2457,30 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7a04e24fab5c89c6a36eb8558c9656f30d81de51dfa4d3b45f26b21d61fa0a6c" dependencies = [ "once_cell", + "valuable", +] + +[[package]] +name = "tracing-indicatif" +version = "0.3.13" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "04d4e11e0e27acef25a47f27e9435355fecdc488867fa2bc90e75b0700d2823d" +dependencies = [ + "indicatif", + "tracing", + "tracing-core", + "tracing-subscriber", +] + +[[package]] +name = "tracing-log" +version = "0.2.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3" +dependencies = [ + "log", + "once_cell", + "tracing-core", ] [[package]] @@ -2493,11 +2489,13 @@ version = "0.3.22" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "2f30143827ddab0d256fd843b7a66d164e9f271cfa0dde49142c5ca0ca291f1e" dependencies = [ + "nu-ansi-term", "parking_lot", "sharded-slab", "smallvec", "thread_local", "tracing-core", + "tracing-log", ] [[package]] @@ -2547,12 +2545,39 @@ dependencies = [ "wasm-bindgen", ] +[[package]] +name = "valuable" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ba73ea9cf16a25df0c8caa16c51acb937d5712a8429db78a3ee29d5dcacd3a65" + [[package]] name = "version_check" version = "0.9.5" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0b928f33d975fc6ad9f86c8f283853ad26bdd5b10b7f1542aa2fa15e2289105a" +[[package]] +name = "vt100" +version = "0.16.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "054ff75fb8fa83e609e685106df4faeffdf3a735d3c74ebce97ec557d5d36fd9" +dependencies = [ + "itoa", + "unicode-width", + "vte", +] + +[[package]] +name = "vte" +version = "0.15.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "a5924018406ce0063cd67f8e008104968b74b563ee1b85dde3ed1f7cb87d3dbd" +dependencies = [ + "arrayvec", + "memchr", +] + [[package]] name = "walkdir" version = "2.5.0" @@ -2595,9 +2620,9 @@ dependencies = [ "binaryninjacore-sys", "clap", "ctrlc", - "env_logger", - "indicatif", - "log", + "tracing", + "tracing-indicatif", + "tracing-subscriber", "warp_ninja", ] @@ -2625,6 +2650,7 @@ dependencies = [ "serde_qs", "tempdir", "thiserror 2.0.12", + "tracing", "uuid", "walkdir", "warp 1.0.1", @@ -2654,6 +2680,7 @@ dependencies = [ "serde_qs", "tempdir", "thiserror 2.0.12", + "tracing", "uuid", "walkdir", "warp 1.0.0", @@ -3035,6 +3062,7 @@ dependencies = [ "dashmap", "once_cell", "thiserror 2.0.12", + "tracing", ] [[package]] @@ -3045,9 +3073,9 @@ dependencies = [ "binaryninjacore-sys", "bstr", "dashmap", - "log", "once_cell", "thiserror 2.0.12", + "tracing", ] [[package]] diff --git a/arch/msp430/Cargo.toml b/arch/msp430/Cargo.toml index 3e0d34fe1b..d5bcc31ee8 100644 --- a/arch/msp430/Cargo.toml +++ b/arch/msp430/Cargo.toml @@ -9,6 +9,7 @@ license = "Apache-2.0" binaryninja.workspace = true binaryninjacore-sys.workspace = true msp430-asm = "^0.2" +tracing = "0.1" [lib] crate-type = ["cdylib"] diff --git a/arch/msp430/src/architecture.rs b/arch/msp430/src/architecture.rs index 996d3c4a96..244c6b071b 100644 --- a/arch/msp430/src/architecture.rs +++ b/arch/msp430/src/architecture.rs @@ -8,7 +8,7 @@ use binaryninja::{ UnusedIntrinsic, UnusedRegisterStack, }, disassembly::{InstructionTextToken, InstructionTextTokenKind}, - tracing, Endianness, + Endianness, }; use msp430_asm::{ diff --git a/arch/msp430/src/lift.rs b/arch/msp430/src/lift.rs index 480b150b65..0630b18bd4 100644 --- a/arch/msp430/src/lift.rs +++ b/arch/msp430/src/lift.rs @@ -2,7 +2,7 @@ use crate::architecture::offset_to_absolute; use crate::flag::{Flag, FlagWrite}; use crate::register::Register; -use binaryninja::{architecture::FlagCondition, low_level_il::lifting::LowLevelILLabel, tracing}; +use binaryninja::{architecture::FlagCondition, low_level_il::lifting::LowLevelILLabel}; use msp430_asm::emulate::Emulated; use msp430_asm::instruction::Instruction; diff --git a/arch/riscv/Cargo.toml b/arch/riscv/Cargo.toml index e247b30167..d5ab661e5e 100644 --- a/arch/riscv/Cargo.toml +++ b/arch/riscv/Cargo.toml @@ -10,6 +10,7 @@ binaryninja.workspace = true binaryninjacore-sys.workspace = true riscv-dis = { path = "disasm" } rayon = { version = "1.0", optional = true } +tracing = "0.1" [features] default = [] diff --git a/arch/riscv/src/lib.rs b/arch/riscv/src/lib.rs index 1ebe7fb442..1f822524d6 100644 --- a/arch/riscv/src/lib.rs +++ b/arch/riscv/src/lib.rs @@ -26,7 +26,6 @@ use binaryninja::{ RelocationType, }, symbol::{Symbol, SymbolType}, - tracing, types::{NameAndType, Type}, }; use std::borrow::Cow; diff --git a/plugins/dwarf/dwarf_export/Cargo.toml b/plugins/dwarf/dwarf_export/Cargo.toml index 81c8a0174b..74cd774ee1 100644 --- a/plugins/dwarf/dwarf_export/Cargo.toml +++ b/plugins/dwarf/dwarf_export/Cargo.toml @@ -12,3 +12,4 @@ binaryninja.workspace = true binaryninjacore-sys.workspace = true gimli = "^0.31" object = { version = "0.32.1", features = ["write"] } +tracing = "0.1" \ No newline at end of file diff --git a/plugins/dwarf/dwarf_export/src/lib.rs b/plugins/dwarf/dwarf_export/src/lib.rs index bc7d3c27e2..284ca34bbf 100644 --- a/plugins/dwarf/dwarf_export/src/lib.rs +++ b/plugins/dwarf/dwarf_export/src/lib.rs @@ -7,7 +7,6 @@ use binaryninja::{ confidence::Conf, rc::Ref, symbol::SymbolType, - tracing, types::{MemberAccess, StructureType, Type, TypeClass}, }; use gimli::{ diff --git a/plugins/dwarf/dwarf_import/Cargo.toml b/plugins/dwarf/dwarf_import/Cargo.toml index f71d4cf43d..d01c60b152 100644 --- a/plugins/dwarf/dwarf_import/Cargo.toml +++ b/plugins/dwarf/dwarf_import/Cargo.toml @@ -20,3 +20,4 @@ cpp_demangle = "0.4.3" regex = "1" indexmap = "2.5.0" object = "0.36" +tracing = "0.1" diff --git a/plugins/dwarf/dwarf_import/demo/Cargo.toml b/plugins/dwarf/dwarf_import/demo/Cargo.toml index 3a5ad601b1..d4418edd46 100644 --- a/plugins/dwarf/dwarf_import/demo/Cargo.toml +++ b/plugins/dwarf/dwarf_import/demo/Cargo.toml @@ -21,3 +21,4 @@ cpp_demangle = "0.4.3" regex = "1" indexmap = "2.5.0" object = "0.36" +tracing = "0.1" \ No newline at end of file diff --git a/plugins/dwarf/dwarf_import/src/die_handlers.rs b/plugins/dwarf/dwarf_import/src/die_handlers.rs index 7f038a5a7a..fb4277b77b 100644 --- a/plugins/dwarf/dwarf_import/src/die_handlers.rs +++ b/plugins/dwarf/dwarf_import/src/die_handlers.rs @@ -18,7 +18,6 @@ use crate::{helpers::*, ReaderType}; use binaryninja::{ rc::*, - tracing, types::{EnumerationBuilder, FunctionParameter, ReferenceType, Type, TypeBuilder}, }; diff --git a/plugins/dwarf/dwarf_import/src/dwarfdebuginfo.rs b/plugins/dwarf/dwarf_import/src/dwarfdebuginfo.rs index 51888afc5b..a5f0c1386c 100644 --- a/plugins/dwarf/dwarf_import/src/dwarfdebuginfo.rs +++ b/plugins/dwarf/dwarf_import/src/dwarfdebuginfo.rs @@ -25,7 +25,6 @@ use binaryninja::{ rc::*, symbol::SymbolType, template_simplifier::simplify_str_to_fqn, - tracing, types::{FunctionParameter, Type}, variable::NamedVariableWithType, }; diff --git a/plugins/dwarf/dwarf_import/src/functions.rs b/plugins/dwarf/dwarf_import/src/functions.rs index a699c02b71..3752e6f1e6 100644 --- a/plugins/dwarf/dwarf_import/src/functions.rs +++ b/plugins/dwarf/dwarf_import/src/functions.rs @@ -19,7 +19,6 @@ use crate::types::get_type; use crate::{helpers::*, ReaderType}; use binaryninja::template_simplifier::simplify_str_to_str; -use binaryninja::tracing; use cpp_demangle::DemangleOptions; use gimli::{constants, AttributeValue, DebuggingInformationEntry, Dwarf, Operation, Unit}; use regex::Regex; diff --git a/plugins/dwarf/dwarf_import/src/helpers.rs b/plugins/dwarf/dwarf_import/src/helpers.rs index 78802f3446..5bc543a0bf 100644 --- a/plugins/dwarf/dwarf_import/src/helpers.rs +++ b/plugins/dwarf/dwarf_import/src/helpers.rs @@ -18,12 +18,12 @@ use std::{str::FromStr, sync::mpsc}; use crate::{DebugInfoBuilderContext, ReaderType}; use binaryninja::binary_view::BinaryViewBase; +use binaryninja::Endianness; use binaryninja::{ binary_view::{BinaryView, BinaryViewExt}, download::{DownloadInstanceInputOutputCallbacks, DownloadProvider}, settings::Settings, }; -use binaryninja::{tracing, Endianness}; use gimli::Dwarf; use gimli::{ constants, Attribute, AttributeValue, diff --git a/plugins/dwarf/dwarf_import/src/lib.rs b/plugins/dwarf/dwarf_import/src/lib.rs index 50cc85284c..193f3b339a 100644 --- a/plugins/dwarf/dwarf_import/src/lib.rs +++ b/plugins/dwarf/dwarf_import/src/lib.rs @@ -34,7 +34,6 @@ use binaryninja::{ debuginfo::{CustomDebugInfoParser, DebugInfo, DebugInfoParser}, settings::Settings, template_simplifier::simplify_str_to_str, - tracing, }; use dwarfreader::create_section_reader_object; diff --git a/plugins/dwarf/dwarf_import/src/types.rs b/plugins/dwarf/dwarf_import/src/types.rs index 9bcfe171f6..8761fa9da9 100644 --- a/plugins/dwarf/dwarf_import/src/types.rs +++ b/plugins/dwarf/dwarf_import/src/types.rs @@ -18,7 +18,6 @@ use crate::{die_handlers::*, ReaderType}; use binaryninja::{ rc::*, - tracing, types::{ BaseStructure, MemberAccess, MemberScope, ReferenceType, StructureBuilder, StructureType, Type, TypeClass, diff --git a/plugins/idb_import/Cargo.toml b/plugins/idb_import/Cargo.toml index 4a958106a4..9ba241d264 100644 --- a/plugins/idb_import/Cargo.toml +++ b/plugins/idb_import/Cargo.toml @@ -13,3 +13,4 @@ anyhow = { version = "1.0.86", features = ["backtrace"] } binaryninja.workspace = true binaryninjacore-sys.workspace = true idb-rs = { git = "https://github.com/Vector35/idb-rs", tag = "0.1.12" } +tracing = "0.1" \ No newline at end of file diff --git a/plugins/idb_import/src/lib.rs b/plugins/idb_import/src/lib.rs index 3564df11cd..f285f554dc 100644 --- a/plugins/idb_import/src/lib.rs +++ b/plugins/idb_import/src/lib.rs @@ -19,7 +19,6 @@ use idb_rs::til::section::TILSection; use idb_rs::til::TypeVariant as TILTypeVariant; use anyhow::{anyhow, Result}; -use binaryninja::tracing; struct IDBDebugInfoParser; impl CustomDebugInfoParser for IDBDebugInfoParser { diff --git a/plugins/pdb-ng/Cargo.toml b/plugins/pdb-ng/Cargo.toml index e77dac5b8e..08776df22b 100644 --- a/plugins/pdb-ng/Cargo.toml +++ b/plugins/pdb-ng/Cargo.toml @@ -14,6 +14,7 @@ binaryninjacore-sys.workspace = true itertools = "0.14" pdb = { git = "https://github.com/Vector35/pdb-rs", rev = "6016177" } regex = "1" +tracing = "0.1" [features] demo = [] \ No newline at end of file diff --git a/plugins/pdb-ng/demo/Cargo.toml b/plugins/pdb-ng/demo/Cargo.toml index bde9b28cd3..590cacca5c 100644 --- a/plugins/pdb-ng/demo/Cargo.toml +++ b/plugins/pdb-ng/demo/Cargo.toml @@ -15,6 +15,7 @@ binaryninjacore-sys.workspace = true itertools = "0.14" pdb = { git = "https://github.com/Vector35/pdb-rs", rev = "6016177" } regex = "1" +tracing = "0.1" [features] demo = [] diff --git a/plugins/pdb-ng/src/lib.rs b/plugins/pdb-ng/src/lib.rs index a21e3e7a83..92aecae475 100644 --- a/plugins/pdb-ng/src/lib.rs +++ b/plugins/pdb-ng/src/lib.rs @@ -28,7 +28,6 @@ use binaryninja::debuginfo::{CustomDebugInfoParser, DebugInfo, DebugInfoParser}; use binaryninja::download::{DownloadInstanceInputOutputCallbacks, DownloadProvider}; use binaryninja::interaction::{MessageBoxButtonResult, MessageBoxButtonSet}; use binaryninja::settings::{QueryOptions, Settings}; -use binaryninja::tracing::{debug, error, info}; use binaryninja::{interaction, user_directory}; use parser::PDBParserInstance; @@ -162,7 +161,7 @@ fn parse_sym_srv(symbol_path: &str, default_store: String) -> Result Result<(bool, Vec)> { if !path.contains("://") { // Local file - info!("Read local file: {}", path); + tracing::info!("Read local file: {}", path); let conts = fs::read(path)?; return Ok((false, conts)); } @@ -182,7 +181,7 @@ fn read_from_sym_store(bv: &BinaryView, path: &str) -> Result<(bool, Vec)> { } }; - info!("GET: {}", path); + tracing::info!("GET: {}", path); let dp = DownloadProvider::try_default().map_err(|_| anyhow!("No default download provider"))?; @@ -397,9 +396,9 @@ impl PDBParser { if info.age != pdb_info.age { if info.age > pdb_info.age { // Have not seen this case, so I'm not sure if this is fatal - info!("PDB age is older than our binary! Loading it anyway, but there may be missing information."); + tracing::info!("PDB age is older than our binary! Loading it anyway, but there may be missing information."); } else { - info!("PDB age is newer than our binary! Loading it anyway, there probably shouldn't be any issues."); + tracing::info!("PDB age is newer than our binary! Loading it anyway, there probably shouldn't be any issues."); } } @@ -424,7 +423,7 @@ impl PDBParser { match fs::create_dir_all(&cab_path) { Ok(_) => true, Err(e) => { - error!("Could not create PDB cache dir: {}", e); + tracing::error!("Could not create PDB cache dir: {}", e); false } } @@ -433,10 +432,10 @@ impl PDBParser { cab_path.push(&info.file_name); match fs::write(&cab_path, conts) { Ok(_) => { - info!("Downloaded to: {}", cab_path.to_string_lossy()); + tracing::info!("Downloaded to: {}", cab_path.to_string_lossy()); } Err(e) => { - error!("Could not write PDB to cache: {}", e) + tracing::error!("Could not write PDB to cache: {}", e) } } } @@ -461,7 +460,7 @@ impl PDBParser { match fs::create_dir_all(&cab_path) { Ok(_) => true, Err(e) => { - error!("Could not create PDB cache dir: {}", e); + tracing::error!("Could not create PDB cache dir: {}", e); false } } @@ -470,16 +469,19 @@ impl PDBParser { cab_path.push(&info.file_name); match fs::write(&cab_path, conts) { Ok(_) => { - info!("Downloaded to: {}", cab_path.to_string_lossy()); + tracing::info!( + "Downloaded to: {}", + cab_path.to_string_lossy() + ); } Err(e) => { - error!("Could not write PDB to cache: {}", e) + tracing::error!("Could not write PDB to cache: {}", e) } } } } } - Err(e) => error!("Could not get local cache for writing: {}", e), + Err(e) => tracing::error!("Could not get local cache for writing: {}", e), } } } else { @@ -512,11 +514,11 @@ impl PDBParser { let mut inst = match PDBParserInstance::new(debug_info, view, pdb) { Ok(inst) => { - info!("Loaded PDB, parsing..."); + tracing::info!("Loaded PDB, parsing..."); inst } Err(e) => { - error!("Could not open PDB: {}", e); + tracing::error!("Could not open PDB: {}", e); return Err(e); } }; @@ -524,11 +526,11 @@ impl PDBParser { (*progress)(cur, max).map_err(|_| anyhow!("Cancelled")) })) { Ok(()) => { - info!("Parsed pdb"); + tracing::info!("Parsed pdb"); Ok(()) } Err(e) => { - error!("Could not parse PDB: {}", e); + tracing::error!("Could not parse PDB: {}", e); if e.to_string() == "Todo" { Ok(()) } else { @@ -563,7 +565,7 @@ impl CustomDebugInfoParser for PDBParser { Ok(_) => return true, Err(e) if e.to_string() == "Cancelled" => return false, Err(_) => { - error!("Chosen PDB file failed to load"); + tracing::error!("Chosen PDB file failed to load"); return false; } } @@ -587,12 +589,12 @@ impl CustomDebugInfoParser for PDBParser { { Ok(_) => return true, Err(e) if e.to_string() == "Cancelled" => return false, - Err(e) => debug!("Skipping, {}", e.to_string()), + Err(e) => tracing::debug!("Skipping, {}", e.to_string()), } } Ok(None) => {} e => { - error!("Error searching symbol store {}: {:?}", store, e) + tracing::error!("Error searching symbol store {}: {:?}", store, e) } } } @@ -607,10 +609,10 @@ impl CustomDebugInfoParser for PDBParser { { Ok(_) => return true, Err(e) if e.to_string() == "Cancelled" => return false, - Err(e) => debug!("Skipping, {}", e.to_string()), + Err(e) => tracing::debug!("Skipping, {}", e.to_string()), }, Err(e) if e.to_string() == "Cancelled" => return false, - Err(e) => debug!("Could not read pdb: {}", e.to_string()), + Err(e) => tracing::debug!("Could not read pdb: {}", e.to_string()), } } @@ -625,10 +627,10 @@ impl CustomDebugInfoParser for PDBParser { { Ok(_) => return true, Err(e) if e.to_string() == "Cancelled" => return false, - Err(e) => debug!("Skipping, {}", e.to_string()), + Err(e) => tracing::debug!("Skipping, {}", e.to_string()), }, Err(e) if e.to_string() == "Cancelled" => return false, - Err(e) => debug!("Could not read pdb: {}", e.to_string()), + Err(e) => tracing::debug!("Could not read pdb: {}", e.to_string()), } } @@ -651,11 +653,11 @@ impl CustomDebugInfoParser for PDBParser { ) { Ok(_) => return true, Err(e) if e.to_string() == "Cancelled" => return false, - Err(e) => debug!("Skipping, {}", e.to_string()), + Err(e) => tracing::debug!("Skipping, {}", e.to_string()), }, Err(e) if e.to_string() == "Cancelled" => return false, Err(e) => { - debug!("Could not read pdb: {}", e.to_string()) + tracing::debug!("Could not read pdb: {}", e.to_string()) } } } @@ -671,13 +673,14 @@ impl CustomDebugInfoParser for PDBParser { { Ok(_) => return true, Err(e) if e.to_string() == "Cancelled" => return false, - Err(e) => debug!("Skipping, {}", e.to_string()), + Err(e) => tracing::debug!("Skipping, {}", e.to_string()), } } Ok(None) => {} - e => error!( + e => tracing::error!( "Error searching local symbol store {}: {:?}", - local_store_path, e + local_store_path, + e ), } } @@ -693,12 +696,12 @@ impl CustomDebugInfoParser for PDBParser { match self.load_from_file(&conts, debug_info, view, &progress, true, true) { Ok(_) => return true, Err(e) if e.to_string() == "Cancelled" => return false, - Err(e) => debug!("Skipping, {}", e.to_string()), + Err(e) => tracing::debug!("Skipping, {}", e.to_string()), } } Ok(None) => {} e => { - error!("Error searching remote symbol server {}: {:?}", server, e) + tracing::error!("Error searching remote symbol server {}: {:?}", server, e) } } } diff --git a/plugins/pdb-ng/src/parser.rs b/plugins/pdb-ng/src/parser.rs index 90f7fc0648..eef933f313 100644 --- a/plugins/pdb-ng/src/parser.rs +++ b/plugins/pdb-ng/src/parser.rs @@ -30,7 +30,6 @@ use binaryninja::debuginfo::{DebugFunctionInfo, DebugInfo}; use binaryninja::platform::Platform; use binaryninja::rc::Ref; use binaryninja::settings::{QueryOptions, Settings}; -use binaryninja::tracing::{debug, info}; use binaryninja::types::{ EnumerationBuilder, NamedTypeReference, NamedTypeReferenceClass, QualifiedName, StructureBuilder, StructureType, Type, TypeClass, @@ -172,7 +171,7 @@ impl<'a, S: Source<'a> + 'a> PDBParserInstance<'a, S> { .add_type(&name.to_string(), ty.as_ref(), &[]); // TODO : Components } - info!( + tracing::info!( "PDB found {} types (before resolving NTRs)", self.named_types.len() ); @@ -198,9 +197,9 @@ impl<'a, S: Source<'a> + 'a> PDBParserInstance<'a, S> { )?; } - info!("PDB found {} types", self.named_types.len()); - info!("PDB found {} data variables", symbols.len()); - info!("PDB found {} functions", functions.len()); + tracing::info!("PDB found {} types", self.named_types.len()); + tracing::info!("PDB found {} data variables", symbols.len()); + tracing::info!("PDB found {} functions", functions.len()); let allow_void = self.settings.get_bool_with_opts( "pdb.features.allowVoidGlobals", @@ -462,7 +461,7 @@ impl<'a, S: Source<'a> + 'a> PDBParserInstance<'a, S> { if *debug_pdb { let space = "\t".repeat(self.type_stack.len()) + &"\t".repeat(self.symbol_stack.len()); let msg = format!("{}", msg()); - debug!( + tracing::debug!( "{}{}", space, msg.replace("\n", &("\n".to_string() + &space)) diff --git a/plugins/pdb-ng/src/struct_grouper.rs b/plugins/pdb-ng/src/struct_grouper.rs index 62f7119813..5e32e874fc 100644 --- a/plugins/pdb-ng/src/struct_grouper.rs +++ b/plugins/pdb-ng/src/struct_grouper.rs @@ -15,7 +15,6 @@ use crate::type_parser::ParsedMember; use anyhow::{anyhow, Result}; use binaryninja::confidence::{Conf, MAX_CONFIDENCE}; -use binaryninja::tracing::{debug, warn}; use binaryninja::types::{MemberAccess, MemberScope, StructureBuilder, StructureType, Type}; use std::cmp::Ordering; use std::env; @@ -358,7 +357,7 @@ pub fn group_structure( apply_groups(members, structure, groups, 0); } Err(e) => { - warn!("{} Could not resolve structure groups: {}", name, e); + tracing::warn!("{} Could not resolve structure groups: {}", name, e); for member in members { match (member.bitfield_position, member.bitfield_size) { (Some(bit_pos), bit_width) => { @@ -1189,6 +1188,6 @@ fn test_bool_modifier() { fn log D, D: Display>(msg: F) { // println!("{}", msg()); if env::var("BN_DEBUG_PDB").is_ok() { - debug!("{}", msg()); + tracing::debug!("{}", msg()); } } diff --git a/plugins/pdb-ng/src/type_parser.rs b/plugins/pdb-ng/src/type_parser.rs index 3490dfc032..f8d03d8ffc 100644 --- a/plugins/pdb-ng/src/type_parser.rs +++ b/plugins/pdb-ng/src/type_parser.rs @@ -24,7 +24,6 @@ use binaryninja::calling_convention::CoreCallingConvention; use binaryninja::confidence::{Conf, MAX_CONFIDENCE}; use binaryninja::platform::Platform; use binaryninja::rc::Ref; -use binaryninja::tracing::warn; use binaryninja::types::{ BaseStructure, EnumerationBuilder, EnumerationMember, FunctionParameter, MemberAccess, MemberScope, NamedTypeReference, NamedTypeReferenceClass, QualifiedName, StructureBuilder, @@ -556,7 +555,7 @@ impl<'a, S: Source<'a> + 'a> PDBParserInstance<'a, S> { if let Some(_old) = self.named_types.insert(name.clone(), parsed.clone()) { - warn!("Found two types both named `{}`, only one will be used.", name); + tracing::warn!("Found two types both named `{}`, only one will be used.", name); } } } @@ -570,7 +569,7 @@ impl<'a, S: Source<'a> + 'a> PDBParserInstance<'a, S> { } } Err(UnimplementedTypeKind(k)) if k != 0 => { - warn!("Not parsing unimplemented type {}: kind {:x?}", ty, k); + tracing::warn!("Not parsing unimplemented type {}: kind {:x?}", ty, k); } Err(e) => { self.log(|| format!("Could not parse type: {}: {}", ty, e)); @@ -922,7 +921,7 @@ impl<'a, S: Source<'a> + 'a> PDBParserInstance<'a, S> { *base_offset, base_type.width(), )); - warn!( + tracing::warn!( "Class `{}` uses virtual inheritance. Type information may be inaccurate.", self.namespace_stack .items @@ -935,7 +934,7 @@ impl<'a, S: Source<'a> + 'a> PDBParserInstance<'a, S> { } if bases.len() > 1 { - warn!( + tracing::warn!( "Class `{}` has multiple base classes. Type information may be inaccurate.", self.namespace_stack .items diff --git a/plugins/svd/Cargo.toml b/plugins/svd/Cargo.toml index cd36858580..e4cdc5d88c 100644 --- a/plugins/svd/Cargo.toml +++ b/plugins/svd/Cargo.toml @@ -12,6 +12,7 @@ binaryninja.workspace = true binaryninjacore-sys.workspace = true svd-parser = { version = "0.14.8", features = ["expand"] } serde_json = "1.0" +tracing = "0.1" [dev-dependencies] insta = { version = "1.42", features = ["yaml"] } diff --git a/plugins/svd/demo/Cargo.toml b/plugins/svd/demo/Cargo.toml index 811f7d08bb..b714757403 100644 --- a/plugins/svd/demo/Cargo.toml +++ b/plugins/svd/demo/Cargo.toml @@ -13,6 +13,7 @@ binaryninja = { workspace = true, features = ["demo"]} binaryninjacore-sys.workspace = true svd-parser = { version = "0.14.8", features = ["expand"] } serde_json = "1.0" +tracing = "0.1" [dev-dependencies] insta = { version = "1.42", features = ["yaml"] } diff --git a/plugins/svd/src/lib.rs b/plugins/svd/src/lib.rs index 396a9447b1..6ada01f9fb 100644 --- a/plugins/svd/src/lib.rs +++ b/plugins/svd/src/lib.rs @@ -6,7 +6,6 @@ use crate::settings::LoadSettings; use binaryninja::binary_view::{BinaryView, BinaryViewBase, BinaryViewExt}; use binaryninja::command::Command; use binaryninja::interaction::{Form, FormInputField}; -use binaryninja::tracing; use binaryninja::workflow::{activity, Activity, AnalysisContext, Workflow}; use std::path::PathBuf; use svd_parser::ValidateLevel; diff --git a/plugins/svd/src/mapper.rs b/plugins/svd/src/mapper.rs index 2c09eb954d..8f4abe47b3 100644 --- a/plugins/svd/src/mapper.rs +++ b/plugins/svd/src/mapper.rs @@ -6,7 +6,6 @@ use binaryninja::rc::Ref; use binaryninja::section::{SectionBuilder, Semantics}; use binaryninja::segment::{SegmentBuilder, SegmentFlags}; use binaryninja::symbol::{SymbolBuilder, SymbolType}; -use binaryninja::tracing; use binaryninja::types::{ BaseStructure, EnumerationBuilder, MemberAccess, MemberScope, NamedTypeReference, NamedTypeReferenceClass, StructureBuilder, StructureMember, Type, TypeBuilder, diff --git a/plugins/warp/Cargo.toml b/plugins/warp/Cargo.toml index 79f7632f10..3a623e0ab4 100644 --- a/plugins/warp/Cargo.toml +++ b/plugins/warp/Cargo.toml @@ -11,6 +11,7 @@ crate-type = ["lib", "cdylib"] demo = [] [dependencies] +tracing = "0.1" binaryninja = { workspace = true, features = ["rayon"] } binaryninjacore-sys.workspace = true warp = { git = "https://github.com/Vector35/warp/", tag = "1.0.1" } diff --git a/plugins/warp/demo/Cargo.toml b/plugins/warp/demo/Cargo.toml index 5066448301..662b41319a 100644 --- a/plugins/warp/demo/Cargo.toml +++ b/plugins/warp/demo/Cargo.toml @@ -12,6 +12,7 @@ path = "../src/lib.rs" demo = [] [dependencies] +tracing = "0.1" binaryninja = { workspace = true, features = ["rayon", "demo"] } binaryninjacore-sys.workspace = true warp = { git = "https://github.com/Vector35/warp/", tag = "1.0.0" } diff --git a/plugins/warp/src/cache.rs b/plugins/warp/src/cache.rs index 30c7487c0d..41aab42345 100644 --- a/plugins/warp/src/cache.rs +++ b/plugins/warp/src/cache.rs @@ -11,7 +11,7 @@ use binaryninja::binary_view::{BinaryView, BinaryViewExt}; use binaryninja::function::Function as BNFunction; use binaryninja::rc::Guard; use binaryninja::rc::Ref as BNRef; -use binaryninja::{tracing, ObjectDestructor}; +use binaryninja::ObjectDestructor; use std::hash::{DefaultHasher, Hash, Hasher}; pub fn register_cache_destructor() { diff --git a/plugins/warp/src/container/disk.rs b/plugins/warp/src/container/disk.rs index 5e4a56139b..6e296ea10f 100644 --- a/plugins/warp/src/container/disk.rs +++ b/plugins/warp/src/container/disk.rs @@ -1,7 +1,6 @@ use crate::container::{ Container, ContainerError, ContainerResult, SourceId, SourcePath, SourceTag, }; -use binaryninja::tracing; use std::collections::{HashMap, HashSet}; use std::fmt::{Debug, Display, Formatter}; use std::hash::{Hash, Hasher}; diff --git a/plugins/warp/src/container/network.rs b/plugins/warp/src/container/network.rs index 0908b103f1..0ba515f9d9 100644 --- a/plugins/warp/src/container/network.rs +++ b/plugins/warp/src/container/network.rs @@ -3,7 +3,6 @@ use crate::container::{ Container, ContainerError, ContainerResult, ContainerSearchQuery, ContainerSearchResponse, SourceId, SourcePath, SourceTag, }; -use binaryninja::tracing; use directories::ProjectDirs; use std::collections::{HashMap, HashSet}; use std::fmt::{Debug, Display, Formatter}; diff --git a/plugins/warp/src/container/network/client.rs b/plugins/warp/src/container/network/client.rs index d3c94d1a73..0b772dcc44 100644 --- a/plugins/warp/src/container/network/client.rs +++ b/plugins/warp/src/container/network/client.rs @@ -5,7 +5,6 @@ use crate::container::{ }; use base64::Engine; use binaryninja::download::DownloadProvider; -use binaryninja::tracing; use serde::Deserialize; use serde_json::json; use std::collections::HashMap; diff --git a/plugins/warp/src/convert/types.rs b/plugins/warp/src/convert/types.rs index 227df2eac7..8421eb5eff 100644 --- a/plugins/warp/src/convert/types.rs +++ b/plugins/warp/src/convert/types.rs @@ -6,7 +6,6 @@ use binaryninja::calling_convention::CoreCallingConvention as BNCallingConventio use binaryninja::confidence::Conf as BNConf; use binaryninja::confidence::MAX_CONFIDENCE; use binaryninja::rc::Ref as BNRef; -use binaryninja::tracing; use binaryninja::types::BaseStructure as BNBaseStructure; use binaryninja::types::EnumerationBuilder as BNEnumerationBuilder; use binaryninja::types::FunctionParameter as BNFunctionParameter; diff --git a/plugins/warp/src/plugin.rs b/plugins/warp/src/plugin.rs index dec62c2f0f..cb527fffa7 100644 --- a/plugins/warp/src/plugin.rs +++ b/plugins/warp/src/plugin.rs @@ -12,8 +12,8 @@ use binaryninja::background_task::BackgroundTask; use binaryninja::command::{ register_command, register_command_for_function, register_command_for_project, }; +use binaryninja::is_ui_enabled; use binaryninja::settings::{QueryOptions, Settings}; -use binaryninja::{is_ui_enabled, tracing}; mod commit; mod create; diff --git a/plugins/warp/src/plugin/commit.rs b/plugins/warp/src/plugin/commit.rs index 56a78f9a87..d98a356af0 100644 --- a/plugins/warp/src/plugin/commit.rs +++ b/plugins/warp/src/plugin/commit.rs @@ -6,7 +6,6 @@ use crate::plugin::create::OpenFileField; use binaryninja::binary_view::BinaryView; use binaryninja::command::Command; use binaryninja::interaction::{Form, FormInputField}; -use binaryninja::tracing; use warp::chunk::ChunkKind; use warp::WarpFile; diff --git a/plugins/warp/src/plugin/create.rs b/plugins/warp/src/plugin/create.rs index 04a3e9b6bd..0c6a2fd5b0 100644 --- a/plugins/warp/src/plugin/create.rs +++ b/plugins/warp/src/plugin/create.rs @@ -10,7 +10,6 @@ use binaryninja::command::Command; use binaryninja::interaction::form::{Form, FormInputField}; use binaryninja::interaction::{MessageBoxButtonResult, MessageBoxButtonSet, MessageBoxIcon}; use binaryninja::rc::Ref; -use binaryninja::tracing; use std::path::PathBuf; use std::thread; use warp::chunk::Chunk; diff --git a/plugins/warp/src/plugin/debug.rs b/plugins/warp/src/plugin/debug.rs index 6db491e28d..d220d32954 100644 --- a/plugins/warp/src/plugin/debug.rs +++ b/plugins/warp/src/plugin/debug.rs @@ -3,7 +3,7 @@ use crate::{build_function, cache}; use binaryninja::binary_view::BinaryView; use binaryninja::command::{Command, FunctionCommand}; use binaryninja::function::Function; -use binaryninja::{tracing, ObjectDestructor}; +use binaryninja::ObjectDestructor; pub struct DebugFunction; diff --git a/plugins/warp/src/plugin/ffi/container.rs b/plugins/warp/src/plugin/ffi/container.rs index 6c2551c18c..2376ef1062 100644 --- a/plugins/warp/src/plugin/ffi/container.rs +++ b/plugins/warp/src/plugin/ffi/container.rs @@ -10,7 +10,6 @@ use binaryninja::architecture::CoreArchitecture; use binaryninja::binary_view::BinaryView; use binaryninja::rc::Ref; use binaryninja::string::BnString; -use binaryninja::tracing; use binaryninja::types::Type; use binaryninjacore_sys::{BNArchitecture, BNBinaryView, BNType}; use std::ffi::{c_char, CStr}; diff --git a/plugins/warp/src/plugin/file.rs b/plugins/warp/src/plugin/file.rs index 899e3f4653..cd5fb626b9 100644 --- a/plugins/warp/src/plugin/file.rs +++ b/plugins/warp/src/plugin/file.rs @@ -1,7 +1,6 @@ use crate::report::ReportGenerator; use binaryninja::binary_view::{BinaryView, BinaryViewExt}; use binaryninja::command::Command; -use binaryninja::tracing; pub struct ShowFileReport; diff --git a/plugins/warp/src/plugin/function.rs b/plugins/warp/src/plugin/function.rs index 3c0dc06c8b..36db7d55f7 100644 --- a/plugins/warp/src/plugin/function.rs +++ b/plugins/warp/src/plugin/function.rs @@ -10,7 +10,6 @@ use binaryninja::binary_view::{BinaryView, BinaryViewExt}; use binaryninja::command::{Command, FunctionCommand}; use binaryninja::function::{Function, FunctionUpdateType}; use binaryninja::rc::Guard; -use binaryninja::tracing; use rayon::iter::ParallelIterator; use std::thread; use warp::signature::function::FunctionGUID; diff --git a/plugins/warp/src/plugin/load.rs b/plugins/warp/src/plugin/load.rs index bd0e483841..2be473d8d9 100644 --- a/plugins/warp/src/plugin/load.rs +++ b/plugins/warp/src/plugin/load.rs @@ -10,7 +10,6 @@ use binaryninja::interaction::{ MessageBoxIcon, }; use binaryninja::rc::Ref; -use binaryninja::tracing; use std::collections::HashMap; use std::path::PathBuf; use std::sync::atomic::AtomicBool; diff --git a/plugins/warp/src/plugin/project.rs b/plugins/warp/src/plugin/project.rs index 8862c00a6e..b6081c1f1a 100644 --- a/plugins/warp/src/plugin/project.rs +++ b/plugins/warp/src/plugin/project.rs @@ -9,7 +9,6 @@ use binaryninja::interaction::{Form, FormInputField}; use binaryninja::project::folder::ProjectFolder; use binaryninja::project::Project; use binaryninja::rc::Ref; -use binaryninja::tracing; use binaryninja::worker_thread::{set_worker_thread_count, worker_thread_count}; use rayon::ThreadPoolBuilder; use regex::Regex; diff --git a/plugins/warp/src/plugin/workflow.rs b/plugins/warp/src/plugin/workflow.rs index a51c739932..1f4ef1016f 100644 --- a/plugins/warp/src/plugin/workflow.rs +++ b/plugins/warp/src/plugin/workflow.rs @@ -15,7 +15,6 @@ use binaryninja::command::Command; use binaryninja::function::Function as BNFunction; use binaryninja::rc::Ref as BNRef; use binaryninja::settings::{QueryOptions, Settings}; -use binaryninja::tracing; use binaryninja::workflow::{activity, Activity, AnalysisContext, Workflow, WorkflowBuilder}; use dashmap::DashSet; use itertools::Itertools; diff --git a/plugins/warp/src/processor.rs b/plugins/warp/src/processor.rs index 3076ddcade..e21a2efd13 100644 --- a/plugins/warp/src/processor.rs +++ b/plugins/warp/src/processor.rs @@ -29,7 +29,6 @@ use binaryninja::rc::{Guard, Ref}; use crate::cache::cached_type_references; use crate::convert::platform_to_target; use crate::{build_function, INCLUDE_TAG_ICON, INCLUDE_TAG_NAME}; -use binaryninja::tracing; use warp::chunk::{Chunk, ChunkKind, CompressionType}; use warp::r#type::chunk::TypeChunk; use warp::signature::chunk::SignatureChunk; diff --git a/plugins/workflow_objc/Cargo.toml b/plugins/workflow_objc/Cargo.toml index da8ae2c6e9..948fc2de26 100644 --- a/plugins/workflow_objc/Cargo.toml +++ b/plugins/workflow_objc/Cargo.toml @@ -17,3 +17,4 @@ dashmap = { version = "6.1", features = ["rayon"]} once_cell = "1.20" thiserror = "2.0" bstr = "1.12" +tracing = "0.1" \ No newline at end of file diff --git a/plugins/workflow_objc/demo/Cargo.toml b/plugins/workflow_objc/demo/Cargo.toml index bb7f41fa52..449abee0bf 100644 --- a/plugins/workflow_objc/demo/Cargo.toml +++ b/plugins/workflow_objc/demo/Cargo.toml @@ -14,8 +14,8 @@ demo = [] [dependencies] binaryninja = { workspace = true, features = ["demo"] } binaryninjacore-sys.workspace = true -log = "0.4" dashmap = { version = "6.1", features = ["rayon"]} once_cell = "1.20" thiserror = "2.0" bstr = "1.12" +tracing = "0.1" \ No newline at end of file diff --git a/plugins/workflow_objc/src/activities/objc_msg_send_calls.rs b/plugins/workflow_objc/src/activities/objc_msg_send_calls.rs index 860240477c..3a772e798c 100644 --- a/plugins/workflow_objc/src/activities/objc_msg_send_calls.rs +++ b/plugins/workflow_objc/src/activities/objc_msg_send_calls.rs @@ -7,7 +7,6 @@ use binaryninja::{ instruction::{InstructionHandler as _, LowLevelILInstruction, LowLevelILInstructionKind}, operation::{CallSsa, Operation}, }, - tracing, variable::PossibleValueSet, workflow::AnalysisContext, }; diff --git a/plugins/workflow_objc/src/activities/objc_msg_send_calls/rewrite_to_direct_call.rs b/plugins/workflow_objc/src/activities/objc_msg_send_calls/rewrite_to_direct_call.rs index 56c2aa5255..02f41de81e 100644 --- a/plugins/workflow_objc/src/activities/objc_msg_send_calls/rewrite_to_direct_call.rs +++ b/plugins/workflow_objc/src/activities/objc_msg_send_calls/rewrite_to_direct_call.rs @@ -4,7 +4,6 @@ use binaryninja::{ function::{LowLevelILFunction, Mutable, NonSSA, SSA}, instruction::{InstructionHandler as _, LowLevelILInstruction, LowLevelILInstructionKind}, }, - tracing, }; use super::MessageSendType; diff --git a/plugins/workflow_objc/src/activities/remove_memory_management.rs b/plugins/workflow_objc/src/activities/remove_memory_management.rs index fdd766502e..cd613ee2bf 100644 --- a/plugins/workflow_objc/src/activities/remove_memory_management.rs +++ b/plugins/workflow_objc/src/activities/remove_memory_management.rs @@ -11,7 +11,6 @@ use binaryninja::{ lifting::LowLevelILLabel, LowLevelILRegisterKind, }, - tracing, variable::PossibleValueSet, workflow::AnalysisContext, }; diff --git a/plugins/workflow_objc/src/activities/super_init.rs b/plugins/workflow_objc/src/activities/super_init.rs index 1cdf8825e5..68c6d3ee5c 100644 --- a/plugins/workflow_objc/src/activities/super_init.rs +++ b/plugins/workflow_objc/src/activities/super_init.rs @@ -10,7 +10,6 @@ use binaryninja::{ MediumLevelILFunction, MediumLevelILLiftedInstruction, MediumLevelILLiftedInstructionKind, }, rc::Ref, - tracing, types::Type, variable::{RegisterValueType, SSAVariable}, workflow::AnalysisContext, diff --git a/plugins/workflow_objc/src/lib.rs b/plugins/workflow_objc/src/lib.rs index 5b41b6d0a9..483751ae72 100644 --- a/plugins/workflow_objc/src/lib.rs +++ b/plugins/workflow_objc/src/lib.rs @@ -1,4 +1,4 @@ -use binaryninja::{add_optional_plugin_dependency, settings::Settings, tracing}; +use binaryninja::{add_optional_plugin_dependency, settings::Settings}; mod activities; mod error; diff --git a/plugins/workflow_objc/src/metadata/global_state.rs b/plugins/workflow_objc/src/metadata/global_state.rs index c6682a5ff3..db29af4981 100644 --- a/plugins/workflow_objc/src/metadata/global_state.rs +++ b/plugins/workflow_objc/src/metadata/global_state.rs @@ -5,7 +5,7 @@ use binaryninja::{ metadata::Metadata, rc::Ref, settings::{QueryOptions, Settings}, - tracing, ObjectDestructor, + ObjectDestructor, }; use dashmap::DashMap; use once_cell::sync::Lazy; diff --git a/plugins/workflow_objc/src/workflow.rs b/plugins/workflow_objc/src/workflow.rs index 13e3a71e19..fdda1d4533 100644 --- a/plugins/workflow_objc/src/workflow.rs +++ b/plugins/workflow_objc/src/workflow.rs @@ -1,4 +1,3 @@ -use binaryninja::tracing; use binaryninja::workflow::{activity, Activity, AnalysisContext, Workflow}; use crate::{activities, error::WorkflowRegistrationError}; diff --git a/rust/Cargo.toml b/rust/Cargo.toml index 2d7aa6a53e..17cb2f0dc4 100644 --- a/rust/Cargo.toml +++ b/rust/Cargo.toml @@ -27,13 +27,17 @@ serde_derive = "1.0" serde_json = "1.0" # Used for tracing compatible logs tracing = { version = "0.1", default-features = false, features = ["std"] } -tracing-subscriber = { version = "0.3", default-features = false, features = ["std", "registry", "smallvec", "parking_lot"] } +tracing-subscriber = { version = "0.3", default-features = false, features = ["std", "registry", "parking_lot"] } [dev-dependencies] rstest = "0.24" tempfile = "3.15" serial_test = "3.2" insta = { version = "1.42", features = ["yaml"] } +# Use default features so that examples can register the fmt subscriber. +tracing-subscriber = { version = "0.3", default-features = true } +# Used for progress bar in examples +tracing-indicatif = "0.3" [package.metadata.typos] default.extend-ignore-re = ["Collapsable"] diff --git a/rust/plugin_examples/data_renderer/Cargo.toml b/rust/plugin_examples/data_renderer/Cargo.toml index 7ac32dfd0c..6c9aa63bbe 100644 --- a/rust/plugin_examples/data_renderer/Cargo.toml +++ b/rust/plugin_examples/data_renderer/Cargo.toml @@ -10,4 +10,4 @@ crate-type = ["cdylib"] binaryninjacore-sys = { path = "../../binaryninjacore-sys" } binaryninja = { path = "../.." } uuid = "1.18.1" -log = "0.4.27" +tracing = "0.1" \ No newline at end of file diff --git a/rust/plugin_examples/data_renderer/src/lib.rs b/rust/plugin_examples/data_renderer/src/lib.rs index 97b81f23b3..e9c6b35486 100644 --- a/rust/plugin_examples/data_renderer/src/lib.rs +++ b/rust/plugin_examples/data_renderer/src/lib.rs @@ -101,7 +101,7 @@ impl CustomDataRenderer for UuidDataRenderer { pub unsafe extern "C" fn CorePluginInit() -> bool { // Initialize logging binaryninja::tracing_init!(); - binaryninja::tracing::info!("Core plugin initialized"); + tracing::info!("Core plugin initialized"); // Register data renderer register_data_renderer(UuidDataRenderer {}); diff --git a/rust/src/custom_binary_view.rs b/rust/src/custom_binary_view.rs index 12fd12a6f2..7a94326678 100644 --- a/rust/src/custom_binary_view.rs +++ b/rust/src/custom_binary_view.rs @@ -48,12 +48,10 @@ where where T: CustomBinaryViewType, { - ffi_wrap!("BinaryViewTypeBase::is_valid_for", unsafe { - let view_type = &*(ctxt as *mut T); - let data = BinaryView::ref_from_raw(BNNewViewReference(data)); - - view_type.is_valid_for(&data) - }) + let view_type = unsafe { &*(ctxt as *mut T) }; + let data = unsafe { BinaryView::ref_from_raw(BNNewViewReference(data)) }; + let _span = ffi_span!("BinaryViewTypeBase::is_valid_for", data); + view_type.is_valid_for(&data) } extern "C" fn cb_deprecated(ctxt: *mut c_void) -> bool @@ -89,6 +87,7 @@ where actual_parent: &data, }; + let _span = ffi_span!("BinaryViewTypeBase::create", data); match view_type.create_custom_view(&data, builder) { Ok(bv) => { // force a leak of the Ref; failure to do this would result @@ -114,6 +113,7 @@ where actual_parent: &data, }; + let _span = ffi_span!("BinaryViewTypeBase::parse", data); match view_type.parse_custom_view(&data, builder) { Ok(bv) => { // force a leak of the Ref; failure to do this would result @@ -134,6 +134,7 @@ where let view_type = &*(ctxt as *mut T); let data = BinaryView::ref_from_raw(BNNewViewReference(data)); + let _span = ffi_span!("BinaryViewTypeBase::load_settings", data); match view_type.load_settings_for_data(&data) { Some(settings) => Ref::into_raw(settings).handle, None => ptr::null_mut() as *mut _, diff --git a/rust/src/debuginfo.rs b/rust/src/debuginfo.rs index 02bf1ebbe7..346bafc3d6 100644 --- a/rust/src/debuginfo.rs +++ b/rust/src/debuginfo.rs @@ -216,12 +216,10 @@ impl DebugInfoParser { where C: CustomDebugInfoParser, { - ffi_wrap!("CustomDebugInfoParser::is_valid", unsafe { - let cmd = &*(ctxt as *const C); - let view = BinaryView::ref_from_raw(view); - - cmd.is_valid(&view) - }) + let cmd = unsafe { &*(ctxt as *const C) }; + let view = unsafe { BinaryView::ref_from_raw(view) }; + let _span = ffi_span!("CustomDebugInfoParser::is_valid", view); + cmd.is_valid(&view) } extern "C" fn cb_parse_info( @@ -235,28 +233,27 @@ impl DebugInfoParser { where C: CustomDebugInfoParser, { - ffi_wrap!("CustomDebugInfoParser::parse_info", unsafe { - let cmd = &*(ctxt as *const C); - let view = BinaryView::ref_from_raw(view); - let debug_file = BinaryView::ref_from_raw(debug_file); - let mut debug_info = DebugInfo::ref_from_raw(debug_info); - - cmd.parse_info( - &mut debug_info, - &view, - &debug_file, - Box::new(move |cur: usize, max: usize| match progress { - Some(func) => { - if func(progress_ctxt, cur, max) { - Ok(()) - } else { - Err(()) - } + let cmd = unsafe { &*(ctxt as *const C) }; + let view = unsafe { BinaryView::ref_from_raw(view) }; + let debug_file = unsafe { BinaryView::ref_from_raw(debug_file) }; + let mut debug_info = unsafe { DebugInfo::ref_from_raw(debug_info) }; + + let _span = ffi_span!("CustomDebugInfoParser::parse_info", view); + cmd.parse_info( + &mut debug_info, + &view, + &debug_file, + Box::new(move |cur: usize, max: usize| match progress { + Some(func) => unsafe { + if func(progress_ctxt, cur, max) { + Ok(()) + } else { + Err(()) } - _ => Ok(()), - }), - ) - }) + }, + _ => Ok(()), + }), + ) } let name = name.to_cstr(); diff --git a/rust/src/ffi.rs b/rust/src/ffi.rs index 7acba51459..901c4454c0 100644 --- a/rust/src/ffi.rs +++ b/rust/src/ffi.rs @@ -20,7 +20,7 @@ macro_rules! ffi_wrap { use std::process; panic::catch_unwind(|| $b).unwrap_or_else(|_| { - tracing::error!("ffi callback caught panic: {}", $n); + ::tracing::error!("ffi callback caught panic: {}", $n); process::abort() }) }}; @@ -37,10 +37,10 @@ macro_rules! ffi_span { use $crate::binary_view::BinaryViewExt; #[allow(unused_imports)] use $crate::file_metadata::FileMetadata; - tracing::info_span!($name, session_id = $bv.file().session_id().0).entered() + ::tracing::info_span!($name, session_id = $bv.file().session_id().0).entered() }}; ($name:expr) => { - tracing::info_span!($name).entered() + ::tracing::info_span!($name).entered() }; } diff --git a/rust/src/logger.rs b/rust/src/logger.rs index f77cb52cc6..31696d25c6 100644 --- a/rust/src/logger.rs +++ b/rust/src/logger.rs @@ -137,6 +137,7 @@ unsafe impl Sync for Logger {} /// This is typically used in headless usage. It can also be used to temporarily log core /// messages to something like a file while some analysis is occurring, once the [`LogGuard`] is /// dropped, the listener will be unregistered. +#[must_use] pub fn register_log_listener(listener: L) -> LogGuard { use binaryninjacore_sys::BNRegisterLogListener; diff --git a/rust/src/tracing.rs b/rust/src/tracing.rs index 3782887778..9216712c95 100644 --- a/rust/src/tracing.rs +++ b/rust/src/tracing.rs @@ -2,14 +2,11 @@ use crate::file_metadata::SessionId; use crate::logger::{ - bn_log_with_session, BnLogLevel, LogContext, LogListener, LOGGER_DEFAULT_SESSION_ID, + bn_log_with_session, BnLogLevel, LogContext, LogGuard, LogListener, LOGGER_DEFAULT_SESSION_ID, }; use tracing::{Event, Id, Level, Subscriber}; -use tracing_subscriber::prelude::*; - -// Re-export specific things to make it easy for the user -pub use tracing::{debug, error, info, trace, warn}; use tracing_subscriber::layer::Context; +use tracing_subscriber::prelude::*; use tracing_subscriber::registry::LookupSpan; use tracing_subscriber::Layer; @@ -26,7 +23,7 @@ use tracing_subscriber::Layer; /// #[unsafe(no_mangle)] /// pub unsafe extern "C" fn CorePluginInit() -> bool { /// binaryninja::tracing_init!("MyPlugin"); -/// binaryninja::tracing::info!("Core plugin initialized"); +/// tracing::info!("Core plugin initialized"); /// true /// } /// ``` @@ -262,7 +259,7 @@ impl tracing::field::Visit for BnFieldVisitor { /// // Register our tracing subscriber, this will send tracing events to stdout. /// tracing_subscriber::fmt::init(); /// // Register our log listener, this will send logs from the core to our tracing subscriber. -/// let _listener = register_log_listener(TracingLogListener::new(BnLogLevel::DebugLog)); +/// let _listener = TracingLogListener::new(BnLogLevel::DebugLog).register(); /// // Should see logs from the core in regard to initialization show up. /// let _session = Session::new().expect("Failed to create session"); /// bn_log("Test", BnLogLevel::DebugLog, "Hello, world!"); @@ -273,9 +270,29 @@ pub struct TracingLogListener { } impl TracingLogListener { - pub fn new(minimum_level: BnLogLevel) -> Self { + /// Create a [`TracingLogListener`] with the minimum log level set to [`BnLogLevel::InfoLog`]. + pub fn new() -> Self { + Self::default() + } + + pub fn new_with_lvl(minimum_level: BnLogLevel) -> Self { Self { minimum_level } } + + /// Register the [`TracingLogListener`] and send logs to the registered tracing subscriber until + /// the [`LogGuard`] is dropped, make sure to register your tracing subscriber before registering. + #[must_use] + pub fn register(self) -> LogGuard { + crate::logger::register_log_listener(self) + } +} + +impl Default for TracingLogListener { + fn default() -> Self { + Self { + minimum_level: BnLogLevel::InfoLog, + } + } } impl LogListener for TracingLogListener { @@ -283,16 +300,40 @@ impl LogListener for TracingLogListener { let session = ctx.session_id.map(|s| s.0); match level { BnLogLevel::ErrorLog | BnLogLevel::AlertLog => { - error!(session_id = session, target = %ctx.logger_name, "{}", message) + tracing::error!( + target: "binaryninja", + session_id = session, + logger = %ctx.logger_name, + "{}", + message + ) } BnLogLevel::WarningLog => { - warn!(session_id = session, target = %ctx.logger_name, "{}", message) + tracing::warn!( + target: "binaryninja", + session_id = session, + logger = %ctx.logger_name, + "{}", + message + ) } BnLogLevel::InfoLog => { - info!(session_id = session, target = %ctx.logger_name, "{}", message) + tracing::info!( + target: "binaryninja", + session_id = session, + logger = %ctx.logger_name, + "{}", + message + ) } BnLogLevel::DebugLog => { - debug!(session_id = session, target = %ctx.logger_name, "{}", message) + tracing::debug!( + target: "binaryninja", + session_id = session, + logger = %ctx.logger_name, + "{}", + message + ) } }; } diff --git a/view/minidump/Cargo.toml b/view/minidump/Cargo.toml index fed4a61195..a39e9172a5 100644 --- a/view/minidump/Cargo.toml +++ b/view/minidump/Cargo.toml @@ -10,4 +10,5 @@ crate-type = ["cdylib"] [dependencies] binaryninja.workspace = true binaryninjacore-sys.workspace = true -minidump = "0.23.0" \ No newline at end of file +minidump = "0.23.0" +tracing = "0.1" \ No newline at end of file diff --git a/view/minidump/src/command.rs b/view/minidump/src/command.rs index 2f28b8b598..ca7ce4c570 100644 --- a/view/minidump/src/command.rs +++ b/view/minidump/src/command.rs @@ -3,7 +3,6 @@ use std::str; use minidump::{Minidump, MinidumpMemoryInfoList}; use binaryninja::binary_view::{BinaryView, BinaryViewBase, BinaryViewExt}; -use binaryninja::tracing; pub fn print_memory_information(bv: &BinaryView) { tracing::debug!("Printing memory information"); diff --git a/view/minidump/src/lib.rs b/view/minidump/src/lib.rs index 00fed601af..1b1f7f1967 100644 --- a/view/minidump/src/lib.rs +++ b/view/minidump/src/lib.rs @@ -1,7 +1,6 @@ use binaryninja::binary_view::BinaryView; use binaryninja::command::{register_command, Command}; use binaryninja::custom_binary_view::register_view_type; -use binaryninja::tracing; mod command; mod view; diff --git a/view/minidump/src/view.rs b/view/minidump/src/view.rs index 32fde030f5..8baf30c2b7 100644 --- a/view/minidump/src/view.rs +++ b/view/minidump/src/view.rs @@ -15,7 +15,7 @@ use binaryninja::custom_binary_view::{ CustomViewBuilder, }; use binaryninja::platform::Platform; -use binaryninja::{tracing, Endianness}; +use binaryninja::Endianness; type BinaryViewResult = binaryninja::binary_view::Result; From 3df10611201b630fbacf05e80bdff71c98ddcb15 Mon Sep 17 00:00:00 2001 From: Mason Reed Date: Fri, 19 Dec 2025 19:15:38 -0500 Subject: [PATCH 3/6] [Rust] Update examples to use tracing --- plugins/warp/examples/headless/Cargo.toml | 8 +- plugins/warp/examples/headless/src/main.rs | 110 +++++++++------------ rust/examples/bndb_to_type_library.rs | 43 ++++++-- rust/examples/create_type_library.rs | 14 ++- rust/examples/decompile.rs | 15 +-- rust/examples/demangler.rs | 17 ++-- rust/examples/disassemble.rs | 15 +-- rust/examples/dump_settings.rs | 15 +-- rust/examples/dump_type_library.rs | 11 ++- rust/examples/flowgraph.rs | 33 ++++--- rust/examples/high_level_il.rs | 13 ++- rust/examples/medium_level_il.rs | 13 ++- rust/examples/simple.rs | 13 ++- rust/examples/type_printer.rs | 7 +- rust/examples/workflow.rs | 17 +++- 15 files changed, 202 insertions(+), 142 deletions(-) diff --git a/plugins/warp/examples/headless/Cargo.toml b/plugins/warp/examples/headless/Cargo.toml index b28b089d12..a32796beb5 100644 --- a/plugins/warp/examples/headless/Cargo.toml +++ b/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" \ No newline at end of file +ctrlc = "3.5" +tracing = "0.1" +tracing-subscriber = "0.3" +tracing-indicatif = "0.3" \ No newline at end of file diff --git a/plugins/warp/examples/headless/src/main.rs b/plugins/warp/examples/headless/src/main.rs index c08103a5cd..29d48f6517 100644 --- a/plugins/warp/examples/headless/src/main.rs +++ b/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,7 +84,12 @@ 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> = args .input @@ -80,14 +97,14 @@ fn main() { .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,7 +115,7 @@ 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(); } } @@ -106,11 +123,11 @@ fn main() { // 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); } } } @@ -118,65 +135,36 @@ fn main() { } // TODO: Also poll for background tasks and display them as independent progress bars. -fn run_progress_bar(state: Arc) -> 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, finished: Arc) { + 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>, -} - -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() + ); } diff --git a/rust/examples/bndb_to_type_library.rs b/rust/examples/bndb_to_type_library.rs index 84515cf7da..2cfaf83ef3 100644 --- a/rust/examples/bndb_to_type_library.rs +++ b/rust/examples/bndb_to_type_library.rs @@ -1,9 +1,21 @@ // Usage: cargo run --example bndb_to_type_library 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); @@ -11,28 +23,43 @@ fn main() { 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); } diff --git a/rust/examples/create_type_library.rs b/rust/examples/create_type_library.rs index 74d93765af..14c387a4a3 100644 --- a/rust/examples/create_type_library.rs +++ b/rust/examples/create_type_library.rs @@ -1,9 +1,13 @@ // Usage: cargo run --example create_type_library 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); } diff --git a/rust/examples/decompile.rs b/rust/examples/decompile.rs index 8bf3ecc3da..6ba9cbf415 100644 --- a/rust/examples/decompile.rs +++ b/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()); diff --git a/rust/examples/demangler.rs b/rust/examples/demangler.rs index b2e5eb66ca..edefaec19b 100644 --- a/rust/examples/demangler.rs +++ b/rust/examples/demangler.rs @@ -2,6 +2,7 @@ use binaryninja::architecture::CoreArchitecture; use binaryninja::binary_view::BinaryView; use binaryninja::demangle::{CustomDemangler, Demangler}; use binaryninja::rc::Ref; +use binaryninja::tracing::TracingLogListener; use binaryninja::types::{QualifiedName, Type}; struct TestDemangler; @@ -26,32 +27,34 @@ impl CustomDemangler for TestDemangler { } fn main() { - println!("Starting session..."); + tracing_subscriber::fmt::init(); + let _listener = TracingLogListener::new().register(); + // This loads all the core architecture, platform, etc plugins let _headless_session = binaryninja::headless::Session::new().expect("Failed to initialize session"); - println!("Registering demangler..."); + tracing::info!("Registering demangler..."); Demangler::register("Test", TestDemangler); let placeholder_arch = CoreArchitecture::by_name("x86_64").expect("x86 exists"); for d in Demangler::list().iter() { - println!("{}", d.name()); + tracing::info!("{}", d.name()); - println!( + tracing::info!( " \"__ZN1AC2Ei\" is mangled? {}", d.is_mangled_string("__ZN1AC2Ei") ); - println!( + tracing::info!( " \"__ZN1AC2Ei\" : {:?}", d.demangle(&placeholder_arch, "__ZN1AC2Ei", None) ); - println!( + tracing::info!( " \"test_name\" : {:?}", d.demangle(&placeholder_arch, "test_name", None) ); - println!( + tracing::info!( " \"test_name2\" : {:?}", d.demangle(&placeholder_arch, "test_name2", None) ); diff --git a/rust/examples/disassemble.rs b/rust/examples/disassemble.rs index 2065c787a1..ce3ff76569 100644 --- a/rust/examples/disassemble.rs +++ b/rust/examples/disassemble.rs @@ -1,6 +1,7 @@ use binaryninja::binary_view::{BinaryViewBase, BinaryViewExt}; use binaryninja::disassembly::{DisassemblyOption, DisassemblySettings, DisassemblyTextRenderer}; use binaryninja::function::Function; +use binaryninja::tracing::TracingLogListener; fn disassemble(func: &Function) { let settings = DisassemblySettings::new(); @@ -17,28 +18,30 @@ fn disassemble(func: &Function) { if let Some((text, _len)) = text_renderer.instruction_text(instr_addr) { // TODO: This only ever appears to return a single string? let text_string: Vec<_> = text.iter().map(|t| t.to_string()).collect(); - println!("{}", text_string.join("")); + tracing::info!("{}", text_string.join("")); } } } } 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() { disassemble(func.as_ref()); diff --git a/rust/examples/dump_settings.rs b/rust/examples/dump_settings.rs index 51452ca7df..8c4af0578a 100644 --- a/rust/examples/dump_settings.rs +++ b/rust/examples/dump_settings.rs @@ -1,7 +1,10 @@ use binaryninja::settings::Settings; +use binaryninja::tracing::TracingLogListener; fn main() { - println!("Starting session..."); + tracing_subscriber::fmt::init(); + let _listener = TracingLogListener::new().register(); + // This loads all the core architecture, platform, etc plugins let _headless_session = binaryninja::headless::Session::new().expect("Failed to initialize session"); @@ -12,10 +15,10 @@ fn main() { let default_value = settings.get_property_string(key, "default"); let title = settings.get_property_string(key, "title"); let description = settings.get_property_string(key, "description"); - println!("{}:", key); - println!(" value: {}", value); - println!(" default_value: {}", default_value); - println!(" title: {}", title); - println!(" description: {}", description); + tracing::info!("{}:", key); + tracing::info!(" value: {}", value); + tracing::info!(" default_value: {}", default_value); + tracing::info!(" title: {}", title); + tracing::info!(" description: {}", description); } } diff --git a/rust/examples/dump_type_library.rs b/rust/examples/dump_type_library.rs index f7398d28eb..9e6b19c29e 100644 --- a/rust/examples/dump_type_library.rs +++ b/rust/examples/dump_type_library.rs @@ -2,21 +2,24 @@ use binaryninja::binary_view::BinaryView; use binaryninja::file_metadata::FileMetadata; +use binaryninja::tracing::TracingLogListener; use binaryninja::types::library::TypeLibrary; use binaryninja::types::printer::{CoreTypePrinter, TokenEscapingType}; fn main() { + tracing_subscriber::fmt::init(); + let _listener = TracingLogListener::new().register(); + let type_lib_str = std::env::args().nth(1).expect("No type library provided"); let type_lib_path = std::path::Path::new(&type_lib_str); - 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 type_lib = TypeLibrary::load_from_file(type_lib_path).expect("Failed to load type library"); - println!("Name: `{}`", type_lib.name()); - println!("GUID: `{}`", type_lib.guid()); + tracing::info!("Name: `{}`", type_lib.name()); + tracing::info!("GUID: `{}`", type_lib.guid()); // Print out all the types as a c header. let type_lib_header_path = type_lib_path.with_extension("h"); @@ -27,7 +30,7 @@ fn main() { .chain(type_lib.named_objects().iter()) .collect(); - println!( + tracing::info!( "Dumping {} types to: `{:?}`", all_types.len(), type_lib_header_path diff --git a/rust/examples/flowgraph.rs b/rust/examples/flowgraph.rs index 75c854a761..cb03234e73 100644 --- a/rust/examples/flowgraph.rs +++ b/rust/examples/flowgraph.rs @@ -6,6 +6,7 @@ use binaryninja::interaction::handler::{ register_interaction_handler, InteractionHandler, InteractionHandlerTask, }; use binaryninja::interaction::{MessageBoxButtonResult, MessageBoxButtonSet, MessageBoxIcon}; +use binaryninja::tracing::TracingLogListener; use binaryninja::{ architecture::BranchType, binary_view::{BinaryView, BinaryViewExt}, @@ -17,22 +18,22 @@ pub struct GraphPrinter; impl GraphPrinter { pub fn print_graph(&self, graph: &FlowGraph) { - println!("Printing flow graph:"); + tracing::info!("Printing flow graph:"); for node in &graph.nodes() { // Print all disassembly lines in the node - println!("Node @ {:?}:", node.position()); - println!("------------------"); - println!("Disassembly lines:"); + tracing::info!("Node @ {:?}:", node.position()); + tracing::info!("------------------"); + tracing::info!("Disassembly lines:"); for line in &node.lines() { - println!(" {}", line); + tracing::info!(" {}", line); } // Print outgoing edges - println!("Outgoing edges:"); + tracing::info!("Outgoing edges:"); for edge in &node.outgoing_edges() { - println!(" {:?} => {:?}", edge.branch_type, edge.target.position()); + tracing::info!(" {:?} => {:?}", edge.branch_type, edge.target.position()); } - println!("------------------"); + tracing::info!("------------------"); } } } @@ -62,14 +63,14 @@ impl InteractionHandler for GraphPrinter { } fn show_plain_text_report(&mut self, _view: Option<&BinaryView>, title: &str, contents: &str) { - println!("Plain text report"); - println!("Title: {}", title); - println!("Contents: {}", contents); + tracing::info!("Plain text report"); + tracing::info!("Title: {}", title); + tracing::info!("Contents: {}", contents); } fn show_graph_report(&mut self, _view: Option<&BinaryView>, title: &str, graph: &FlowGraph) { - println!("Graph report"); - println!("Title: {}", title); + tracing::info!("Graph report"); + tracing::info!("Title: {}", title); self.print_graph(graph); } @@ -115,12 +116,14 @@ fn test_graph() { } fn main() { - println!("Starting session..."); + tracing_subscriber::fmt::init(); + let _listener = TracingLogListener::new().register(); + // 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("/bin/cat") .expect("Couldn't open `/bin/cat`"); diff --git a/rust/examples/high_level_il.rs b/rust/examples/high_level_il.rs index ddc8f08d1b..a099437a20 100644 --- a/rust/examples/high_level_il.rs +++ b/rust/examples/high_level_il.rs @@ -1,19 +1,22 @@ use binaryninja::binary_view::{BinaryViewBase, BinaryViewExt}; +use binaryninja::tracing::TracingLogListener; fn main() { - println!("Starting session..."); + tracing_subscriber::fmt::init(); + let _listener = TracingLogListener::new().register(); + // 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("/bin/cat") .expect("Couldn't open `/bin/cat`"); - 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() { println!("{:?}:", func.symbol().full_name()); diff --git a/rust/examples/medium_level_il.rs b/rust/examples/medium_level_il.rs index 543a085629..c9412d089c 100644 --- a/rust/examples/medium_level_il.rs +++ b/rust/examples/medium_level_il.rs @@ -1,19 +1,22 @@ use binaryninja::binary_view::{BinaryViewBase, BinaryViewExt}; +use binaryninja::tracing::TracingLogListener; fn main() { - println!("Starting session..."); + tracing_subscriber::fmt::init(); + let _listener = TracingLogListener::new().register(); + // 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("/bin/cat") .expect("Couldn't open `/bin/cat`"); - 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() { println!("{:?}:", func.symbol().full_name()); diff --git a/rust/examples/simple.rs b/rust/examples/simple.rs index 66dbdfc086..c01ef74e58 100644 --- a/rust/examples/simple.rs +++ b/rust/examples/simple.rs @@ -1,20 +1,23 @@ use binaryninja::architecture::Architecture; use binaryninja::binary_view::{BinaryViewBase, BinaryViewExt}; +use binaryninja::tracing::TracingLogListener; fn main() { - println!("Starting session..."); + tracing_subscriber::fmt::init(); + let _listener = TracingLogListener::new().register(); + // 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("/bin/cat") .expect("Couldn't open `/bin/cat`"); - println!("File: `{}`", bv.file()); - println!("File size: `{:#x}`", bv.len()); - println!("Function count: {}", bv.functions().len()); + tracing::info!("File: `{}`", bv.file()); + tracing::info!("File size: `{:#x}`", bv.len()); + tracing::info!("Function count: {}", bv.functions().len()); for func in &bv.functions() { println!("{}:", func.symbol()); diff --git a/rust/examples/type_printer.rs b/rust/examples/type_printer.rs index b88a023304..7407197ed5 100644 --- a/rust/examples/type_printer.rs +++ b/rust/examples/type_printer.rs @@ -1,13 +1,16 @@ +use binaryninja::tracing::TracingLogListener; use binaryninja::types::printer::{CoreTypePrinter, TokenEscapingType}; use binaryninja::types::{MemberAccess, MemberScope, Structure, StructureMember, Type}; fn main() { - println!("Starting session..."); + tracing_subscriber::fmt::init(); + let _listener = TracingLogListener::new().register(); + // 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("/bin/cat") .expect("Couldn't open `/bin/cat`"); diff --git a/rust/examples/workflow.rs b/rust/examples/workflow.rs index d030209a0b..bfbbbdb250 100644 --- a/rust/examples/workflow.rs +++ b/rust/examples/workflow.rs @@ -2,6 +2,7 @@ use binaryninja::binary_view::BinaryViewExt; use binaryninja::low_level_il::expression::{ExpressionHandler, LowLevelILExpressionKind}; use binaryninja::low_level_il::instruction::InstructionHandler; use binaryninja::low_level_il::VisitorAction; +use binaryninja::tracing::TracingLogListener; use binaryninja::workflow::{Activity, AnalysisContext, Workflow}; const RUST_ACTIVITY_NAME: &str = "analysis.plugins.rustexample"; @@ -31,7 +32,11 @@ fn example_activity(analysis_context: &AnalysisContext) { llil_instr.visit_tree(&mut |expr| { if let LowLevelILExpressionKind::Const(_op) = expr.kind() { // Replace all consts with 0x1337. - println!("Replacing llil expression @ 0x{:x} : {}", instr, expr.index); + tracing::debug!( + "Replacing llil expression @ 0x{:x} : {}", + instr, + expr.index + ); unsafe { llil.replace_expression(expr.index, llil.const_int(4, 0x1337)) }; @@ -46,12 +51,14 @@ fn example_activity(analysis_context: &AnalysisContext) { } pub fn main() { - println!("Starting session..."); + tracing_subscriber::fmt::init(); + let _listener = TracingLogListener::new().register(); + // This loads all the core architecture, platform, etc plugins let headless_session = binaryninja::headless::Session::new().expect("Failed to initialize session"); - println!("Registering workflow..."); + tracing::info!("Registering workflow..."); let activity = Activity::new_with_action(RUST_ACTIVITY_CONFIG, example_activity); // Update the meta-workflow with our new activity. Workflow::cloned("core.function.metaAnalysis") @@ -61,7 +68,7 @@ pub fn main() { .register() .expect("Couldn't register activity"); - println!("Loading binary..."); + tracing::info!("Loading binary..."); let bv = headless_session .load("/bin/cat") .expect("Couldn't open `/bin/cat`"); @@ -74,7 +81,7 @@ pub fn main() { instr.visit_tree(&mut |expr| { if let LowLevelILExpressionKind::Const(value) = expr.kind() { if value.value() == 0x1337 { - println!( + tracing::info!( "Found constant 0x1337 at instruction 0x{:x} in function {}", instr.address(), func.start() From c8d7244d5449bf878ae8374bc8cef26c7c37bf04 Mon Sep 17 00:00:00 2001 From: Mason Reed Date: Fri, 19 Dec 2025 19:51:53 -0500 Subject: [PATCH 4/6] [Rust] Fix old rust toolchain version being used when checking Rust API Would be really nice if we consolidated this somewhere so this does not keep happening --- rust/CMakeLists.txt | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/rust/CMakeLists.txt b/rust/CMakeLists.txt index caead2d975..fbdccd3766 100644 --- a/rust/CMakeLists.txt +++ b/rust/CMakeLists.txt @@ -2,7 +2,7 @@ cmake_minimum_required(VERSION 3.13 FATAL_ERROR) project(rust_api) -set(CARGO_API_VERSION 1.83.0) +set(CARGO_API_VERSION 1.91.1) file(GLOB_RECURSE RUST_API_SOURCES CONFIGURE_DEPENDS ../binaryninjacore.h From 9717943e4017ff22209416a2b1d7d15ccf7554e7 Mon Sep 17 00:00:00 2001 From: Mason Reed Date: Fri, 19 Dec 2025 19:52:39 -0500 Subject: [PATCH 5/6] [Rust] Add top level documentation to `tracing` and `logger` --- rust/src/logger.rs | 7 +++++-- rust/src/tracing.rs | 22 ++++++++++++++++++++-- 2 files changed, 25 insertions(+), 4 deletions(-) diff --git a/rust/src/logger.rs b/rust/src/logger.rs index 31696d25c6..66e594fdb2 100644 --- a/rust/src/logger.rs +++ b/rust/src/logger.rs @@ -1,5 +1,8 @@ -// TODO: Describe this in terms of the core Logger, but refer to tracing for how to capture rust logs. - +//! Core [`Logger`] implementation, see [`crate::tracing`] for typical plugin and headless usage. +//! +//! This module defines the core logger model, which is typically not used directly and instead is used +//! via the [`crate::tracing`] implementations. If you require a custom [`LogListener`] or need to log +//! directly to the core instead of through `tracing` macros, that is what this module is useful for. use crate::file_metadata::SessionId; use crate::rc::{Ref, RefCountable}; use crate::string::{raw_to_string, BnString, IntoCStr}; diff --git a/rust/src/tracing.rs b/rust/src/tracing.rs index 9216712c95..e569229e1e 100644 --- a/rust/src/tracing.rs +++ b/rust/src/tracing.rs @@ -1,4 +1,22 @@ -// TODO: Add top level docs here. +//! Integration with the [`tracing`](https://docs.rs/tracing) ecosystem. Send logs to and from Binary Ninja. +//! +//! This module allows you to use standard Rust `tracing` macros (like `info!`, `warn!`, `error!`) +//! and have them get sent to Binary Ninja, as well as the other way around with [`TracingLogListener`]. +//! +//! ## For Plugins +//! +//! When writing a plugin, and you want your Rust logs to appear in the Binary Ninja UI, use the +//! [`crate::tracing_init`] macro at the start of your plugin's init function. +//! +//! ## For Headless +//! +//! When running headless (standalone executables), and you want internal Binary Ninja logs to appear +//! in your terminal's standard output, register the [`TracingLogListener`] after initializing your +//! tracing subscriber. +//! +//! ## Never use both [`BinaryNinjaLayer`] and [`TracingLogListener`] simultaneously +//! +//! Enabling both creates an infinite feedback loop where a log triggers a log, deadlocking the application. use crate::file_metadata::SessionId; use crate::logger::{ @@ -259,7 +277,7 @@ impl tracing::field::Visit for BnFieldVisitor { /// // Register our tracing subscriber, this will send tracing events to stdout. /// tracing_subscriber::fmt::init(); /// // Register our log listener, this will send logs from the core to our tracing subscriber. -/// let _listener = TracingLogListener::new(BnLogLevel::DebugLog).register(); +/// let _listener = TracingLogListener::new().register(); /// // Should see logs from the core in regard to initialization show up. /// let _session = Session::new().expect("Failed to create session"); /// bn_log("Test", BnLogLevel::DebugLog, "Hello, world!"); From 77ebe1bb3d023759569a4595d0f09f74ecd8ed41 Mon Sep 17 00:00:00 2001 From: Mason Reed Date: Fri, 19 Dec 2025 20:30:31 -0500 Subject: [PATCH 6/6] [Rust] More session scoped logs Assign the `session_id` span field before calling into the relocation handler so logs get scoped to the specific view. --- rust/src/function_recognizer.rs | 2 ++ rust/src/relocation.rs | 2 ++ 2 files changed, 4 insertions(+) diff --git a/rust/src/function_recognizer.rs b/rust/src/function_recognizer.rs index 0d85d827af..f46c741d4a 100644 --- a/rust/src/function_recognizer.rs +++ b/rust/src/function_recognizer.rs @@ -50,6 +50,7 @@ where let bv = unsafe { BinaryView::from_raw(bv).to_owned() }; let func = unsafe { Function::from_raw(func).to_owned() }; let llil = unsafe { LowLevelILFunction::from_raw(llil).to_owned() }; + let _span = ffi_span!("FunctionRecognizer::recognize_low_level_il", bv); context.recognizer.recognize_low_level_il(&bv, &func, &llil) } @@ -66,6 +67,7 @@ where let bv = unsafe { BinaryView::from_raw(bv).to_owned() }; let func = unsafe { Function::from_raw(func).to_owned() }; let mlil = unsafe { MediumLevelILFunction::from_raw(mlil).to_owned() }; + let _span = ffi_span!("FunctionRecognizer::recognize_medium_level_il", bv); context .recognizer .recognize_medium_level_il(&bv, &func, &mlil) diff --git a/rust/src/relocation.rs b/rust/src/relocation.rs index a4f9667ece..a2c3822115 100644 --- a/rust/src/relocation.rs +++ b/rust/src/relocation.rs @@ -442,6 +442,7 @@ where .iter() .map(RelocationInfo::from_raw) .collect::>(); + let _span = ffi_span!("RelocationHandler::get_relocation_info", bv); let ok = custom_handler.get_relocation_info(bv.as_ref(), arch.as_ref(), info.as_mut_slice()); for (result, info) in result.iter_mut().zip(info.iter()) { @@ -466,6 +467,7 @@ where let arch = unsafe { CoreArchitecture::from_raw(arch) }; let reloc = unsafe { Relocation::from_raw(reloc) }; let dest = unsafe { core::slice::from_raw_parts_mut(dest, len) }; + let _span = ffi_span!("RelocationHandler::apply_relocation", bv); custom_handler.apply_relocation(bv.as_ref(), arch.as_ref(), &reloc, dest) }