From 35a0f3af252bb10e54f08966ee716ce2e2373963 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Damir=20Jeli=C4=87?= Date: Mon, 17 Apr 2023 11:24:57 +0200 Subject: [PATCH] crypto: Improve some logs around Olm decryption and encryption --- Cargo.lock | 2 +- Cargo.toml | 2 +- .../src/identities/device.rs | 28 ++++++------- crates/matrix-sdk-crypto/src/olm/account.rs | 40 +++++++++---------- crates/matrix-sdk-crypto/src/olm/session.rs | 19 +++++++-- 5 files changed, 50 insertions(+), 41 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 6ecee5a47..98691451c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5732,7 +5732,7 @@ checksum = "49874b5167b65d7193b8aba1567f5c7d93d001cafc34600cee003eda787e483f" [[package]] name = "vodozemac" version = "0.3.0" -source = "git+https://github.com/matrix-org/vodozemac?rev=a6f62ef7fbd9bb58d0d888b743d9239967c63da3#a6f62ef7fbd9bb58d0d888b743d9239967c63da3" +source = "git+https://github.com/matrix-org/vodozemac?rev=2203c921139766edaa2972c541959b6d4d03ba9f#2203c921139766edaa2972c541959b6d4d03ba9f" dependencies = [ "aes", "arrayvec", diff --git a/Cargo.toml b/Cargo.toml index 0db1c2d96..9cd78cd43 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -44,7 +44,7 @@ tracing = { version = "0.1.36", default-features = false, features = ["std"] } tracing-core = "0.1.30" uniffi = { git = "https://github.com/mozilla/uniffi-rs", rev = "75b9df455d1b67d25291c09634ff22160e4abcbf" } uniffi_bindgen = { git = "https://github.com/mozilla/uniffi-rs", rev = "75b9df455d1b67d25291c09634ff22160e4abcbf" } -vodozemac = { git = "https://github.com/matrix-org/vodozemac", rev = "a6f62ef7fbd9bb58d0d888b743d9239967c63da3" } +vodozemac = { git = "https://github.com/matrix-org/vodozemac", rev = "2203c921139766edaa2972c541959b6d4d03ba9f" } zeroize = "1.3.0" # Default release profile, select with `--release` diff --git a/crates/matrix-sdk-crypto/src/identities/device.rs b/crates/matrix-sdk-crypto/src/identities/device.rs index 0153b9483..b86068510 100644 --- a/crates/matrix-sdk-crypto/src/identities/device.rs +++ b/crates/matrix-sdk-crypto/src/identities/device.rs @@ -32,7 +32,7 @@ use ruma::{ use serde::{Deserialize, Deserializer, Serialize, Serializer}; use serde_json::Value; use tokio::sync::Mutex; -use tracing::{trace, warn}; +use tracing::{instrument, trace, warn}; use vodozemac::{olm::SessionConfig, Curve25519PublicKey, Ed25519PublicKey}; use super::{atomic_bool_deserializer, atomic_bool_serializer}; @@ -432,6 +432,16 @@ impl Device { /// # Arguments /// /// * `content` - The content of the event that should be encrypted. + #[instrument( + skip_all, + fields( + recipient = %self.user_id(), + recipient_device = %self.device_id(), + recipient_key = ?self.curve25519_key(), + event_type, + session, + )) + ] pub(crate) async fn encrypt( &self, event_type: &str, @@ -694,8 +704,6 @@ impl ReadOnlyDevice { } } else { warn!( - user_id = ?self.user_id(), - device_id = ?self.device_id(), "Trying to find a Olm session of a device, but the device doesn't have a \ Curve25519 key", ); @@ -777,21 +785,11 @@ impl ReadOnlyDevice { if let Some(mut session) = session { 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", - ); + trace!("Successfully encrypted an event"); Ok((session, message)) } else { - warn!( - "Trying to encrypt a Megolm session for user {} on device {}, \ - but no Olm session is found", - self.user_id(), - self.device_id() - ); + warn!("Trying to encrypt an event for a device, but no Olm session is found.",); Err(OlmError::MissingSession) } diff --git a/crates/matrix-sdk-crypto/src/olm/account.rs b/crates/matrix-sdk-crypto/src/olm/account.rs index aa167feb1..106383e16 100644 --- a/crates/matrix-sdk-crypto/src/olm/account.rs +++ b/crates/matrix-sdk-crypto/src/olm/account.rs @@ -36,7 +36,7 @@ use serde::{Deserialize, Serialize}; use serde_json::{value::RawValue as RawJsonValue, Value}; use sha2::{Digest, Sha256}; use tokio::sync::Mutex; -use tracing::{debug, info, instrument, trace, warn, Span}; +use tracing::{debug, field::debug, info, instrument, trace, warn, Span}; use vodozemac::{ olm::{ Account as InnerAccount, AccountPickle, IdentityKeys, OlmMessage, @@ -191,16 +191,14 @@ impl Account { self.decrypt_olm_helper(sender, content.sender_key, &content.ciphertext).await } + #[instrument(skip_all, fields(sender, sender_key = %content.sender_key))] async fn decrypt_olm_v1( &self, sender: &UserId, content: &OlmV1Curve25519AesSha2Content, ) -> OlmResult { if content.recipient_key != self.identity_keys().curve25519 { - warn!( - sender_key = content.sender_key.to_base64(), - "Olm event doesn't contain a ciphertext for our key" - ); + warn!("Olm event doesn't contain a ciphertext for our key"); Err(EventError::MissingCiphertext.into()) } else { @@ -208,11 +206,12 @@ impl Account { } } + #[instrument(skip_all, fields(algorithm = ?event.content.algorithm()))] pub(crate) async fn decrypt_to_device_event( &self, event: &EncryptedToDeviceEvent, ) -> OlmResult { - trace!(algorithm = ?event.content.algorithm(), "Decrypting a to-device event"); + trace!("Decrypting a to-device event"); match &event.content { ToDeviceEncryptedEventContent::OlmV1Curve25519AesSha2(c) => { @@ -224,7 +223,6 @@ impl Account { } ToDeviceEncryptedEventContent::Unknown(_) => { warn!( - algorithm = ?event.content.algorithm(), "Error decrypting an to-device event, unsupported \ encryption algorithm" ); @@ -287,7 +285,7 @@ impl Account { } /// Decrypt an Olm message, creating a new Olm session if possible. - #[instrument(skip(self, message), fields(session_id))] + #[instrument(skip(self, message))] async fn decrypt_olm_message( &self, sender: &UserId, @@ -328,12 +326,7 @@ impl Account { // 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:?}", - ); - + Err(_) => { return Err(OlmError::SessionWedged(sender.to_owned(), sender_key)); } }; @@ -1086,12 +1079,9 @@ impl ReadOnlyAccount { #[instrument( skip_all, fields( - sender_key = ?their_identity_key, + message, session_id = message.session_id(), - session_keys = ?message.session_keys(), - chain_index = message.message().chain_index(), - message_version = message.message().version(), - ratchet_key = %message.message().ratchet_key(), + session, ) )] pub async fn create_inbound_session( @@ -1101,12 +1091,20 @@ impl ReadOnlyAccount { ) -> Result { 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 result = + self.inner.lock().await.create_inbound_session(their_identity_key, message).map_err( + |e| { + warn!("Failed to create a new Olm session from a pre-key message: {e:?}"); + e + }, + )?; let now = SecondsSinceUnixEpoch::now(); let session_id = result.session.session_id(); - trace!(?session_id, "Olm session created successfully"); + Span::current().record("session", debug(&result.session)); + + trace!("Olm session created successfully"); let session = Session { user_id: self.user_id.clone(), diff --git a/crates/matrix-sdk-crypto/src/olm/session.rs b/crates/matrix-sdk-crypto/src/olm/session.rs index b31ddf111..d1004a5e2 100644 --- a/crates/matrix-sdk-crypto/src/olm/session.rs +++ b/crates/matrix-sdk-crypto/src/olm/session.rs @@ -18,6 +18,7 @@ use ruma::{serde::Raw, OwnedDeviceId, OwnedUserId, SecondsSinceUnixEpoch}; use serde::{Deserialize, Serialize}; use serde_json::{json, Value}; use tokio::sync::Mutex; +use tracing::{field::debug, instrument, trace, Span}; use vodozemac::{ olm::{DecryptionError, OlmMessage, Session as InnerSession, SessionConfig, SessionPickle}, Curve25519PublicKey, @@ -78,10 +79,18 @@ impl Session { /// # Arguments /// /// * `message` - The Olm message that should be decrypted. + #[instrument(skip_all, fields(session))] pub async fn decrypt(&mut self, message: &OlmMessage) -> Result { - let plaintext = self.inner.lock().await.decrypt(message)?; + let mut inner = self.inner.lock().await; + let plaintext = inner.decrypt(message)?; + + Span::current().record("session", debug(inner)); + trace!("Decrypted a Olm message"); + let plaintext = String::from_utf8_lossy(&plaintext).to_string(); + self.last_use_time = SecondsSinceUnixEpoch::now(); + Ok(plaintext) } @@ -116,7 +125,11 @@ impl Session { /// /// * `plaintext` - The plaintext that should be encrypted. pub(crate) async fn encrypt_helper(&mut self, plaintext: &str) -> OlmMessage { - let message = self.inner.lock().await.encrypt(plaintext); + let mut session = self.inner.lock().await; + + Span::current().record("session", debug(&session)); + let message = session.encrypt(plaintext); + self.last_use_time = SecondsSinceUnixEpoch::now(); message } @@ -178,7 +191,7 @@ impl Session { _ => unreachable!(), }; - let content = Raw::new(&content).expect("A encrypted can always be serialized"); + let content = Raw::new(&content)?; Ok(content) }