From 0ee8d2733ae5cc9018beb84fe8218eaa0f1d8d7c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Damir=20Jeli=C4=87?= Date: Fri, 22 Oct 2021 16:00:42 +0200 Subject: [PATCH] fix(crypto): Improve the log lines for the room key encryption flow --- .../src/olm/group_sessions/outbound.rs | 12 ++- .../src/session_manager/group_sessions.rs | 83 ++++++++++------- .../src/session_manager/sessions.rs | 89 ++++++++++++------- crates/matrix-sdk-crypto/src/store/mod.rs | 27 +++++- 4 files changed, 143 insertions(+), 68 deletions(-) diff --git a/crates/matrix-sdk-crypto/src/olm/group_sessions/outbound.rs b/crates/matrix-sdk-crypto/src/olm/group_sessions/outbound.rs index 98d46dcdc..71944d6ce 100644 --- a/crates/matrix-sdk-crypto/src/olm/group_sessions/outbound.rs +++ b/crates/matrix-sdk-crypto/src/olm/group_sessions/outbound.rs @@ -14,7 +14,7 @@ use std::{ cmp::max, - collections::BTreeMap, + collections::{BTreeMap, BTreeSet}, fmt, sync::{ atomic::{AtomicBool, AtomicU64, Ordering}, @@ -47,7 +47,7 @@ use ruma::{ }; use serde::{Deserialize, Serialize}; use serde_json::{json, Value}; -use tracing::{debug, error, trace}; +use tracing::{debug, error, info}; use super::{ super::{deserialize_instant, serialize_instant}, @@ -211,8 +211,12 @@ impl OutboundGroupSession { /// users/devices that received the session. pub fn mark_request_as_sent(&self, request_id: &Uuid) { if let Some((_, (_, r))) = self.to_share_with_set.remove(request_id) { - trace!( - request_id = request_id.to_string().as_str(), + let recipients: BTreeMap<&UserId, BTreeSet<&DeviceId>> = + r.iter().map(|(u, d)| (u, d.keys().map(|d| d.as_ref()).collect())).collect(); + + info!( + ?request_id, + ?recipients, "Marking to-device request carrying a room key as sent" ); diff --git a/crates/matrix-sdk-crypto/src/session_manager/group_sessions.rs b/crates/matrix-sdk-crypto/src/session_manager/group_sessions.rs index d0e312438..ec2d69ae0 100644 --- a/crates/matrix-sdk-crypto/src/session_manager/group_sessions.rs +++ b/crates/matrix-sdk-crypto/src/session_manager/group_sessions.rs @@ -159,11 +159,7 @@ impl GroupSessionManager { content: Value, event_type: &str, ) -> MegolmResult { - let session = if let Some(s) = self.sessions.get(room_id) { - s - } else { - panic!("Session wasn't created nor shared"); - }; + let session = self.sessions.get(room_id).expect("Session wasn't created nor shared"); assert!(!session.expired(), "Session expired"); @@ -320,10 +316,11 @@ impl GroupSessionManager { let users: HashSet<&UserId> = users.collect(); let mut devices: HashMap> = HashMap::new(); - debug!( + trace!( users = ?users, history_visibility = ?history_visibility, session_id = outbound.session_id(), + room_id = outbound.room_id().as_str(), "Calculating group session recipients" ); @@ -386,9 +383,10 @@ impl GroupSessionManager { devices.entry(user_id.clone()).or_insert_with(Vec::new).extend(non_blacklisted_devices); } - debug!( + trace!( should_rotate = should_rotate, session_id = outbound.session_id(), + room_id = outbound.room_id().as_str(), "Done calculating group session recipients" ); @@ -434,7 +432,7 @@ impl GroupSessionManager { users: impl Iterator, encryption_settings: impl Into, ) -> OlmResult>> { - debug!(room_id = room_id.as_str(), "Checking if a room key needs to be shared",); + trace!(room_id = room_id.as_str(), "Checking if a room key needs to be shared",); let encryption_settings = encryption_settings.into(); let history_visibility = encryption_settings.history_visibility.clone(); @@ -463,8 +461,8 @@ impl GroupSessionManager { room_id = room_id.as_str(), old_session_id = old_session_id, session_id = outbound.session_id(), - "A user/device has left the group since we last sent a message, \ - rotating the outbound session.", + "A user or device has left the room since we last sent a \ + message, rotating the room key.", ); outbound @@ -485,16 +483,17 @@ impl GroupSessionManager { let message_index = outbound.message_index().await; if !devices.is_empty() { - let users = devices.iter().fold(BTreeMap::new(), |mut acc, d| { + let recipients = devices.iter().fold(BTreeMap::new(), |mut acc, d| { acc.entry(d.user_id()).or_insert_with(BTreeSet::new).insert(d.device_id()); acc }); info!( index = message_index, - users = ?users, + recipients = ?recipients, room_id = room_id.as_str(), - "Sharing an outbound group session", + session_id = outbound.session_id(), + "Trying to encrypt a room key", ); } @@ -519,33 +518,53 @@ impl GroupSessionManager { let requests = outbound.pending_requests(); - debug!( - room_id = room_id.as_str(), - session_id = outbound.session_id(), - request_count = requests.len(), - "Done generating to-device requests for a room key share" - ); - if requests.is_empty() { - debug!( + if !outbound.shared() { + debug!( + room_id = room_id.as_str(), + session_id = outbound.session_id(), + "The room key doesn't need to be shared with anyone. Marking as shared." + ); + + outbound.mark_as_shared(); + changes.outbound_group_sessions.push(outbound.clone()); + } + } else { + let mut recipients: BTreeMap<&UserId, BTreeSet<&DeviceIdOrAllDevices>> = + BTreeMap::new(); + + for request in &requests { + for (user_id, device_map) in &request.messages { + let devices = device_map.keys(); + recipients.entry(user_id).or_default().extend(devices) + } + } + + let transaction_ids: Vec = requests.iter().map(|r| r.txn_id).collect(); + + // TODO log the withheld reasons here as well. + info!( room_id = room_id.as_str(), session_id = outbound.session_id(), - "The outbound group session doesn't need to be shared with \ - anyone, marking as shared", + request_count = requests.len(), + ?transaction_ids, + ?recipients, + "Encrypted a room key and created to-device requests" ); - outbound.mark_as_shared(); } - let session_count = changes.sessions.len(); + if !changes.is_empty() { + let session_count = changes.sessions.len(); - self.store.save_changes(changes).await?; + self.store.save_changes(changes).await?; - debug!( - room_id = room_id.as_str(), - session_id = outbound.session_id(), - session_count = session_count, - "Stored the changed sessions after encrypting an room key" - ); + trace!( + room_id = room_id.as_str(), + session_id = outbound.session_id(), + session_count = session_count, + "Stored the changed sessions after encrypting an room key" + ); + } Ok(requests) } diff --git a/crates/matrix-sdk-crypto/src/session_manager/sessions.rs b/crates/matrix-sdk-crypto/src/session_manager/sessions.rs index 422ea2773..fef86fe15 100644 --- a/crates/matrix-sdk-crypto/src/session_manager/sessions.rs +++ b/crates/matrix-sdk-crypto/src/session_manager/sessions.rs @@ -12,7 +12,11 @@ // See the License for the specific language governing permissions and // limitations under the License. -use std::{collections::BTreeMap, sync::Arc, time::Duration}; +use std::{ + collections::{BTreeMap, BTreeSet}, + sync::Arc, + time::Duration, +}; use dashmap::{DashMap, DashSet}; use matrix_sdk_common::uuid::Uuid; @@ -22,9 +26,9 @@ use ruma::{ }, assign, events::{dummy::ToDeviceDummyEventContent, AnyToDeviceEventContent}, - DeviceId, DeviceIdBox, DeviceKeyAlgorithm, UserId, + DeviceId, DeviceIdBox, DeviceKeyAlgorithm, EventEncryptionAlgorithm, UserId, }; -use tracing::{error, info, warn}; +use tracing::{debug, error, info, warn}; use crate::{ error::OlmResult, @@ -176,25 +180,37 @@ impl SessionManager { let user_devices = self.store.get_readonly_devices(user_id).await?; for (device_id, device) in user_devices.into_iter() { - let sender_key = if let Some(k) = device.get_key(DeviceKeyAlgorithm::Curve25519) { - k + if !device.algorithms().contains(&EventEncryptionAlgorithm::OlmV1Curve25519AesSha2) + { + warn!( + user_id = device.user_id().as_str(), + device_id = device.device_id().as_str(), + algorithms =? device.algorithms(), + "Device doesn't support any of our 1-to-1 E2EE \ + algorithms, can't establish an Olm session" + ); + } else if let Some(sender_key) = device.get_key(DeviceKeyAlgorithm::Curve25519) { + let sessions = self.store.get_sessions(sender_key).await?; + + let is_missing = if let Some(sessions) = sessions { + sessions.lock().await.is_empty() + } else { + true + }; + + if is_missing { + missing + .entry(user_id.to_owned()) + .or_insert_with(BTreeMap::new) + .insert(device_id, DeviceKeyAlgorithm::SignedCurve25519); + } } else { - continue; - }; - - let sessions = self.store.get_sessions(sender_key).await?; - - let is_missing = if let Some(sessions) = sessions { - sessions.lock().await.is_empty() - } else { - true - }; - - if is_missing { - missing - .entry(user_id.to_owned()) - .or_insert_with(BTreeMap::new) - .insert(device_id, DeviceKeyAlgorithm::SignedCurve25519); + warn!( + user_id = device.user_id().as_str(), + device_id = device.device_id().as_str(), + "Device doesn't have a valid Curve25519 key, \ + can't establish an Olm session" + ); } } } @@ -215,6 +231,8 @@ impl SessionManager { if missing.is_empty() { Ok(None) } else { + debug!(?missing, "Collected user/device pairs that are missing an Olm session"); + Ok(Some(( Uuid::new_v4(), assign!(KeysClaimRequest::new(missing), { @@ -231,9 +249,10 @@ impl SessionManager { /// /// * `response` - The response containing the claimed one-time keys. pub async fn receive_keys_claim_response(&self, response: &KeysClaimResponse) -> OlmResult<()> { - // TODO log the failures here + debug!(failures =? response.failures, "Received a /keys/claim response"); let mut changes = Changes::default(); + let mut new_sessions: BTreeMap<&UserId, BTreeSet<&DeviceId>> = BTreeMap::new(); for (user_id, user_devices) in &response.one_time_keys { for (device_id, key_map) in user_devices { @@ -241,32 +260,40 @@ impl SessionManager { Ok(Some(d)) => d, Ok(None) => { warn!( - "Tried to create an Olm session for {} {}, but the device is unknown", - user_id, device_id + user_id = user_id.as_str(), + device_id = device_id.as_str(), + "Tried to create an Olm session but the device is \ + unknown", ); continue; } Err(e) => { warn!( - "Tried to create an Olm session for {} {}, but \ - can't fetch the device from the store {:?}", - user_id, device_id, e + user_id = user_id.as_str(), + device_id = device_id.as_str(), + error =? e, + "Tried to create an Olm session, but we can't \ + fetch the device from the store", ); continue; } }; - info!("Creating outbound Session for {} {}", user_id, device_id); - let session = match self.account.create_outbound_session(device, key_map).await { Ok(s) => s, Err(e) => { - warn!("Error creating new outbound session {:?}", e); + warn!( + user_id = user_id.as_str(), + device_id = device_id.as_str(), + error =? e, + "Error creating outbound session" + ); continue; } }; changes.sessions.push(session); + new_sessions.entry(user_id).or_default().insert(device_id); self.key_request_machine.retry_keyshare(user_id, device_id); @@ -279,8 +306,8 @@ impl SessionManager { } } - // TODO turn this into a single save_changes() call. self.store.save_changes(changes).await?; + info!(sessions =? new_sessions, "Established new Olm sessions"); match self.key_request_machine.collect_incoming_key_requests().await { Ok(sessions) => { diff --git a/crates/matrix-sdk-crypto/src/store/mod.rs b/crates/matrix-sdk-crypto/src/store/mod.rs index b40e85647..21bb6ec15 100644 --- a/crates/matrix-sdk-crypto/src/store/mod.rs +++ b/crates/matrix-sdk-crypto/src/store/mod.rs @@ -109,11 +109,26 @@ pub struct Changes { pub message_hashes: Vec, pub inbound_group_sessions: Vec, pub outbound_group_sessions: Vec, - pub identities: IdentityChanges, pub key_requests: Vec, + pub identities: IdentityChanges, pub devices: DeviceChanges, } +impl Changes { + /// Are there any changes stored or is this an empty `Changes` struct + pub fn is_empty(&self) -> bool { + self.account.is_none() + && self.private_identity.is_none() + && self.sessions.is_empty() + && self.message_hashes.is_empty() + && self.inbound_group_sessions.is_empty() + && self.outbound_group_sessions.is_empty() + && self.key_requests.is_empty() + && self.identities.is_empty() + && self.devices.is_empty() + } +} + #[derive(Debug, Clone, Default)] #[allow(missing_docs)] pub struct IdentityChanges { @@ -121,6 +136,12 @@ pub struct IdentityChanges { pub changed: Vec, } +impl IdentityChanges { + fn is_empty(&self) -> bool { + self.new.is_empty() && self.changed.is_empty() + } +} + #[derive(Debug, Clone, Default)] #[allow(missing_docs)] pub struct DeviceChanges { @@ -136,6 +157,10 @@ impl DeviceChanges { self.changed.extend(other.changed); self.deleted.extend(other.deleted); } + + fn is_empty(&self) -> bool { + self.new.is_empty() && self.changed.is_empty() && self.deleted.is_empty() + } } /// A struct containing private cross signing keys that can be backed up or