bitwarden/browser
1
0
Fork 0
mirror of https://github.com/bitwarden/browser synced 2026-02-08 20:50:28 +00:00
Code Issues Releases Wiki Activity

[BEEEP][PM-255518] Use tracing for improved observability

Browse Source
This commit is contained in:
neuronull
2025-09-05 15:08:51 -06:00
parent 048d8a5f79
commit 7e0fd185bb
8 changed files with 180 additions and 65 deletions
Download Patch File Download Diff File Expand all files Collapse all files

62
apps/desktop/desktop_native/Cargo.lock generated
View File

@@ -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"

2
apps/desktop/desktop_native/Cargo.toml
View File

@@ -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"

1
apps/desktop/desktop_native/core/Cargo.toml
View File

@@ -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"] }

23
apps/desktop/desktop_native/core/src/ssh_agent/mod.rs
View File

@@ -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<peerinfo::models::PeerInfo, BitwardenSshKey>
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<peerinfo::models::PeerInfo, BitwardenSshKey>
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<peerinfo::models::PeerInfo, BitwardenSshKey>
_ => 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<peerinfo::models::PeerInfo, BitwardenSshKey>
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<peerinfo::models::PeerInfo, BitwardenSshKey>
impl BitwardenDesktopAgent<BitwardenSshKey> {
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<BitwardenSshKey> {
);
}
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<BitwardenSshKey> {
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;
}

27
apps/desktop/desktop_native/core/src/ssh_agent/named_pipe_listener_stream.rs
View File

@@ -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<AtomicBool>) -> 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;

17
apps/desktop/desktop_native/core/src/ssh_agent/unix.rs
View File

@@ -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<BitwardenSshKey> {
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<BitwardenSshKey> {
}
};
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<BitwardenSshKey> {
// 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<BitwardenSshKey> {
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");
}
}
});

2
apps/desktop/desktop_native/napi/Cargo.toml
View File

@@ -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 }

111
apps/desktop/desktop_native/napi/src/lib.rs
View File

@@ -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<ThreadsafeFunction<(LogLevel, String), CalleeHandled>>);
static JS_LOGGER: JsLogger = JsLogger(OnceLock::new());
@@ -840,42 +854,79 @@ pub mod logging {
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,
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<S> Layer<S> 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();
}
}