From 7e0fd185bbb9444c5c648d4f6aed6578879b564a Mon Sep 17 00:00:00 2001 From: neuronull <9162534+neuronull@users.noreply.github.com> Date: Fri, 5 Sep 2025 15:08:51 -0600 Subject: [PATCH] [BEEEP][PM-255518] Use tracing for improved observability --- apps/desktop/desktop_native/Cargo.lock | 62 ++++++++++ apps/desktop/desktop_native/Cargo.toml | 2 + apps/desktop/desktop_native/core/Cargo.toml | 1 + .../desktop_native/core/src/ssh_agent/mod.rs | 23 ++-- .../ssh_agent/named_pipe_listener_stream.rs | 27 ++--- .../desktop_native/core/src/ssh_agent/unix.rs | 17 ++- apps/desktop/desktop_native/napi/Cargo.toml | 2 + apps/desktop/desktop_native/napi/src/lib.rs | 111 +++++++++++++----- 8 files changed, 180 insertions(+), 65 deletions(-) diff --git a/apps/desktop/desktop_native/Cargo.lock b/apps/desktop/desktop_native/Cargo.lock index 70814c74106..83eadae0296 100644 --- a/apps/desktop/desktop_native/Cargo.lock +++ b/apps/desktop/desktop_native/Cargo.lock @@ -906,6 +906,7 @@ dependencies = [ "tokio", "tokio-stream", "tokio-util", + "tracing", "typenum", "widestring", "windows 0.61.1", @@ -933,6 +934,8 @@ dependencies = [ "tokio", "tokio-stream", "tokio-util", + "tracing", + "tracing-subscriber", "windows-registry", "windows_plugin_authenticator", ] @@ -1904,6 +1907,15 @@ dependencies = [ "winapi", ] +[[package]] +name = "nu-ansi-term" +version = "0.50.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d4a28e057d01f97e61255210fcff094d74ed0466038633e95017f5beb68e4399" +dependencies = [ + "windows-sys 0.52.0", +] + [[package]] name = "num" version = "0.4.3" @@ -2857,6 +2869,15 @@ dependencies = [ "digest", ] +[[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" @@ -3125,6 +3146,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 = "time" version = "0.3.41" @@ -3276,6 +3306,32 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e672c95779cf947c5311f83787af4fa8fffd12fb27e4993211a84bdfd9610f9c" dependencies = [ "once_cell", + "valuable", +] + +[[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]] +name = "tracing-subscriber" +version = "0.3.20" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2054a14f5307d601f88daf0553e1cbf472acc4f2c51afab632431cdcd72124d5" +dependencies = [ + "nu-ansi-term", + "sharded-slab", + "smallvec", + "thread_local", + "tracing-core", + "tracing-log", ] [[package]] @@ -3496,6 +3552,12 @@ version = "0.2.2" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "06abde3611657adf66d383f00b093d7faecc7fa57071cce2578660c9f1010821" +[[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" diff --git a/apps/desktop/desktop_native/Cargo.toml b/apps/desktop/desktop_native/Cargo.toml index b5819d3688e..a50c06498a5 100644 --- a/apps/desktop/desktop_native/Cargo.toml +++ b/apps/desktop/desktop_native/Cargo.toml @@ -61,6 +61,8 @@ thiserror = "=2.0.12" tokio = "=1.45.0" tokio-stream = "=0.1.15" tokio-util = "=0.7.13" +tracing = "=0.1.41" +tracing-subscriber = "=0.3.20" typenum = "=1.18.0" uniffi = "=0.28.3" widestring = "=1.2.0" diff --git a/apps/desktop/desktop_native/core/Cargo.toml b/apps/desktop/desktop_native/core/Cargo.toml index 97189e1d7cd..eb417c6a8d9 100644 --- a/apps/desktop/desktop_native/core/Cargo.toml +++ b/apps/desktop/desktop_native/core/Cargo.toml @@ -48,6 +48,7 @@ ssh-key = { workspace = true, features = [ ] } sysinfo = { workspace = true, features = ["windows"] } thiserror = { workspace = true } +tracing = { workspace = true } tokio = { workspace = true, features = ["io-util", "sync", "macros", "net"] } tokio-stream = { workspace = true, features = ["net"] } tokio-util = { workspace = true, features = ["codec"] } diff --git a/apps/desktop/desktop_native/core/src/ssh_agent/mod.rs b/apps/desktop/desktop_native/core/src/ssh_agent/mod.rs index d038ba2277f..3440a0114ae 100644 --- a/apps/desktop/desktop_native/core/src/ssh_agent/mod.rs +++ b/apps/desktop/desktop_native/core/src/ssh_agent/mod.rs @@ -11,6 +11,7 @@ use bitwarden_russh::{ session_bind::SessionBindResult, ssh_agent::{self, SshKey}, }; +use tracing::{error, info}; #[cfg_attr(target_os = "windows", path = "windows.rs")] #[cfg_attr(target_os = "macos", path = "unix.rs")] @@ -86,7 +87,7 @@ impl ssh_agent::Agent info: &peerinfo::models::PeerInfo, ) -> bool { if !self.is_running() { - println!("[BitwardenDesktopAgent] Agent is not running, but tried to call confirm"); + error!("Agent is not running, but tried to call confirm"); return false; } @@ -94,7 +95,7 @@ impl ssh_agent::Agent let request_data = match request_parser::parse_request(data) { Ok(data) => data, Err(e) => { - println!("[SSH Agent] Error while parsing request: {e}"); + error!(error = %e, "Error while parsing request"); return false; } }; @@ -105,12 +106,12 @@ impl ssh_agent::Agent _ => None, }; - println!( - "[SSH Agent] Confirming request from application: {}, is_forwarding: {}, namespace: {}, host_key: {}", + info!( + is_forwarding = %info.is_forwarding(), + namespace = ?namespace.as_ref(), + host_key = %STANDARD.encode(info.host_key()), + "Confirming request from application: {}", info.process_name(), - info.is_forwarding(), - namespace.clone().unwrap_or_default(), - STANDARD.encode(info.host_key()) ); let mut rx_channel = self.get_ui_response_rx.lock().await.resubscribe(); @@ -172,7 +173,7 @@ impl ssh_agent::Agent connection_info.set_host_key(session_bind_info.host_key.clone()); } SessionBindResult::SignatureFailure => { - println!("[BitwardenDesktopAgent] Session bind failure: Signature failure"); + error!("Session bind failure: Signature failure"); } } } @@ -181,7 +182,7 @@ impl ssh_agent::Agent impl BitwardenDesktopAgent { pub fn stop(&self) { if !self.is_running() { - println!("[BitwardenDesktopAgent] Tried to stop agent while it is not running"); + error!("Tried to stop agent while it is not running"); return; } @@ -227,7 +228,7 @@ impl BitwardenDesktopAgent { ); } Err(e) => { - eprintln!("[SSH Agent Native Module] Error while parsing key: {e}"); + error!(error=%e, "Error while parsing key"); } } } @@ -265,7 +266,7 @@ impl BitwardenDesktopAgent { fn get_request_id(&self) -> u32 { if !self.is_running() { - println!("[BitwardenDesktopAgent] Agent is not running, but tried to get request id"); + error!("Agent is not running, but tried to get request id"); return 0; } diff --git a/apps/desktop/desktop_native/core/src/ssh_agent/named_pipe_listener_stream.rs b/apps/desktop/desktop_native/core/src/ssh_agent/named_pipe_listener_stream.rs index fccd7ca5ed6..cb10e873a33 100644 --- a/apps/desktop/desktop_native/core/src/ssh_agent/named_pipe_listener_stream.rs +++ b/apps/desktop/desktop_native/core/src/ssh_agent/named_pipe_listener_stream.rs @@ -14,6 +14,7 @@ use tokio::{ select, }; use tokio_util::sync::CancellationToken; +use tracing::{error, info}; use windows::Win32::{Foundation::HANDLE, System::Pipes::GetNamedPipeClientProcessId}; use crate::ssh_agent::peerinfo::{self, models::PeerInfo}; @@ -31,42 +32,38 @@ impl NamedPipeServerStream { pub fn new(cancellation_token: CancellationToken, is_running: Arc) -> Self { let (tx, rx) = tokio::sync::mpsc::channel(16); tokio::spawn(async move { - println!( - "[SSH Agent Native Module] Creating named pipe server on {}", - PIPE_NAME - ); + info!("Creating named pipe server on {}", PIPE_NAME); let mut listener = match ServerOptions::new().create(PIPE_NAME) { Ok(pipe) => pipe, - Err(err) => { - println!("[SSH Agent Native Module] Encountered an error creating the first pipe. The system's openssh service must likely be disabled"); - println!("[SSH Agent Natvie Module] error: {}", err); + Err(e) => { + error!(error = %e, "Encountered an error creating the first pipe. The system's openssh service must likely be disabled"); cancellation_token.cancel(); is_running.store(false, Ordering::Relaxed); return; } }; loop { - println!("[SSH Agent Native Module] Waiting for connection"); + info!("Waiting for connection"); select! { _ = cancellation_token.cancelled() => { - println!("[SSH Agent Native Module] Cancellation token triggered, stopping named pipe server"); + info!("[SSH Agent Native Module] Cancellation token triggered, stopping named pipe server"); break; } _ = listener.connect() => { - println!("[SSH Agent Native Module] Incoming connection"); + info!("[SSH Agent Native Module] Incoming connection"); let handle = HANDLE(listener.as_raw_handle()); let mut pid = 0; unsafe { if let Err(e) = GetNamedPipeClientProcessId(handle, &mut pid) { - println!("Error getting named pipe client process id {}", e); + error!(error = %e, pid, "Faile to get named pipe client process id"); continue } }; let peer_info = peerinfo::gather::get_peer_info(pid); let peer_info = match peer_info { - Err(err) => { - println!("Failed getting process info for pid {} {}", pid, err); + Err(e) => { + error!(error = %e, pid = %pid, "Failed getting process info"); continue }, Ok(info) => info, @@ -76,8 +73,8 @@ impl NamedPipeServerStream { listener = match ServerOptions::new().create(PIPE_NAME) { Ok(pipe) => pipe, - Err(err) => { - println!("[SSH Agent Native Module] Encountered an error creating a new pipe {}", err); + Err(e) => { + error!(error = %e, "Encountered an error creating a new pipe"); cancellation_token.cancel(); is_running.store(false, Ordering::Relaxed); return; diff --git a/apps/desktop/desktop_native/core/src/ssh_agent/unix.rs b/apps/desktop/desktop_native/core/src/ssh_agent/unix.rs index 53142d4c476..813ebd61cc1 100644 --- a/apps/desktop/desktop_native/core/src/ssh_agent/unix.rs +++ b/apps/desktop/desktop_native/core/src/ssh_agent/unix.rs @@ -12,6 +12,7 @@ use bitwarden_russh::ssh_agent; use homedir::my_home; use tokio::{net::UnixListener, sync::Mutex}; use tokio_util::sync::CancellationToken; +use tracing::{error, info}; use crate::ssh_agent::peercred_unix_listener_stream::PeercredUnixListenerStream; @@ -36,14 +37,12 @@ impl BitwardenDesktopAgent { let ssh_path = match std::env::var("BITWARDEN_SSH_AUTH_SOCK") { Ok(path) => path, Err(_) => { - println!("[SSH Agent Native Module] BITWARDEN_SSH_AUTH_SOCK not set, using default path"); + info!("BITWARDEN_SSH_AUTH_SOCK not set, using default path"); let ssh_agent_directory = match my_home() { Ok(Some(home)) => home, _ => { - println!( - "[SSH Agent Native Module] Could not determine home directory" - ); + info!("Could not determine home directory"); return; } }; @@ -65,10 +64,10 @@ impl BitwardenDesktopAgent { } }; - println!("[SSH Agent Native Module] Starting SSH Agent server on {ssh_path:?}"); + info!(socket = %ssh_path, "Starting SSH Agent server"); let sockname = std::path::Path::new(&ssh_path); if let Err(e) = std::fs::remove_file(sockname) { - println!("[SSH Agent Native Module] Could not remove existing socket file: {e}"); + error!(error = %e, socket = %ssh_path, "Could not remove existing socket file"); if e.kind() != std::io::ErrorKind::NotFound { return; } @@ -79,7 +78,7 @@ impl BitwardenDesktopAgent { // Only the current user should be able to access the socket if let Err(e) = fs::set_permissions(sockname, fs::Permissions::from_mode(0o600)) { - println!("[SSH Agent Native Module] Could not set socket permissions: {e}"); + error!(error = %e, socket = ?sockname, "Could not set socket permissions"); return; } @@ -100,10 +99,10 @@ impl BitwardenDesktopAgent { cloned_agent_state .is_running .store(false, std::sync::atomic::Ordering::Relaxed); - println!("[SSH Agent Native Module] SSH Agent server exited"); + info!("SSH Agent server exited"); } Err(e) => { - eprintln!("[SSH Agent Native Module] Error while starting agent server: {e}"); + error!(error = %e, socket = %ssh_path, "Unable to start start agent server"); } } }); diff --git a/apps/desktop/desktop_native/napi/Cargo.toml b/apps/desktop/desktop_native/napi/Cargo.toml index 8f2a5cb78a9..2dbb7069b69 100644 --- a/apps/desktop/desktop_native/napi/Cargo.toml +++ b/apps/desktop/desktop_native/napi/Cargo.toml @@ -27,6 +27,8 @@ serde_json = { workspace = true } tokio = { workspace = true } tokio-stream = { workspace = true } tokio-util = { workspace = true } +tracing = { workspace = true } +tracing-subscriber = { workspace = true } [target.'cfg(windows)'.dependencies] windows-registry = { workspace = true } diff --git a/apps/desktop/desktop_native/napi/src/lib.rs b/apps/desktop/desktop_native/napi/src/lib.rs index 24d41bc3831..63523ba5c41 100644 --- a/apps/desktop/desktop_native/napi/src/lib.rs +++ b/apps/desktop/desktop_native/napi/src/lib.rs @@ -823,11 +823,25 @@ pub mod passkey_authenticator { #[napi] pub mod logging { - use log::{Level, Metadata, Record}; + //! `logging` is the interface between the native desktop's usage of the `tracing` crate + //! for logging, to intercept events and write to the JS space. + //! + //! # Example + //! + //! [Elec] 14:34:03.517 › [NAPI] [INFO] desktop_core::ssh_agent::platform_ssh_agent: Starting SSH Agent server {socket=/Users/foo/.bitwarden-ssh-agent.sock} + + use std::fmt::{self, Write}; + use std::sync::OnceLock; + use napi::threadsafe_function::{ ErrorStrategy::CalleeHandled, ThreadsafeFunction, ThreadsafeFunctionCallMode, }; - use std::sync::OnceLock; + use tracing::{ + field::{Field, Visit}, + Level, + }; + use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt, Layer}; + struct JsLogger(OnceLock>); static JS_LOGGER: JsLogger = JsLogger(OnceLock::new()); @@ -840,42 +854,79 @@ pub mod logging { Error, } - impl From for LogLevel { - fn from(level: Level) -> Self { - match level { - Level::Trace => LogLevel::Trace, - Level::Debug => LogLevel::Debug, - Level::Info => LogLevel::Info, - Level::Warn => LogLevel::Warn, - Level::Error => LogLevel::Error, + impl From<&Level> for LogLevel { + fn from(level: &Level) -> Self { + match *level { + Level::TRACE => LogLevel::Trace, + Level::DEBUG => LogLevel::Debug, + Level::INFO => LogLevel::Info, + Level::WARN => LogLevel::Warn, + Level::ERROR => LogLevel::Error, } } } + /// Visitor handles custom formatting for the field names + struct Visitor<'a> { + buffer: &'a mut String, + } + + impl Visit for Visitor<'_> { + fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { + // display the event's message + if field.name() == "message" { + write!(self.buffer, ": {:?}", value) + .expect("Failed to write log event fields to buffer"); + + // all other fields display as "{field_name=field_value}" + } else { + write!(self.buffer, " {{{}={:?}}}", field.name(), value) + .expect("Failed to write log event fields to buffer"); + } + } + } + + // JsLayer lets us intercept events and write them to the JS Logger. + struct JsLayer; + + impl Layer for JsLayer + where + S: tracing::Subscriber, + { + fn on_event( + &self, + event: &tracing::Event<'_>, + _ctx: tracing_subscriber::layer::Context<'_, S>, + ) { + let mut buffer = String::new(); + + write!( + &mut buffer, + "[{}] {}", + event.metadata().level().as_str(), + event.metadata().module_path().unwrap_or_default() + ) + .expect("Failed to write tracing event to buffer"); + + let mut visitor = Visitor { + buffer: &mut buffer, + }; + + event.record(&mut visitor); + + let msg = (event.metadata().level().into(), buffer); + + if let Some(logger) = JS_LOGGER.0.get() { + let _ = logger.call(Ok(msg), ThreadsafeFunctionCallMode::NonBlocking); + }; + } + } + #[napi] pub fn init_napi_log(js_log_fn: ThreadsafeFunction<(LogLevel, String), CalleeHandled>) { let _ = JS_LOGGER.0.set(js_log_fn); - let _ = log::set_logger(&JS_LOGGER); - log::set_max_level(log::LevelFilter::Debug); - } - impl log::Log for JsLogger { - fn enabled(&self, metadata: &Metadata) -> bool { - metadata.level() <= log::max_level() - } - - fn log(&self, record: &Record) { - if !self.enabled(record.metadata()) { - return; - } - let Some(logger) = self.0.get() else { - return; - }; - let msg = (record.level().into(), record.args().to_string()); - let _ = logger.call(Ok(msg), ThreadsafeFunctionCallMode::NonBlocking); - } - - fn flush(&self) {} + tracing_subscriber::registry().with(JsLayer).init(); } }