chore(crypto): Log Olm session identifiers

Co-authored-by: Damir Jelić <poljar@termina.org.uk>

Author: Anderas

Cargo.lock

@@ -40,7 +40,7 @@ thiserror = "1.0.38"
 tracing = { version = "0.1.36", default-features = false, features = ["std"] }
 uniffi = "0.23.0"
 uniffi_bindgen = "0.23.0"
-vodozemac = { git = "https://github.com/matrix-org/vodozemac", rev = "12b24e909107c1fac23245376f294eaf48ba186a" }
+vodozemac = { git = "https://github.com/matrix-org/vodozemac", rev = "fb609ca1e4df5a7a818490ae86ac694119e41e71" }
 zeroize = "1.3.0"
 
 # Default release profile, select with `--release`

Cargo.toml

@@ -31,7 +31,7 @@ use ruma::{
 };
 use serde::{Deserialize, Deserializer, Serialize, Serializer};
 use serde_json::Value;
-use tracing::warn;
+use tracing::{trace, warn};
 use vodozemac::{olm::SessionConfig, Curve25519PublicKey, Ed25519PublicKey};
 
 use super::{atomic_bool_deserializer, atomic_bool_serializer};
@@ -676,6 +676,13 @@ impl ReadOnlyDevice {
 
         let message = session.encrypt(self, event_type, content).await?;
 
+        trace!(
+            user_id = ?self.user_id(),
+            device_id = ?self.device_id(),
+            session_id = session.session_id(),
+            "Successfully encrypted a Megolm session",
+        );
+
         Ok((session, message))
     }
 

crates/matrix-sdk-crypto/src/identities/device.rs

@@ -36,7 +36,7 @@ use ruma::{
 use serde::{Deserialize, Serialize};
 use serde_json::{value::RawValue as RawJsonValue, Value};
 use sha2::{Digest, Sha256};
-use tracing::{debug, info, trace, warn};
+use tracing::{debug, info, instrument, trace, warn, Span};
 use vodozemac::{
     olm::{
         Account as InnerAccount, AccountPickle, IdentityKeys, OlmMessage, PreKeyMessage,
@@ -286,66 +286,80 @@ impl Account {
     }
 
     /// Decrypt an Olm message, creating a new Olm session if possible.
+    #[instrument(skip(self, message), fields(session_id))]
     async fn decrypt_olm_message(
         &self,
         sender: &UserId,
         sender_key: Curve25519PublicKey,
         message: &OlmMessage,
     ) -> OlmResult<(SessionType, DecryptionResult)> {
         // First try to decrypt using an existing session.
-        let (session, plaintext) =
-            if let Some(d) = self.decrypt_with_existing_sessions(sender_key, message).await? {
-                // Decryption succeeded, de-structure the session/plaintext out of
-                // the Option.
-                (SessionType::Existing(d.0), d.1)
-            } else {
-                // Decryption failed with every known session, let's try to create a
-                // new session.
-                match message {
-                    // A new session can only be created using a pre-key message,
-                    // return with an error if it isn't one.
-                    OlmMessage::Normal(_) => {
-                        warn!(
-                            ?sender_key,
-                            "Failed to decrypt a non-pre-key message with all \
-                            available sessions",
-                        );
-
-                        return Err(OlmError::SessionWedged(sender.to_owned(), sender_key));
-                    }
+        let (session, plaintext) = if let Some(d) =
+            self.decrypt_with_existing_sessions(sender_key, message).await?
+        {
+            // Decryption succeeded, de-structure the session/plaintext out of
+            // the Option.
+            (SessionType::Existing(d.0), d.1)
+        } else {
+            // Decryption failed with every known session, let's try to create a
+            // new session.
+            match message {
+                // A new session can only be created using a pre-key message,
+                // return with an error if it isn't one.
+                OlmMessage::Normal(_) => {
+                    let session_ids = if let Some(sessions) =
+                        self.store.get_sessions(&sender_key.to_base64()).await?
+                    {
+                        sessions.lock().await.iter().map(|s| s.session_id().to_owned()).collect()
+                    } else {
+                        vec![]
+                    };
 
-                    OlmMessage::PreKey(m) => {
-                        // Create the new session.
-                        let result = match self.inner.create_inbound_session(sender_key, m).await {
-                            Ok(r) => r,
-                            Err(e) => {
-                                warn!(
-                                    ?sender_key,
-                                    session_keys = ?m.session_keys(),
-                                    "Failed to create a new Olm session from a \
-                                    pre-key message: {e:?}",
-                                );
-                                return Err(OlmError::SessionWedged(sender.to_owned(), sender_key));
-                            }
-                        };
+                    warn!(
+                        ?session_ids,
+                        "Failed to decrypt a non-pre-key message with all available sessions",
+                    );
 
-                        // We need to add the new session to the session cache, otherwise
-                        // we might try to create the same session again.
-                        // TODO separate the session cache from the storage so we only add
-                        // it to the cache but don't store it.
-                        let changes = Changes {
-                            account: Some(self.inner.clone()),
-                            sessions: vec![result.session.clone()],
-                            ..Default::default()
-                        };
-                        self.store.save_changes(changes).await?;
+                    return Err(OlmError::SessionWedged(sender.to_owned(), sender_key));
+                }
 
-                        (SessionType::New(result.session), result.plaintext)
-                    }
+                OlmMessage::PreKey(m) => {
+                    // Create the new session.
+                    let result = match self.inner.create_inbound_session(sender_key, m).await {
+                        Ok(r) => r,
+                        Err(e) => {
+                            warn!(
+                                session_keys = ?m.session_keys(),
+                                "Failed to create a new Olm session from a pre-key message: {e:?}",
+                            );
+
+                            return Err(OlmError::SessionWedged(sender.to_owned(), sender_key));
+                        }
+                    };
+
+                    // We need to add the new session to the session cache, otherwise
+                    // we might try to create the same session again.
+                    // TODO: separate the session cache from the storage so we only add
+                    // it to the cache but don't store it.
+                    let changes = Changes {
+                        account: Some(self.inner.clone()),
+                        sessions: vec![result.session.clone()],
+                        ..Default::default()
+                    };
+                    self.store.save_changes(changes).await?;
+
+                    (SessionType::New(result.session), result.plaintext)
                 }
-            };
+            }
+        };
 
-        trace!(?sender_key, "Successfully decrypted an Olm message");
+        let session_id = match &session {
+            SessionType::New(s) => s.session_id(),
+            SessionType::Existing(s) => s.session_id(),
+        };
+
+        Span::current().record("session_id", session_id);
+        trace!("Successfully decrypted an Olm message");
 
         match self.parse_decrypted_to_device_event(sender, sender_key, plaintext).await {
             Ok(result) => Ok((session, result)),
@@ -368,7 +382,6 @@ impl Account {
                 }
 
                 warn!(
-                    sender_key = sender_key.to_base64(),
                     error = ?e,
                     "A to-device message was successfully decrypted but \
                     parsing and checking the event fields failed"
@@ -1045,22 +1058,28 @@ impl ReadOnlyAccount {
     ///
     /// * `message` - A pre-key Olm message that was sent to us by the other
     /// account.
+    #[instrument(
+        skip_all,
+        fields(
+            sender_key = ?their_identity_key,
+            session_id = message.session_id(),
+            session_keys = ?message.session_keys(),
+        )
+    )]
     pub async fn create_inbound_session(
         &self,
         their_identity_key: Curve25519PublicKey,
         message: &PreKeyMessage,
     ) -> Result<InboundCreationResult, SessionCreationError> {
-        debug!(
-            sender_key = ?their_identity_key,
-            session_keys = ?message.session_keys(),
-            "Creating a new Olm session from a pre-key message"
-        );
+        debug!("Creating a new Olm session from a pre-key message");
 
         let result = self.inner.lock().await.create_inbound_session(their_identity_key, message)?;
 
         let now = SecondsSinceUnixEpoch::now();
         let session_id = result.session.session_id();
 
+        trace!(?session_id, "Olm session created successfully");
+
         let session = Session {
             user_id: self.user_id.clone(),
             device_id: self.device_id.clone(),