[Rust] Enter more session scoped tracing spans for debug info and binary view callbacks

6 files changed, 46 insertions, 44 deletions

diff --git a/plugins/pdb-ng/Cargo.toml b/plugins/pdb-ng/Cargo.toml
index e77dac5b..08776df2 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 bde9b28c..590cacca 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 5bbbb53e..86ae1cdd 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<impl Iterat
 fn read_from_sym_store(bv: &BinaryView, path: &str) -> Result<(bool, Vec<u8>)> {
     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<u8>)> {
         }
     };
 
-    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 708bc34a..82a2bd75 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, 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 8143ff42..378d8c3b 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<F: FnOnce() -> 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 e22489a9..2ab2a0cc 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, StructureBuilder, StructureMember,
@@ -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));
@@ -921,7 +920,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
                             .last()
@@ -933,7 +932,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
                     .last()