feat: log errors at ffi boundary [WPB-14355]

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"

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

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<RecursiveError> 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<RecursiveError> for CoreCryptoError {
 // When we redesign the errors in `core-crypto`, these ambiguities should disappear anyway.
 impl From<core_crypto::Error> 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<Key<'kvs>, 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"
+            )
+        });
+    }
 }

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<RecursiveError> 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<RecursiveError> for InternalError {
 // When we redesign the errors in `core-crypto`, these ambiguities should disappear anyway.
 impl From<core_crypto::Error> 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<Level> for CoreCryptoLogLevel {
 
 struct KeyValueVisitor<'kvs>(BTreeMap<Key<'kvs>, 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);