crypto: Improve some log lines
This commit is contained in:
parent
bc8c2752e4
commit
3726492cf9
2 changed files with 88 additions and 44 deletions
|
@ -41,7 +41,7 @@ use ruma::{
|
|||
};
|
||||
use serde::{Deserialize, Serialize};
|
||||
use thiserror::Error;
|
||||
use tracing::{error, info, trace, warn};
|
||||
use tracing::{debug, error, info, trace, warn};
|
||||
|
||||
use crate::{
|
||||
error::{OlmError, OlmResult},
|
||||
|
@ -230,6 +230,13 @@ impl From<SecretName> for SecretInfo {
|
|||
}
|
||||
|
||||
impl OutgoingKeyRequest {
|
||||
fn request_type(&self) -> &str {
|
||||
match &self.info {
|
||||
SecretInfo::KeyRequest(_) => "m.room_key_request",
|
||||
SecretInfo::SecretRequest(s) => s.as_ref(),
|
||||
}
|
||||
}
|
||||
|
||||
fn to_request(&self, own_device_id: &DeviceId) -> OutgoingRequest {
|
||||
let content = match &self.info {
|
||||
SecretInfo::KeyRequest(r) => {
|
||||
|
@ -533,9 +540,10 @@ impl KeyRequestMachine {
|
|||
info
|
||||
} else {
|
||||
warn!(
|
||||
"Received a key request from {} {} with a request \
|
||||
action, but no key info was found",
|
||||
event.sender, event.content.requesting_device_id
|
||||
sender = event.sender.as_str(),
|
||||
requesting_device_id = event.content.requesting_device_id.as_str(),
|
||||
"Received a key request with a request of action, but
|
||||
no key info was found",
|
||||
);
|
||||
return Ok(None);
|
||||
}
|
||||
|
@ -543,7 +551,12 @@ impl KeyRequestMachine {
|
|||
// We ignore cancellations here since there's nothing to serve.
|
||||
Action::CancelRequest => return Ok(None),
|
||||
action => {
|
||||
warn!("Unknown room key request action: {:?}", action);
|
||||
warn!(
|
||||
sender = event.sender.as_str(),
|
||||
requesting_device_id = event.content.requesting_device_id.as_str(),
|
||||
action = action.as_ref(),
|
||||
"Received a room key request with an unknown action",
|
||||
);
|
||||
return Ok(None);
|
||||
}
|
||||
};
|
||||
|
@ -560,9 +573,12 @@ impl KeyRequestMachine {
|
|||
let session = if let Some(s) = session {
|
||||
s
|
||||
} else {
|
||||
info!(
|
||||
"Received a key request from {} {} for an unknown inbound group session {}.",
|
||||
&event.sender, &event.content.requesting_device_id, &key_info.session_id
|
||||
debug!(
|
||||
user_id = event.sender.as_str(),
|
||||
device_id = event.content.requesting_device_id.as_str(),
|
||||
session_id = key_info.session_id.as_str(),
|
||||
room_id = key_info.room_id.as_str(),
|
||||
"Received a room key request for an unknown inbound group session",
|
||||
);
|
||||
return Ok(None);
|
||||
};
|
||||
|
@ -573,32 +589,34 @@ impl KeyRequestMachine {
|
|||
if let Some(device) = device {
|
||||
match self.should_share_key(&device, &session).await {
|
||||
Err(e) => {
|
||||
info!(
|
||||
"Received a key request from {} {} that we won't serve: {}",
|
||||
device.user_id(),
|
||||
device.device_id(),
|
||||
e
|
||||
debug!(
|
||||
user_id = device.user_id().as_str(),
|
||||
device_id = device.device_id().as_str(),
|
||||
reason =? e,
|
||||
"Received a key request that we won't serve",
|
||||
);
|
||||
|
||||
Ok(None)
|
||||
}
|
||||
Ok(message_index) => {
|
||||
info!(
|
||||
"Serving a key request for {} from {} {} with message_index {:?}.",
|
||||
key_info.session_id,
|
||||
device.user_id(),
|
||||
device.device_id(),
|
||||
message_index,
|
||||
user_id = device.user_id().as_str(),
|
||||
device_id = device.device_id().as_str(),
|
||||
session_id = key_info.session_id.as_str(),
|
||||
room_id = key_info.room_id.as_str(),
|
||||
message_index =? message_index,
|
||||
"Serving a room key request",
|
||||
);
|
||||
|
||||
match self.share_session(&session, &device, message_index).await {
|
||||
Ok(s) => Ok(Some(s)),
|
||||
Err(OlmError::MissingSession) => {
|
||||
info!(
|
||||
"Key request from {} {} is missing an Olm session, \
|
||||
user_id = device.user_id().as_str(),
|
||||
device_id = device.device_id().as_str(),
|
||||
session_id = key_info.session_id.as_str(),
|
||||
"Key request is missing an Olm session, \
|
||||
putting the request in the wait queue",
|
||||
device.user_id(),
|
||||
device.device_id()
|
||||
);
|
||||
self.handle_key_share_without_session(device, event);
|
||||
|
||||
|
@ -610,8 +628,9 @@ impl KeyRequestMachine {
|
|||
}
|
||||
} else {
|
||||
warn!(
|
||||
"Received a key request from an unknown device {} {}.",
|
||||
&event.sender, &event.content.requesting_device_id
|
||||
user_id = event.sender.as_str(),
|
||||
device_id = event.content.requesting_device_id.as_str(),
|
||||
"Received a key request from an unknown device",
|
||||
);
|
||||
self.store.update_tracked_user(&event.sender, true).await?;
|
||||
|
||||
|
@ -830,8 +849,6 @@ impl KeyRequestMachine {
|
|||
&self,
|
||||
key_info: SecretInfo,
|
||||
) -> Result<OutgoingRequest, CryptoStoreError> {
|
||||
info!("Creating new outgoing room key request {:#?}", key_info);
|
||||
|
||||
let request = OutgoingKeyRequest {
|
||||
request_recipient: self.user_id().to_owned(),
|
||||
request_id: Uuid::new_v4(),
|
||||
|
@ -918,7 +935,12 @@ impl KeyRequestMachine {
|
|||
let info = self.store.get_outgoing_secret_requests(id).await?;
|
||||
|
||||
if let Some(mut info) = info {
|
||||
trace!("Marking outgoing key request as sent {:#?}", info);
|
||||
trace!(
|
||||
recipient = info.request_recipient.as_str(),
|
||||
request_type = info.request_type(),
|
||||
request_id = info.request_id.to_string().as_str(),
|
||||
"Marking outgoing key request as sent"
|
||||
);
|
||||
info.sent_out = true;
|
||||
self.save_outgoing_key_info(info).await?;
|
||||
}
|
||||
|
@ -932,8 +954,12 @@ impl KeyRequestMachine {
|
|||
///
|
||||
/// This will queue up a request cancellation.
|
||||
async fn mark_as_done(&self, key_info: OutgoingKeyRequest) -> Result<(), CryptoStoreError> {
|
||||
// TODO perhaps only remove the key info if the first known index is 0.
|
||||
trace!("Successfully received a forwarded room key for {:#?}", key_info);
|
||||
trace!(
|
||||
recipient = key_info.request_recipient.as_str(),
|
||||
request_type = key_info.request_type(),
|
||||
request_id = key_info.request_id.to_string().as_str(),
|
||||
"Successfully received a secret, removing the request"
|
||||
);
|
||||
|
||||
self.outgoing_requests.remove(&key_info.request_id);
|
||||
// TODO return the key info instead of deleting it so the sync handler
|
||||
|
@ -986,18 +1012,18 @@ impl KeyRequestMachine {
|
|||
|
||||
if let Some(s) = &session {
|
||||
info!(
|
||||
"Received a forwarded room key from {} for room {} with session id {}",
|
||||
event.sender,
|
||||
s.room_id(),
|
||||
s.session_id()
|
||||
sender = event.sender.as_str(),
|
||||
room_id = s.room_id().as_str(),
|
||||
session_id = s.session_id(),
|
||||
"Received a forwarded room key",
|
||||
);
|
||||
}
|
||||
|
||||
Ok((Some(AnyToDeviceEvent::ForwardedRoomKey(event.clone())), session))
|
||||
} else {
|
||||
info!(
|
||||
"Received a forwarded room key from {}, but no key info was found.",
|
||||
event.sender,
|
||||
sender = event.sender.as_str(),
|
||||
"Received a forwarded room key but no key info was found.",
|
||||
);
|
||||
Ok((None, None))
|
||||
}
|
||||
|
|
|
@ -215,12 +215,15 @@ impl OlmMachine {
|
|||
) -> StoreResult<Self> {
|
||||
let account = match store.load_account().await? {
|
||||
Some(a) => {
|
||||
debug!("Restored account");
|
||||
debug!(ed25519_key = a.identity_keys().ed25519(), "Restored an Olm account");
|
||||
a
|
||||
}
|
||||
None => {
|
||||
debug!("Creating a new account");
|
||||
let account = ReadOnlyAccount::new(&user_id, &device_id);
|
||||
debug!(
|
||||
ed25519_key = account.identity_keys().ed25519(),
|
||||
"Created a new Olm account"
|
||||
);
|
||||
store.save_account(account.clone()).await?;
|
||||
account
|
||||
}
|
||||
|
@ -228,7 +231,14 @@ impl OlmMachine {
|
|||
|
||||
let identity = match store.load_identity().await? {
|
||||
Some(i) => {
|
||||
debug!("Restored the cross signing identity");
|
||||
let master_key = i
|
||||
.master_public_key()
|
||||
.await
|
||||
.and_then(|m| m.get_first_key().map(|m| m.to_string()));
|
||||
debug!(
|
||||
master_key =? master_key,
|
||||
"Restored the cross signing identity"
|
||||
);
|
||||
i
|
||||
}
|
||||
None => {
|
||||
|
@ -697,7 +707,7 @@ impl OlmMachine {
|
|||
.receive_forwarded_room_key(&decrypted.sender_key, &mut e)
|
||||
.await?),
|
||||
_ => {
|
||||
warn!("Received an unexpected encrypted to-device event");
|
||||
warn!(event_type =? event.event_type(), "Received an unexpected encrypted to-device event");
|
||||
Ok((Some(event), None))
|
||||
}
|
||||
}
|
||||
|
@ -811,19 +821,26 @@ impl OlmMachine {
|
|||
Ok(e) => e,
|
||||
Err(e) => {
|
||||
// Skip invalid events.
|
||||
warn!("Received an invalid to-device event {:?} {:?}", e, raw_event);
|
||||
warn!(
|
||||
error =? e,
|
||||
"Received an invalid to-device event"
|
||||
);
|
||||
continue;
|
||||
}
|
||||
};
|
||||
|
||||
info!("Received a to-device event {:?}", event);
|
||||
info!(
|
||||
sender = event.sender().as_str(),
|
||||
event_type = event.event_type(),
|
||||
"Received a to-device event"
|
||||
);
|
||||
|
||||
match event {
|
||||
AnyToDeviceEvent::RoomEncrypted(e) => {
|
||||
let decrypted = match self.decrypt_to_device_event(&e).await {
|
||||
Ok(e) => e,
|
||||
Err(err) => {
|
||||
warn!("Failed to decrypt to-device event from {} {}", e.sender, err);
|
||||
warn!(sender = e.sender.as_str(), error =? e, "Failed to decrypt to-device event");
|
||||
|
||||
if let OlmError::SessionWedged(sender, curve_key) = err {
|
||||
if let Err(e) = self
|
||||
|
@ -832,8 +849,9 @@ impl OlmMachine {
|
|||
.await
|
||||
{
|
||||
error!(
|
||||
"Couldn't mark device from {} to be unwedged {:?}",
|
||||
sender, e
|
||||
sender = sender.as_str(),
|
||||
error =? e,
|
||||
"Couldn't mark device from to be unwedged",
|
||||
);
|
||||
}
|
||||
}
|
||||
|
|
Loading…
Reference in a new issue