crypto: Improve some logs around Olm decryption and encryption

This commit is contained in:
Damir Jelić
2023-04-17 11:24:57 +02:00
parent 9f1ec9ac3a
commit 35a0f3af25
5 changed files with 50 additions and 41 deletions

2
Cargo.lock generated
View File

@@ -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",

View File

@@ -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`

View File

@@ -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)
}

View File

@@ -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<OlmDecryptionInfo> {
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<OlmDecryptionInfo> {
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<InboundCreationResult, SessionCreationError> {
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(),

View File

@@ -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<String, DecryptionError> {
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)
}