fix(crypto): Improve the log lines for the room key encryption flow

This commit is contained in:
Damir Jelić
2021-10-22 16:00:42 +02:00
parent 38ae79ba3c
commit 0ee8d2733a
4 changed files with 143 additions and 68 deletions

View File

@@ -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"
);

View File

@@ -159,11 +159,7 @@ impl GroupSessionManager {
content: Value,
event_type: &str,
) -> MegolmResult<EncryptedEventContent> {
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<UserId, Vec<Device>> = 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<Item = &UserId>,
encryption_settings: impl Into<EncryptionSettings>,
) -> OlmResult<Vec<Arc<ToDeviceRequest>>> {
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<Uuid> = 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)
}

View File

@@ -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) => {

View File

@@ -109,11 +109,26 @@ pub struct Changes {
pub message_hashes: Vec<OlmMessageHash>,
pub inbound_group_sessions: Vec<InboundGroupSession>,
pub outbound_group_sessions: Vec<OutboundGroupSession>,
pub identities: IdentityChanges,
pub key_requests: Vec<GossipRequest>,
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<ReadOnlyUserIdentities>,
}
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