mirror/matrix-rust-sdk
1
0
Fork 0
mirror of https://github.com/matrix-org/matrix-rust-sdk.git synced 2026-04-26 10:11:10 -04:00
Code Issues Packages Projects Releases Wiki Activity

refactor(crypto): Improve logging

Browse Source
This commit is contained in:
Jonas Platte
2022-12-23 13:25:15 +01:00
committed by Jonas Platte
parent 7efbba5d8b
commit 46fe998a33
4 changed files with 70 additions and 117 deletions
Download Patch File Download Diff File Expand all files Collapse all files

149
crates/matrix-sdk-crypto/src/machine.rs
View File

@@ -43,7 +43,7 @@ use ruma::{
RoomId, TransactionId, UInt, UserId,
};
use serde_json::{value::to_raw_value, Value};
use tracing::{debug, error, info, trace, warn};
use tracing::{debug, error, field::display, info, instrument, trace, warn};
use vodozemac::{
megolm::{DecryptionError, SessionOrdering},
Curve25519PublicKey, Ed25519Signature,
@@ -552,6 +552,13 @@ impl OlmMachine {
Ok(decrypted)
}
#[instrument(
skip_all,
// This function is only ever called by add_room_key via
// handle_decrypted_to_device_event, so sender and sender_key are
// already recorded.
fields(room_id = %content.room_id, algorithm = %event.content.algorithm())
)]
async fn handle_key(
&self,
sender_key: Curve25519PublicKey,
@@ -568,56 +575,31 @@ impl OlmMachine {
);
if let Ok(session) = session {
if self.store.compare_group_session(&session).await? == SessionOrdering::Better {
info!(
sender = %event.sender,
%sender_key,
room_id = %content.room_id,
session_id = session.session_id(),
algorithm = %event.content.algorithm(),
"Received a new megolm room key",
);
tracing::Span::current().record("session_id", session.session_id());
if self.store.compare_group_session(&session).await? == SessionOrdering::Better {
info!("Received a new megolm room key");
Ok(Some(session))
} else {
warn!(
sender = %event.sender,
%sender_key,
room_id = %content.room_id,
session_id = session.session_id(),
algorithm = %event.content.algorithm(),
"Received a megolm room key that we already have a better version of, discarding",
"Received a megolm room key that we already have a better \
version of, discarding",
);
Ok(None)
}
} else {
warn!(
sender = %event.sender,
%sender_key,
algorithm = %event.content.algorithm(),
"Received room key with unsupported key algorithm",
);
warn!("Received a room key with an unsupported algorithm");
Ok(None)
}
}
/// Create a group session from a room key and add it to our crypto store.
#[instrument(skip_all, fields(algorithm = %event.content.algorithm()))]
async fn add_room_key(
&self,
sender_key: Curve25519PublicKey,
event: &DecryptedRoomKeyEvent,
) -> OlmResult<Option<InboundGroupSession>> {
let unsupported_warning = || {
warn!(
sender = %event.sender,
%sender_key,
algorithm = %event.content.algorithm(),
"Received room key with unsupported key algorithm",
);
};
match &event.content {
RoomKeyContent::MegolmV1AesSha2(content) => {
self.handle_key(sender_key, event, content).await
@@ -627,7 +609,7 @@ impl OlmMachine {
self.handle_key(sender_key, event, content).await
}
RoomKeyContent::Unknown(_) => {
unsupported_warning();
warn!("Received a room key with an unsupported algorithm");
Ok(None)
}
}
@@ -761,16 +743,19 @@ impl OlmMachine {
/// # Arguments
///
/// * `decrypted` - The decrypted event and some associated metadata.
#[instrument(
skip_all,
fields(
sender = %decrypted.sender,
sender_key = %decrypted.result.sender_key,
event_type = decrypted.result.event.event_type(),
),
)]
async fn handle_decrypted_to_device_event(
&self,
decrypted: &mut OlmDecryptionInfo,
) -> OlmResult<()> {
trace!(
sender = %decrypted.sender,
sender_key = %decrypted.result.sender_key,
event_type = decrypted.result.event.event_type(),
"Received a decrypted to-device event"
);
debug!("Received a decrypted to-device event");
match &decrypted.result.event {
AnyDecryptedOlmEvent::RoomKey(e) => {
@@ -799,11 +784,8 @@ impl OlmMachine {
decrypted.result.raw_event = Raw::from_json(to_raw_value(&e)?);
}
}
AnyDecryptedOlmEvent::Custom(e) => {
warn!(
event_type = ?e.event_type,
"Received an unexpected encrypted to-device event"
);
AnyDecryptedOlmEvent::Custom(_) => {
warn!("Received an unexpected encrypted to-device event");
}
}
@@ -812,7 +794,7 @@ impl OlmMachine {
async fn handle_verification_event(&self, event: &ToDeviceEvents) {
if let Err(e) = self.verification_machine.receive_any_event(event).await {
error!("Error handling a verification event: {:?}", e);
error!("Error handling a verification event: {e:?}");
}
}
@@ -921,10 +903,7 @@ impl OlmMachine {
Ok(e) => e,
Err(e) => {
// Skip invalid events.
warn!(
error = ?e,
"Received an invalid to-device event"
);
warn!("Received an invalid to-device event: {e}");
events.push(raw_event);
continue;
}
@@ -986,10 +965,7 @@ impl OlmMachine {
.cast();
}
Err(e) => {
warn!(
error = ?e,
"Received an invalid encrypted to-device event"
);
warn!("Received an invalid encrypted to-device event: {e}");
raw_event = decrypted.result.raw_event;
}
}
@@ -1100,6 +1076,12 @@ impl OlmMachine {
})
}
#[instrument(
skip_all,
// This function is only ever called by decrypt_room_event, so
// room_id, sender, algorithm and session_id are recorded already
fields(sender_key, event_type),
)]
async fn decrypt_megolm_events(
&self,
room_id: &RoomId,
@@ -1109,36 +1091,23 @@ impl OlmMachine {
if let Some(session) =
self.store.get_inbound_group_session(room_id, content.session_id()).await?
{
// TODO check the message index.
tracing::Span::current().record("sender_key", session.sender_key().to_base64());
// TODO: check the message index.
let (decrypted_event, _) = session.decrypt(event).await?;
match decrypted_event.deserialize() {
Ok(e) => {
// TODO log the event type once `AnySyncRoomEvent` has the
// TODO: log the event type once `AnyTimelineEvent` has the
// method as well
trace!(
sender = event.sender.as_str(),
room_id = room_id.as_str(),
session_id = session.session_id(),
sender_key = session.sender_key().to_base64(),
algorithm = %session.algorithm(),
"Successfully decrypted a room event"
);
trace!("Successfully decrypted a room event");
if let AnyTimelineEvent::MessageLike(e) = e {
self.verification_machine.receive_any_event(&e).await?;
}
}
Err(e) => {
warn!(
sender = event.sender.as_str(),
room_id = room_id.as_str(),
session_id = session.session_id(),
sender_key = session.sender_key().to_base64(),
algorithm = %session.algorithm(),
error = ?e,
"Event was successfully decrypted but has an invalid format"
);
warn!("Event was successfully decrypted but has an invalid format: {e}");
}
}
@@ -1157,6 +1126,7 @@ impl OlmMachine {
/// * `event` - The event that should be decrypted.
///
/// * `room_id` - The ID of the room where the event was sent to.
#[instrument(skip_all, fields(%room_id, sender, algorithm, session_id))]
pub async fn decrypt_room_event(
&self,
event: &Raw<EncryptedEvent>,
@@ -1164,22 +1134,21 @@ impl OlmMachine {
) -> MegolmResult<TimelineEvent> {
let event = event.deserialize()?;
let content = match &event.content.scheme {
let span = tracing::Span::current();
span.record("sender", display(&event.sender));
span.record("algorithm", display(event.content.algorithm()));
let content: SupportedEventEncryptionSchemes<'_> = match &event.content.scheme {
RoomEventEncryptionScheme::MegolmV1AesSha2(c) => c.into(),
#[cfg(feature = "experimental-algorithms")]
RoomEventEncryptionScheme::MegolmV2AesSha2(c) => c.into(),
RoomEventEncryptionScheme::Unknown(c) => {
warn!(
sender = event.sender.as_str(),
room_id = room_id.as_str(),
algorithm = %c.algorithm,
"Received an encrypted room event with an unsupported algorithm"
);
RoomEventEncryptionScheme::Unknown(_) => {
warn!("Received an encrypted room event with an unsupported algorithm");
return Err(EventError::UnsupportedAlgorithm.into());
}
};
span.record("session_id", content.session_id());
let result = self.decrypt_megolm_events(room_id, &event, &content).await;
if let Err(e) = &result {
@@ -1188,23 +1157,13 @@ impl OlmMachine {
| MegolmError::Decryption(DecryptionError::UnknownMessageIndex(_, _)) => {
// TODO: log the withheld reason if we have one.
debug!(
sender = event.sender.as_str(),
room_id = room_id.as_str(),
session_id = content.session_id(),
algorithm = %content.algorithm(),
"Failed to decrypt a room event, the room key is missing or has been ratcheted"
"Failed to decrypt a room event, the room key is \
missing or has been ratcheted"
);
self.key_request_machine.create_outgoing_key_request(room_id, &event).await?;
}
_ => {
warn!(
sender = event.sender.as_str(),
room_id = room_id.as_str(),
session_id = content.session_id(),
algorithm = %content.algorithm(),
error = ?e,
"Failed to decrypt a room event"
);
warn!("Failed to decrypt a room event: {e}");
}
}
}

13
crates/matrix-sdk-crypto/src/types/events/room/encrypted.rs
View File

@@ -249,19 +249,6 @@ impl SupportedEventEncryptionSchemes<'_> {
SupportedEventEncryptionSchemes::MegolmV2AesSha2(c) => &c.session_id,
}
}
/// The algorithm that was used to encrypt the event content.
pub fn algorithm(&self) -> EventEncryptionAlgorithm {
match self {
SupportedEventEncryptionSchemes::MegolmV1AesSha2(_) => {
EventEncryptionAlgorithm::MegolmV1AesSha2
}
#[cfg(feature = "experimental-algorithms")]
SupportedEventEncryptionSchemes::MegolmV2AesSha2(_) => {
EventEncryptionAlgorithm::MegolmV2AesSha2
}
}
}
}
impl<'a> From<&'a MegolmV1AesSha2Content> for SupportedEventEncryptionSchemes<'a> {

7
crates/matrix-sdk-crypto/src/verification/event_enums.rs
View File

@@ -55,6 +55,13 @@ pub enum AnyEvent<'a> {
}
impl AnyEvent<'_> {
pub fn event_type(&self) -> String {
match self {
Self::Room(e) => e.event_type().to_string(),
Self::ToDevice(e) => e.event_type().to_string(),
}
}
pub fn sender(&self) -> &UserId {
match self {
Self::Room(e) => e.sender(),

18
crates/matrix-sdk-crypto/src/verification/machine.rs
View File

@@ -28,7 +28,7 @@ use ruma::{
uint, DeviceId, EventId, MilliSecondsSinceUnixEpoch, OwnedDeviceId, OwnedUserId, RoomId,
SecondsSinceUnixEpoch, TransactionId, UInt, UserId,
};
use tracing::{debug, info, trace, warn};
use tracing::{debug, field::display, info, instrument, trace, warn};
use super::{
cache::{RequestInfo, VerificationCache},
@@ -311,12 +311,17 @@ impl VerificationMachine {
Ok(())
}
#[instrument(skip_all, fields(event_type, sender))]
pub async fn receive_any_event(
&self,
event: impl Into<AnyEvent<'_>>,
) -> Result<(), CryptoStoreError> {
let event = event.into();
let span = tracing::Span::current();
span.record("event_type", display(event.event_type()));
span.record("sender", display(event.sender()));
let Ok(flow_id) = FlowId::try_from(&event) else {
// This isn't a verification event, return early.
return Ok(());
@@ -324,12 +329,11 @@ impl VerificationMachine {
let flow_id_mismatch = || {
warn!(
sender = event.sender().as_str(),
flow_id = flow_id.as_str(),
"Received a verification event with a mismatched flow id, \
the verification object was created for a in-room \
verification but a event was received over to-device \
messaging or vice versa"
the verification object was created for a in-room \
verification but a event was received over to-device \
messaging or vice versa"
);
};
@@ -345,14 +349,12 @@ impl VerificationMachine {
match &content {
AnyVerificationContent::Request(r) => {
info!(
sender = event.sender().as_str(),
from_device = r.from_device().as_str(),
"Received a new verification request",
);
let Some(timestamp) = event.timestamp() else {
warn!(
sender = event.sender().as_str(),
from_device = r.from_device().as_str(),
"The key verification request didn't contain a valid timestamp"
);
@@ -361,7 +363,6 @@ impl VerificationMachine {
if !Self::is_timestamp_valid(timestamp) {
trace!(
sender = event.sender().as_str(),
from_device = r.from_device().as_str(),
?timestamp,
"The received verification request was too old or too far into the future",
@@ -371,7 +372,6 @@ impl VerificationMachine {
if event_sent_from_us(&event, r.from_device()) {
trace!(
sender = event.sender().as_str(),
from_device = r.from_device().as_str(),
"The received verification request was sent by us, ignoring it",
);