diff --git a/Cargo.lock b/Cargo.lock index 222c55f952..41eb6ab0e3 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -987,8 +987,10 @@ dependencies = [ "serde_json", "sha2", "strum", + "testing_logger", "thiserror 1.0.69", "tls_codec", + "tokio", "uniffi", "wasm-bindgen", "wasm-bindgen-futures", @@ -4726,6 +4728,15 @@ dependencies = [ "winapi-util", ] +[[package]] +name = "testing_logger" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6d92b727cb45d33ae956f7f46b966b25f1bc712092aeef9dba5ac798fc89f720" +dependencies = [ + "log", +] + [[package]] name = "textwrap" version = "0.16.1" diff --git a/Cargo.toml b/Cargo.toml index 9d49ff7b8d..9f63b7050c 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -32,7 +32,7 @@ hex = "0.4" idb = "0.6" indexmap = "2" itertools = "0.13" -log = { version = "0.4", features = ["kv_unstable_serde"] } +log = { version = "0.4", features = ["kv_serde"] } log-reload = "0.1.0" mls-crypto-provider = { path = "mls-provider" } pem = "3.0" diff --git a/crypto-ffi/Cargo.toml b/crypto-ffi/Cargo.toml index 63bbd17e47..dd2783c56c 100644 --- a/crypto-ffi/Cargo.toml +++ b/crypto-ffi/Cargo.toml @@ -18,7 +18,12 @@ required-features = ["uniffi/cli"] [features] default = ["proteus"] -proteus = ["core-crypto/proteus", "core-crypto/cryptobox-migrate", "dep:proteus-wasm", "dep:core-crypto-keystore"] +proteus = [ + "core-crypto/proteus", + "core-crypto/cryptobox-migrate", + "dep:proteus-wasm", + "dep:core-crypto-keystore", +] [dependencies] thiserror.workspace = true @@ -32,7 +37,7 @@ log-reload.workspace = true serde_json.workspace = true derive_more.workspace = true proteus-wasm = { workspace = true, optional = true } -core-crypto-keystore = { workspace = true, optional = true} +core-crypto-keystore = { workspace = true, optional = true } # see https://github.com/RustCrypto/hashes/issues/404 [target.'cfg(not(any(target_arch = "aarch64", target_arch = "x86_64", target_arch = "x86")))'.dependencies] @@ -69,7 +74,18 @@ wasm-bindgen-test = "0.3" wasm-opt = false [package.metadata.wasm-pack.profile.release] -wasm-opt = ["-Os", "--enable-mutable-globals", "--enable-threads", "--detect-features"] +wasm-opt = [ + "-Os", + "--enable-mutable-globals", + "--enable-threads", + "--detect-features", +] [lints.rust] -unexpected_cfgs = { level = "warn", check-cfg = ['cfg(wasm_bindgen_unstable_test_coverage)'] } +unexpected_cfgs = { level = "warn", check-cfg = [ + 'cfg(wasm_bindgen_unstable_test_coverage)', +] } + +[dev-dependencies] +testing_logger = "0.1.1" +tokio = { version = "1.43.0", default-features = false, features = ["macros", "rt"] } diff --git a/crypto-ffi/src/generic/mod.rs b/crypto-ffi/src/generic/mod.rs index 492f1759c8..fd954dfd0a 100644 --- a/crypto-ffi/src/generic/mod.rs +++ b/crypto-ffi/src/generic/mod.rs @@ -22,7 +22,7 @@ use std::{ }; use log::{ - kv::{self, Key, Value, Visitor}, + kv::{self, Key, Value, VisitSource}, Level, LevelFilter, Metadata, Record, }; use log_reload::ReloadLog; @@ -202,8 +202,39 @@ pub enum CoreCryptoError { Other(String), } +/// Prepare and dispatch a log message reporting this error. +/// +/// We want to ensure consistent logging every time we pass a log message across the FFI boundary, +/// as we cannot guarantee the method, format, or existence of error logging once the result crosses. +/// Unfortunately, as there is no single point at which we convert internal errors to trans-ffi +/// errors, we need to extract the logging procedure and ensure it's called at each relevant point. +/// +/// This has the further disadvantage that we have very little context information at the point of +/// logging. We'll try this out for now anyway; if it turns out that we need to add more tracing +/// in the future, we can figure out our techniques then. +fn log_error(error: &dyn std::error::Error) { + // we exclude the original error message from the chain + let chain = { + let mut error = error; + let mut chain = Vec::new(); + while let Some(inner) = error.source() { + chain.push(inner.to_string()); + error = inner; + } + chain + }; + let msg = error.to_string(); + let err = serde_json::json!({"msg": msg, "chain": chain}); + // even though there exists a `:err` formatter, it only captures the top-level + // message from the error, so it's still worth building our own inner error formatter + // and using serde here + log::warn!(target: "core-crypto", err:serde; "core-crypto returning this error across ffi; see recent log messages for context"); +} + impl From for CoreCryptoError { fn from(error: RecursiveError) -> Self { + log_error(&error); + // check if the innermost error is any kind of e2e error let innermost = { let mut err: &dyn std::error::Error = &error; @@ -279,6 +310,8 @@ impl From for CoreCryptoError { // When we redesign the errors in `core-crypto`, these ambiguities should disappear anyway. impl From for CoreCryptoError { fn from(error: core_crypto::Error) -> Self { + log_error(&error); + // we can take care of the _simple_ error-mapping up here. #[cfg(feature = "proteus")] if let core_crypto::Error::Proteus(proteus) = &error { @@ -981,7 +1014,7 @@ pub trait CoreCryptoLogger: std::fmt::Debug + Send + Sync { struct KeyValueVisitor<'kvs>(BTreeMap, Value<'kvs>>); -impl<'kvs> Visitor<'kvs> for KeyValueVisitor<'kvs> { +impl<'kvs> VisitSource<'kvs> for KeyValueVisitor<'kvs> { #[inline] fn visit_pair(&mut self, key: Key<'kvs>, value: Value<'kvs>) -> Result<(), kv::Error> { self.0.insert(key, value); @@ -2320,4 +2353,24 @@ mod tests { CoreCryptoError::Mls(MlsError::ConversationAlreadyExists(_)) )); } + + #[tokio::test] + async fn test_error_is_logged() { + testing_logger::setup(); + // we shouldn't be able to create a SQLite DB in `/root` unless we are running this test as root + // Don't do that! + let result = CoreCrypto::new("/root/asdf".into(), "key".into(), None, None, None).await; + assert!( + result.is_err(), + "result must be an error in order to verify that something was logged" + ); + testing_logger::validate(|captured_logs| { + assert!( + captured_logs.iter().any(|log| log.level == Level::Warn + && log.target == "core-crypto" + && log.body.contains("returning this error across ffi")), + "log message did not appear within the captured logs" + ) + }); + } } diff --git a/crypto-ffi/src/wasm/mod.rs b/crypto-ffi/src/wasm/mod.rs index 0898897595..cbf0f34e4b 100644 --- a/crypto-ffi/src/wasm/mod.rs +++ b/crypto-ffi/src/wasm/mod.rs @@ -28,7 +28,7 @@ use core_crypto::{prelude::*, InnermostErrorMessage, MlsTransportResponse}; use futures_util::future::TryFutureExt; use js_sys::{Promise, Uint8Array}; use log::{ - kv::{self, Key, Value, Visitor}, + kv::{self, Key, Value, VisitSource}, Level, LevelFilter, Metadata, Record, }; use log_reload::ReloadLog; @@ -206,8 +206,40 @@ pub(crate) enum InternalError { Other(String), } +/// Prepare and dispatch a log message reporting this error. +/// +/// We want to ensure consistent logging every time we pass a log message across the FFI boundary, +/// as we cannot guarantee the method, format, or existence of error logging once the result crosses. +/// In this case there is a single point at which we convert internal errors to trans-ffi +/// errors, but it was still convenient to extract the logging procedure, because that point is +/// within a macro-generated `From` impl. +/// +/// This has the further disadvantage that we have very little context information at the point of +/// logging. We'll try this out for now anyway; if it turns out that we need to add more tracing +/// in the future, we can figure out our techniques then. +fn log_error(error: &dyn std::error::Error) { + // we exclude the original error message from the chain + let chain = { + let mut error = error; + let mut chain = Vec::new(); + while let Some(inner) = error.source() { + chain.push(inner.to_string()); + error = inner; + } + chain + }; + let msg = error.to_string(); + let err = serde_json::json!({"msg": msg, "chain": chain}); + // even though there exists a `:err` formatter, it only captures the top-level + // message from the error, so it's still worth building our own inner error formatter + // and using serde here + log::warn!(target: "core-crypto", err:serde; "core-crypto returning this error across ffi; see recent log messages for context"); +} + impl From for InternalError { fn from(error: RecursiveError) -> Self { + log_error(&error); + // check if the innermost error is any kind of e2e error let innermost = { let mut err: &dyn std::error::Error = &error; @@ -283,6 +315,8 @@ impl From for InternalError { // When we redesign the errors in `core-crypto`, these ambiguities should disappear anyway. impl From for InternalError { fn from(error: core_crypto::Error) -> Self { + log_error(&error); + // we can take care of the _simple_ error-mapping up here. #[cfg(feature = "proteus")] if let core_crypto::Error::Proteus(proteus) = &error { @@ -1188,7 +1222,7 @@ impl From for CoreCryptoLogLevel { struct KeyValueVisitor<'kvs>(BTreeMap, Value<'kvs>>); -impl<'kvs> Visitor<'kvs> for KeyValueVisitor<'kvs> { +impl<'kvs> VisitSource<'kvs> for KeyValueVisitor<'kvs> { #[inline] fn visit_pair(&mut self, key: Key<'kvs>, value: Value<'kvs>) -> Result<(), kv::Error> { self.0.insert(key, value);