From 1ea163271bcca2f0d9fa6a8767c751c887e62fae Mon Sep 17 00:00:00 2001 From: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> Date: Mon, 11 Mar 2024 12:16:39 +0000 Subject: [PATCH] crypto: Include event timestamp in decryption failure logs Co-authored-by: Benjamin Bouvier Signed-off-by: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> --- Cargo.lock | 1 + crates/matrix-sdk-crypto/CHANGELOG.md | 3 ++ crates/matrix-sdk-crypto/Cargo.toml | 1 + crates/matrix-sdk-crypto/src/machine.rs | 8 ++- crates/matrix-sdk-crypto/src/utilities.rs | 62 +++++++++++++++++++++++ 5 files changed, 74 insertions(+), 1 deletion(-) diff --git a/Cargo.lock b/Cargo.lock index c6ff73a65..579e899b2 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3121,6 +3121,7 @@ dependencies = [ "stream_assert", "subtle", "thiserror", + "time", "tokio", "tokio-stream", "tracing", diff --git a/crates/matrix-sdk-crypto/CHANGELOG.md b/crates/matrix-sdk-crypto/CHANGELOG.md index 42d99e867..d5392f44a 100644 --- a/crates/matrix-sdk-crypto/CHANGELOG.md +++ b/crates/matrix-sdk-crypto/CHANGELOG.md @@ -29,6 +29,9 @@ Additions: - Add new API `store::Store::export_room_keys_stream` that provides room keys on demand. +- Include event timestamps on logs from event decryption. + ([#3194](https://github.com/matrix-org/matrix-rust-sdk/pull/3194)) + # 0.7.0 - Add method to mark a list of inbound group sessions as backed up: diff --git a/crates/matrix-sdk-crypto/Cargo.toml b/crates/matrix-sdk-crypto/Cargo.toml index b579e64d8..158e8a35d 100644 --- a/crates/matrix-sdk-crypto/Cargo.toml +++ b/crates/matrix-sdk-crypto/Cargo.toml @@ -52,6 +52,7 @@ serde = { workspace = true, features = ["derive", "rc"] } serde_json = { workspace = true } sha2 = { workspace = true } subtle = "2.5.0" +time = { version = "0.3.34", features = ["formatting"] } tokio-stream = { workspace = true, features = ["sync"] } tokio = { workspace = true } thiserror = { workspace = true } diff --git a/crates/matrix-sdk-crypto/src/machine.rs b/crates/matrix-sdk-crypto/src/machine.rs index 8274bbb26..0f558b95d 100644 --- a/crates/matrix-sdk-crypto/src/machine.rs +++ b/crates/matrix-sdk-crypto/src/machine.rs @@ -88,6 +88,7 @@ use crate::{ }, EventEncryptionAlgorithm, Signatures, }, + utilities::timestamp_to_iso8601, verification::{Verification, VerificationMachine, VerificationRequest}, CrossSigningKeyExport, CryptoStoreError, KeysQueryRequest, LocalTrust, ReadOnlyDevice, RoomKeyImportResult, SignatureError, ToDeviceRequest, @@ -1534,7 +1535,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, event_id, sender, algorithm, session_id, sender_key))] + #[instrument(skip_all, fields(?room_id, event_id, origin_server_ts, sender, algorithm, session_id, sender_key))] pub async fn decrypt_room_event( &self, event: &Raw, @@ -1545,6 +1546,11 @@ impl OlmMachine { tracing::Span::current() .record("sender", debug(&event.sender)) .record("event_id", debug(&event.event_id)) + .record( + "origin_server_ts", + timestamp_to_iso8601(event.origin_server_ts) + .unwrap_or_else(|| "".to_owned()), + ) .record("algorithm", debug(event.content.algorithm())); let content: SupportedEventEncryptionSchemes<'_> = match &event.content.scheme { diff --git a/crates/matrix-sdk-crypto/src/utilities.rs b/crates/matrix-sdk-crypto/src/utilities.rs index 09d12f0f2..103b39aa7 100644 --- a/crates/matrix-sdk-crypto/src/utilities.rs +++ b/crates/matrix-sdk-crypto/src/utilities.rs @@ -12,6 +12,14 @@ // See the License for the specific language governing permissions and // limitations under the License. +use std::num::NonZeroU8; + +use ruma::MilliSecondsSinceUnixEpoch; +use time::{ + format_description::well_known::{iso8601, Iso8601}, + OffsetDateTime, +}; + #[cfg(test)] pub(crate) fn json_convert(value: &T) -> serde_json::Result where @@ -21,3 +29,57 @@ where let json = serde_json::to_string(value)?; serde_json::from_str(&json) } + +const ISO8601_WITH_MILLIS: iso8601::EncodedConfig = iso8601::Config::DEFAULT + .set_time_precision(iso8601::TimePrecision::Second { decimal_digits: NonZeroU8::new(3) }) + .encode(); + +/// Format the given timestamp into a human-readable timestamp. +/// +/// # Returns +/// +/// Provided the timestamp fits within an `OffsetDateTime` (ie, it is on or +/// before year 9999), a string that looks like `1970-01-01T00:00:00.000Z`. +/// Otherwise, `None`. +pub fn timestamp_to_iso8601(ts: MilliSecondsSinceUnixEpoch) -> Option { + let nanos_since_epoch = i128::from(ts.get()) * 1_000_000; + + // OffsetDateTime has a max year of 9999, whereas MilliSecondsSinceUnixEpoch has + // a max year of 285427, so `from_unix_timestamp_nanos` can overflow for very + // large timestamps. (The Y10K problem!) + let dt = OffsetDateTime::from_unix_timestamp_nanos(nanos_since_epoch).ok()?; + + // SAFETY: `format` can fail if: + // * The input lacks information on a component we have asked it to format + // (eg, it is given a `Time` and we ask it for a date), or + // * The input contains an invalid component (eg 30th February), or + // * An `io::Error` is raised internally. + // + // The first two cannot occur because we know we are giving it a valid + // OffsetDateTime that has all the components we are asking it to print. + // + // The third should not occur because we are formatting a short string to an + // in-memory buffer. + + Some(dt.format(&Iso8601::).unwrap()) +} + +#[cfg(test)] +pub(crate) mod tests { + use ruma::{MilliSecondsSinceUnixEpoch, UInt}; + + use super::timestamp_to_iso8601; + + #[test] + fn test_timestamp_to_iso8601() { + assert_eq!( + timestamp_to_iso8601(MilliSecondsSinceUnixEpoch(UInt::new_saturating(0))), + Some("1970-01-01T00:00:00.000Z".to_owned()) + ); + assert_eq!( + timestamp_to_iso8601(MilliSecondsSinceUnixEpoch(UInt::new_saturating(1709657033012))), + Some("2024-03-05T16:43:53.012Z".to_owned()) + ); + assert_eq!(timestamp_to_iso8601(MilliSecondsSinceUnixEpoch(UInt::MAX)), None); + } +}