[Rust] 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.

1 files changed, 305 insertions, 0 deletions

diff --git a/rust/src/tracing.rs b/rust/src/tracing.rs
new file mode 100644
index 00000000..2afdcd5e
--- /dev/null
+++ b/rust/src/tracing.rs
@@ -0,0 +1,305 @@
+// 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 will only be applied when the target name is implicit. Explicitly provided
+    /// target names will be preserved as-is.
+    ///
+    /// # Example
+    ///
+    /// Given the target "my_crate::commands::analyze" the target will be rewritten to "MyCrate.Commands.Analyze".
+    pub format_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_format_target(mut self, formatted: bool) -> Self {
+        self.format_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.format_target {
+            target = format_target(&target);
+        }
+
+        target
+    }
+}
+
+impl Default for BinaryNinjaLayer {
+    fn default() -> Self {
+        Self {
+            target_mappings: vec![("binaryninja".to_string(), "Binary Ninja".to_string())],
+            format_target: true,
+        }
+    }
+}
+
+impl<S> Layer<S> 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::<SessionId>().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<SessionId>,
+}
+
+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
+    }
+}