1
0
mirror of https://github.com/bitwarden/browser synced 2025-12-06 00:13:28 +00:00

[BEEEP][PM-255518] Use tracing for improved observability (#16321)

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

* feedback dani-garcia: use DefaultVisitor

* set default log level

* convert printlns in objc crate

* convert printlns in autotype crate

* convert printlns in autostart crate

* convert printlns in core/password crate

* convert printlns in core/biometric crate

* convert printlns in napi crate

* convert log usage in macos provider crate

* convert existing log macros to tracing

* fix the cargo.toml sort lint errors

* Revert "fix the cargo.toml sort lint errors"

This reverts commit fd149ab697.

* fix the sort lint using correct cargo sort version

* feedback coltonhurst: more comments/clarity on behavior

* revert changes to ssh_agent
This commit is contained in:
neuronull
2025-09-22 09:56:23 -06:00
committed by GitHub
parent 3bbc6c564c
commit 3f14fdc62d
17 changed files with 226 additions and 73 deletions

View File

@@ -342,6 +342,7 @@ checksum = "ace50bade8e6234aa140d9a2f552bbee1db4d353f69b8217bc503490fc1a9f26"
name = "autotype"
version = "0.0.0"
dependencies = [
"tracing",
"windows 0.61.1",
"windows-core 0.61.0",
]
@@ -448,7 +449,6 @@ dependencies = [
"cbc",
"hex",
"homedir",
"log",
"oo7",
"pbkdf2",
"rand 0.9.1",
@@ -903,7 +903,6 @@ dependencies = [
"interprocess",
"keytar",
"libc",
"log",
"oo7",
"pin-project",
"pkcs8",
@@ -922,6 +921,7 @@ dependencies = [
"tokio",
"tokio-stream",
"tokio-util",
"tracing",
"typenum",
"widestring",
"windows 0.61.1",
@@ -941,7 +941,6 @@ dependencies = [
"bitwarden_chromium_importer",
"desktop_core",
"hex",
"log",
"napi",
"napi-build",
"napi-derive",
@@ -950,6 +949,8 @@ dependencies = [
"tokio",
"tokio-stream",
"tokio-util",
"tracing",
"tracing-subscriber",
"windows-registry",
"windows_plugin_authenticator",
]
@@ -964,6 +965,7 @@ dependencies = [
"glob",
"thiserror 2.0.12",
"tokio",
"tracing",
]
[[package]]
@@ -1796,9 +1798,19 @@ dependencies = [
"serde_json",
"tokio",
"tokio-util",
"tracing",
"uniffi",
]
[[package]]
name = "matchers"
version = "0.2.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "d1525a2a28c7f4fa0fc98bb91ae755d1e2d1505079e05539e35bc876b5d65ae9"
dependencies = [
"regex-automata",
]
[[package]]
name = "md-5"
version = "0.10.6"
@@ -1968,6 +1980,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"
@@ -2971,6 +2992,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"
@@ -3239,6 +3269,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"
@@ -3391,6 +3430,36 @@ 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 = [
"matchers",
"nu-ansi-term",
"once_cell",
"regex-automata",
"sharded-slab",
"smallvec",
"thread_local",
"tracing",
"tracing-core",
"tracing-log",
]
[[package]]
@@ -3611,6 +3680,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 = "vcpkg"
version = "0.2.15"

View File

@@ -62,6 +62,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 = { version = "=0.3.20", features = ["fmt", "env-filter"] }
typenum = "=1.18.0"
uniffi = "=0.28.3"
widestring = "=1.2.0"

View File

@@ -6,6 +6,7 @@ edition.workspace = true
publish.workspace = true
[target.'cfg(windows)'.dependencies]
tracing.workspace = true
windows = { workspace = true, features = [
"Win32_UI_Input_KeyboardAndMouse",
"Win32_UI_WindowsAndMessaging",

View File

@@ -1,6 +1,7 @@
use std::ffi::OsString;
use std::os::windows::ffi::OsStringExt;
use tracing::debug;
use windows::Win32::Foundation::{GetLastError, HWND};
use windows::Win32::UI::Input::KeyboardAndMouse::{
SendInput, INPUT, INPUT_0, INPUT_KEYBOARD, KEYBDINPUT, KEYEVENTF_KEYUP, KEYEVENTF_UNICODE,
@@ -187,7 +188,7 @@ fn send_input(inputs: Vec<INPUT>) -> Result<(), ()> {
let insert_count = unsafe { SendInput(&inputs, std::mem::size_of::<INPUT>() as i32) };
let e = unsafe { GetLastError().to_hresult().message() };
println!("type_input() called, GetLastError() is: {:?}", e);
debug!("type_input() called, GetLastError() is: {:?}", e);
if insert_count == 0 {
return Err(()); // input was blocked by another thread

View File

@@ -14,7 +14,6 @@ base64 = { workspace = true }
cbc = { workspace = true, features = ["alloc"] }
hex = { workspace = true }
homedir = { workspace = true }
log = { workspace = true }
pbkdf2 = "=0.12.2"
rand = { workspace = true }
rusqlite = { version = "=0.35.0", features = ["bundled"] }

View File

@@ -31,7 +31,6 @@ ed25519 = { workspace = true, features = ["pkcs8"] }
futures = { workspace = true }
homedir = { workspace = true }
interprocess = { workspace = true, features = ["tokio"] }
log = { workspace = true }
pin-project = { workspace = true }
pkcs8 = { workspace = true, features = ["alloc", "encryption", "pem"] }
rand = { workspace = true }
@@ -52,6 +51,7 @@ thiserror = { workspace = true }
tokio = { workspace = true, features = ["io-util", "sync", "macros", "net"] }
tokio-stream = { workspace = true, features = ["net"] }
tokio-util = { workspace = true, features = ["codec"] }
tracing = { workspace = true }
typenum = { workspace = true }
zeroizing-alloc = { workspace = true }

View File

@@ -1,5 +1,6 @@
use anyhow::Result;
use ashpd::desktop::background::Background;
use tracing::{error, info};
pub async fn set_autostart(autostart: bool, params: Vec<String>) -> Result<()> {
let request = if params.is_empty() {
@@ -10,11 +11,15 @@ pub async fn set_autostart(autostart: bool, params: Vec<String>) -> Result<()> {
match request.send().await.and_then(|r| r.response()) {
Ok(response) => {
println!("[ASHPD] Autostart enabled: {:?}", response);
info!(
response = ?response,
"[ASHPD] Autostart enabled");
Ok(())
}
Err(err) => {
println!("[ASHPD] Error enabling autostart: {}", err);
error!(
error = %err,
"[ASHPD] Error enabling autostart");
Err(anyhow::anyhow!("error enabling autostart {}", err))
}
}

View File

@@ -4,6 +4,7 @@ use anyhow::Result;
use base64::Engine;
use rand::RngCore;
use sha2::{Digest, Sha256};
use tracing::error;
use crate::biometric::{base64_engine, KeyMaterial, OsDerivedKey};
use zbus::Connection;
@@ -35,7 +36,7 @@ impl super::BiometricTrait for Biometric {
match result {
Ok(result) => Ok(result.is_authorized),
Err(e) => {
println!("polkit biometric error: {:?}", e);
error!( error = %e, "polkit biometric error");
Ok(false)
}
}

View File

@@ -5,21 +5,21 @@ use interprocess::local_socket::{
tokio::{prelude::*, Stream},
GenericFilePath, ToFsName,
};
use log::{error, info};
use tracing::{error, info};
pub async fn connect(
path: PathBuf,
send: tokio::sync::mpsc::Sender<String>,
mut recv: tokio::sync::mpsc::Receiver<String>,
) -> Result<(), Box<dyn std::error::Error>> {
info!("Attempting to connect to {}", path.display());
info!(?path, "Attempting to connect");
let name = path.as_os_str().to_fs_name::<GenericFilePath>()?;
let conn = Stream::connect(name).await?;
let mut conn = crate::ipc::internal_ipc_codec(conn);
info!("Connected to {}", path.display());
info!(?path, "Connected");
// This `connected` and the latter `disconnected` messages are the only ones that
// are sent from the Rust IPC code and not just forwarded from the desktop app.
@@ -46,7 +46,7 @@ pub async fn connect(
res = conn.next() => {
match res {
Some(Err(e)) => {
error!("Error reading from IPC server: {e}");
error!(error = %e, "Error reading from IPC server");
break;
}
None => {

View File

@@ -7,12 +7,12 @@ use futures::{SinkExt, StreamExt, TryFutureExt};
use anyhow::Result;
use interprocess::local_socket::{tokio::prelude::*, GenericFilePath, ListenerOptions};
use log::{error, info};
use tokio::{
io::{AsyncRead, AsyncWrite},
sync::{broadcast, mpsc},
};
use tokio_util::sync::CancellationToken;
use tracing::{error, info};
use super::MESSAGE_CHANNEL_BUFFER;
@@ -143,11 +143,11 @@ async fn listen_incoming(
client_id
);
tokio::spawn(future.map_err(|e| {
error!("Error handling connection: {}", e)
error!(error = %e, "Error handling connection")
}));
},
Err(e) => {
error!("Error accepting connection: {}", e);
error!(error = %e, "Error accepting connection");
break;
},
}
@@ -176,7 +176,7 @@ async fn handle_connection(
loop {
tokio::select! {
_ = cancel_token.cancelled() => {
info!("Client {client_id} cancelled.");
info!(client_id, "Client cancelled.");
break;
},
@@ -187,7 +187,7 @@ async fn handle_connection(
client_stream.send(msg.into()).await?;
},
Err(e) => {
info!("Error reading message: {}", e);
error!(error = %e, "Error reading message");
break;
}
}
@@ -199,7 +199,7 @@ async fn handle_connection(
result = client_stream.next() => {
match result {
Some(Err(e)) => {
info!("Error reading from client {client_id}: {e}");
error!(client_id, error = %e, "Error reading from client");
client_to_server_send.send(Message {
client_id,
@@ -209,7 +209,7 @@ async fn handle_connection(
break;
},
None => {
info!("Client {client_id} disconnected.");
info!(client_id, "Client disconnected.");
client_to_server_send.send(Message {
client_id,

View File

@@ -2,6 +2,7 @@ use crate::password::PASSWORD_NOT_FOUND;
use anyhow::{anyhow, Result};
use oo7::dbus::{self};
use std::collections::HashMap;
use tracing::info;
pub async fn get_password(service: &str, account: &str) -> Result<String> {
match get_password_new(service, account).await {
@@ -27,7 +28,7 @@ async fn get_password_new(service: &str, account: &str) -> Result<String> {
// forces to read via secret service; remvove after 2025.03
async fn get_password_legacy(service: &str, account: &str) -> Result<String> {
println!("falling back to get legacy {} {}", service, account);
info!("falling back to get legacy {} {}", service, account);
let svc = dbus::Service::new().await?;
let collection = svc.default_collection().await?;
let keyring = oo7::Keyring::DBus(collection);
@@ -38,10 +39,7 @@ async fn get_password_legacy(service: &str, account: &str) -> Result<String> {
match res {
Some(res) => {
let secret = res.secret().await?;
println!(
"deleting legacy secret service entry {} {}",
service, account
);
info!(service, account, "deleting legacy secret service entry",);
keyring.delete(&attributes).await?;
let secret_string = String::from_utf8(secret.to_vec())?;
set_password(service, account, &secret_string).await?;
@@ -77,7 +75,7 @@ pub async fn delete_password(service: &str, account: &str) -> Result<()> {
// seems to happen because we call [delete_password] many times when a forced
// de-auth occurs to clean up old keys.
if is_locked().await? {
println!("skipping deletion of old keys. OS keyring is locked.");
info!("skipping deletion of old keys. OS keyring is locked.");
return Ok(());
}
@@ -105,11 +103,11 @@ pub async fn is_locked() -> Result<bool> {
if let Some(item) = items.first() {
return match item.is_locked().await {
Ok(is_locked) => {
println!("OS keyring is locked = {is_locked}");
info!(is_locked, "OS keyring");
Ok(is_locked)
}
Err(_) => {
println!("OS keyring is unlocked");
info!("OS keyring is unlocked");
Ok(false)
}
};

View File

@@ -21,6 +21,7 @@ serde = { workspace = true, features = ["derive"] }
serde_json = { workspace = true }
tokio = { workspace = true, features = ["sync"] }
tokio-util = { workspace = true }
tracing = { workspace = true }
uniffi = { workspace = true, features = ["cli"] }
[target.'cfg(target_os = "macos")'.dependencies]

View File

@@ -7,8 +7,8 @@ use std::{
};
use futures::FutureExt;
use log::{error, info};
use serde::{de::DeserializeOwned, Deserialize, Serialize};
use tracing::{error, info};
uniffi::setup_scaffolding!();
@@ -114,21 +114,21 @@ impl MacOSProviderClient {
match value {
Ok(value) => {
if let Err(e) = cb.complete(value) {
error!("Error deserializing message: {e}");
error!(error = %e, "Error deserializing message");
}
}
Err(e) => {
error!("Error processing message: {e:?}");
error!(error = ?e, "Error processing message");
cb.error(e)
}
}
}
None => {
error!("No callback found for sequence number: {sequence_number}")
error!(sequence_number, "No callback found for sequence number")
}
},
Err(e) => {
error!("Error deserializing message: {e}");
error!(error = %e, "Error deserializing message");
}
};
}

View File

@@ -20,7 +20,6 @@ base64 = { workspace = true }
bitwarden_chromium_importer = { path = "../bitwarden_chromium_importer" }
desktop_core = { path = "../core" }
hex = { workspace = true }
log = { workspace = true }
napi = { workspace = true, features = ["async"] }
napi-derive = { workspace = true }
serde = { workspace = true, features = ["derive"] }
@@ -28,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 }

View File

@@ -175,6 +175,7 @@ pub mod sshagent {
threadsafe_function::{ErrorStrategy::CalleeHandled, ThreadsafeFunction},
};
use tokio::{self, sync::Mutex};
use tracing::error;
#[napi]
pub struct SshAgentState {
@@ -242,7 +243,7 @@ pub mod sshagent {
.expect("should be able to send auth response to agent");
}
Err(e) => {
println!("[SSH Agent Native Module] calling UI callback promise was rejected: {e}");
error!(error = %e, "Calling UI callback promise was rejected");
let _ = auth_response_tx_arc
.lock()
.await
@@ -251,7 +252,7 @@ pub mod sshagent {
}
},
Err(e) => {
println!("[SSH Agent Native Module] calling UI callback could not create promise: {e}");
error!(error = %e, "Calling UI callback could not create promise");
let _ = auth_response_tx_arc
.lock()
.await
@@ -513,6 +514,7 @@ pub mod autofill {
ErrorStrategy, ThreadsafeFunction, ThreadsafeFunctionCallMode,
};
use serde::{de::DeserializeOwned, Deserialize, Serialize};
use tracing::error;
#[napi]
pub async fn run_command(value: String) -> napi::Result<String> {
@@ -668,7 +670,7 @@ pub mod autofill {
MessageType::Connected | MessageType::Disconnected => continue,
MessageType::Message => {
let Some(message) = message else {
println!("[ERROR] Message is empty");
error!("Message is empty");
continue;
};
@@ -686,7 +688,7 @@ pub mod autofill {
continue;
}
Err(e) => {
println!("[ERROR] Error deserializing message1: {e}");
error!(error = %e, "Error deserializing message1");
}
}
@@ -705,7 +707,7 @@ pub mod autofill {
continue;
}
Err(e) => {
println!("[ERROR] Error deserializing message1: {e}");
error!(error = %e, "Error deserializing message1");
}
}
@@ -722,11 +724,11 @@ pub mod autofill {
continue;
}
Err(e) => {
println!("[ERROR] Error deserializing message2: {e}");
error!(error = %e, "Error deserializing message2");
}
}
println!("[ERROR] Received an unknown message2: {message:?}");
error!(message, "Received an unknown message2");
}
}
}
@@ -823,11 +825,28 @@ 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::Write;
use std::sync::OnceLock;
use napi::threadsafe_function::{
ErrorStrategy::CalleeHandled, ThreadsafeFunction, ThreadsafeFunctionCallMode,
};
use std::sync::OnceLock;
use tracing::Level;
use tracing_subscriber::fmt::format::{DefaultVisitor, Writer};
use tracing_subscriber::{
filter::{EnvFilter, LevelFilter},
layer::SubscriberExt,
util::SubscriberInitExt,
Layer,
};
struct JsLogger(OnceLock<ThreadsafeFunction<(LogLevel, String), CalleeHandled>>);
static JS_LOGGER: JsLogger = JsLogger(OnceLock::new());
@@ -840,42 +859,86 @@ 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,
}
}
}
// JsLayer lets us intercept events and write them to the JS Logger.
struct JsLayer;
impl<S> Layer<S> for JsLayer
where
S: tracing::Subscriber,
{
// This function builds a log message buffer from the event data and
// calls the JS logger with it.
//
// For example, this log call:
//
// ```
// mod supreme {
// mod module {
// let foo = "bar";
// info!(best_variable_name = %foo, "Foo done it again.");
// }
// }
// ```
//
// , results in the following string:
//
// [INFO] supreme::module: Foo done it again. {best_variable_name=bar}
fn on_event(
&self,
event: &tracing::Event<'_>,
_ctx: tracing_subscriber::layer::Context<'_, S>,
) {
let mut buffer = String::new();
// create the preamble text that precedes the message and vars. e.g.:
// [INFO] desktop_core::ssh_agent::platform_ssh_agent:
let level = event.metadata().level().as_str();
let module_path = event.metadata().module_path().unwrap_or_default();
write!(&mut buffer, "[{level}] {module_path}:")
.expect("Failed to write tracing event to buffer");
let writer = Writer::new(&mut buffer);
// DefaultVisitor adds the message and variables to the buffer
let mut visitor = DefaultVisitor::new(writer, false);
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()
}
let filter = EnvFilter::builder()
// set the default log level to INFO.
.with_default_directive(LevelFilter::INFO.into())
// parse directives from the RUST_LOG environment variable,
// overriding the default directive for matching targets.
.from_env_lossy();
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(filter)
.with(JsLayer)
.init();
}
}

View File

@@ -12,6 +12,7 @@ default = []
anyhow = { workspace = true }
thiserror = { workspace = true }
tokio = { workspace = true }
tracing = { workspace = true }
[target.'cfg(target_os = "macos")'.dependencies]
core-foundation = "=0.10.1"

View File

@@ -66,6 +66,8 @@ impl Drop for ObjCString {
mod objc {
use std::os::raw::c_void;
use tracing::error;
use super::*;
unsafe extern "C" {
@@ -79,8 +81,9 @@ mod objc {
let value: String = match value.try_into() {
Ok(value) => value,
Err(e) => {
println!(
"Error: Failed to convert ObjCString to Rust string during commandReturn: {e}"
error!(
error = %e,
"Error: Failed to convert ObjCString to Rust string during commandReturn"
);
return false;
@@ -90,7 +93,9 @@ mod objc {
match context.send(value) {
Ok(_) => 0,
Err(e) => {
println!("Error: Failed to return ObjCString from ObjC code to Rust code: {e}");
error!(
error = %e,
"Error: Failed to return ObjCString from ObjC code to Rust code");
return false;
}