From 293f49fbca9d7bb2f162b928e001bc8950c8c585 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Thu, 7 Mar 2024 13:08:15 +0000 Subject: [PATCH 1/7] Include event timestamp in decryption failure logs --- Cargo.lock | 1 + crates/matrix-sdk-crypto/Cargo.toml | 1 + crates/matrix-sdk-crypto/src/machine.rs | 4 +- crates/matrix-sdk-crypto/src/utilities.rs | 47 +++++++++++++++++++++++ 4 files changed, 52 insertions(+), 1 deletion(-) diff --git a/Cargo.lock b/Cargo.lock index 547f4e6ac6b..5ee326c54b7 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/Cargo.toml b/crates/matrix-sdk-crypto/Cargo.toml index b579e64d88d..158e8a35daa 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 8274bbb2653..70d2e4ae754 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, event_ts, sender, algorithm, session_id, sender_key))] pub async fn decrypt_room_event( &self, event: &Raw, @@ -1545,6 +1546,7 @@ impl OlmMachine { tracing::Span::current() .record("sender", debug(&event.sender)) .record("event_id", debug(&event.event_id)) + .record("event_ts", timestamp_to_iso8601(event.origin_server_ts)) .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 09d12f0f25d..7cca66f9466 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,42 @@ 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. +/// +/// The result looks like `1970-01-01T00:00:00.000Z`. +pub fn timestamp_to_iso8601(ts: MilliSecondsSinceUnixEpoch) -> String { + 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 this can overflow for very large timestamps. (The + // Y10K problem!) + match OffsetDateTime::from_unix_timestamp_nanos(nanos_since_epoch) { + Err(_) => "".to_owned(), + Ok(dt) => 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))), + "1970-01-01T00:00:00.000Z" + ); + assert_eq!( + timestamp_to_iso8601(MilliSecondsSinceUnixEpoch(UInt::new_saturating(1709657033012))), + "2024-03-05T16:43:53.012Z" + ); + assert_eq!(timestamp_to_iso8601(MilliSecondsSinceUnixEpoch(UInt::MAX)), ""); + } +} From 513d8832fc449fa00dcb8d45fe3f2a428c8a0de6 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Thu, 7 Mar 2024 13:10:28 +0000 Subject: [PATCH 2/7] changelog --- crates/matrix-sdk-crypto/CHANGELOG.md | 3 +++ 1 file changed, 3 insertions(+) diff --git a/crates/matrix-sdk-crypto/CHANGELOG.md b/crates/matrix-sdk-crypto/CHANGELOG.md index 42d99e867eb..d5392f44a5c 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: From db947c693cad487551dd6023b473aeb7149b37fb Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Thu, 7 Mar 2024 17:36:07 +0000 Subject: [PATCH 3/7] Return `None` on overflow --- crates/matrix-sdk-crypto/src/machine.rs | 5 ++++- crates/matrix-sdk-crypto/src/utilities.rs | 25 +++++++++++++---------- 2 files changed, 18 insertions(+), 12 deletions(-) diff --git a/crates/matrix-sdk-crypto/src/machine.rs b/crates/matrix-sdk-crypto/src/machine.rs index 70d2e4ae754..522fe786a0a 100644 --- a/crates/matrix-sdk-crypto/src/machine.rs +++ b/crates/matrix-sdk-crypto/src/machine.rs @@ -1546,7 +1546,10 @@ impl OlmMachine { tracing::Span::current() .record("sender", debug(&event.sender)) .record("event_id", debug(&event.event_id)) - .record("event_ts", timestamp_to_iso8601(event.origin_server_ts)) + .record( + "event_ts", + timestamp_to_iso8601(event.origin_server_ts).unwrap_or("".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 7cca66f9466..6d84d32cf10 100644 --- a/crates/matrix-sdk-crypto/src/utilities.rs +++ b/crates/matrix-sdk-crypto/src/utilities.rs @@ -36,17 +36,20 @@ const ISO8601_WITH_MILLIS: iso8601::EncodedConfig = iso8601::Config::DEFAULT /// Format the given timestamp into a human-readable timestamp. /// -/// The result looks like `1970-01-01T00:00:00.000Z`. -pub fn timestamp_to_iso8601(ts: MilliSecondsSinceUnixEpoch) -> String { +/// # 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 this can overflow for very large timestamps. (The - // Y10K problem!) - match OffsetDateTime::from_unix_timestamp_nanos(nanos_since_epoch) { - Err(_) => "".to_owned(), - Ok(dt) => dt.format(&Iso8601::).unwrap(), - } + // 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()?; + + Some(dt.format(&Iso8601::).unwrap()) } #[cfg(test)] @@ -59,12 +62,12 @@ pub(crate) mod tests { fn test_timestamp_to_iso8601() { assert_eq!( timestamp_to_iso8601(MilliSecondsSinceUnixEpoch(UInt::new_saturating(0))), - "1970-01-01T00:00:00.000Z" + Some("1970-01-01T00:00:00.000Z".to_owned()) ); assert_eq!( timestamp_to_iso8601(MilliSecondsSinceUnixEpoch(UInt::new_saturating(1709657033012))), - "2024-03-05T16:43:53.012Z" + Some("2024-03-05T16:43:53.012Z".to_owned()) ); - assert_eq!(timestamp_to_iso8601(MilliSecondsSinceUnixEpoch(UInt::MAX)), ""); + assert_eq!(timestamp_to_iso8601(MilliSecondsSinceUnixEpoch(UInt::MAX)), None); } } From 5f75ee349f1c64f367f2b749e67bf708d0ea6cfd Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Thu, 7 Mar 2024 17:36:20 +0000 Subject: [PATCH 4/7] Add SAFETY comment --- crates/matrix-sdk-crypto/src/utilities.rs | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/crates/matrix-sdk-crypto/src/utilities.rs b/crates/matrix-sdk-crypto/src/utilities.rs index 6d84d32cf10..103b39aa775 100644 --- a/crates/matrix-sdk-crypto/src/utilities.rs +++ b/crates/matrix-sdk-crypto/src/utilities.rs @@ -49,6 +49,18 @@ pub fn timestamp_to_iso8601(ts: MilliSecondsSinceUnixEpoch) -> Option { // 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()) } From a9c1d19379432be51fa56374274cbd7d7dcec898 Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Thu, 7 Mar 2024 17:36:47 +0000 Subject: [PATCH 5/7] Rename event field --- crates/matrix-sdk-crypto/src/machine.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/crates/matrix-sdk-crypto/src/machine.rs b/crates/matrix-sdk-crypto/src/machine.rs index 522fe786a0a..57f78c0b991 100644 --- a/crates/matrix-sdk-crypto/src/machine.rs +++ b/crates/matrix-sdk-crypto/src/machine.rs @@ -1547,7 +1547,7 @@ impl OlmMachine { .record("sender", debug(&event.sender)) .record("event_id", debug(&event.event_id)) .record( - "event_ts", + "origin_server_ts", timestamp_to_iso8601(event.origin_server_ts).unwrap_or("".to_owned()), ) .record("algorithm", debug(event.content.algorithm())); From 5aee72373224da1425edfd3bf307c43bb6846ecf Mon Sep 17 00:00:00 2001 From: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> Date: Thu, 7 Mar 2024 18:02:42 +0000 Subject: [PATCH 6/7] Apply suggestions from code review Co-authored-by: Benjamin Bouvier Signed-off-by: Richard van der Hoff <1389908+richvdh@users.noreply.github.com> --- crates/matrix-sdk-crypto/src/machine.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/crates/matrix-sdk-crypto/src/machine.rs b/crates/matrix-sdk-crypto/src/machine.rs index 57f78c0b991..4578b6a84ba 100644 --- a/crates/matrix-sdk-crypto/src/machine.rs +++ b/crates/matrix-sdk-crypto/src/machine.rs @@ -1535,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, event_ts, 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, @@ -1548,7 +1548,7 @@ impl OlmMachine { .record("event_id", debug(&event.event_id)) .record( "origin_server_ts", - timestamp_to_iso8601(event.origin_server_ts).unwrap_or("".to_owned()), + timestamp_to_iso8601(event.origin_server_ts).unwrap_or_else(|| "".to_owned()), ) .record("algorithm", debug(event.content.algorithm())); From b6ededabfea316d7bb54dd7b772e26f9dcffe25a Mon Sep 17 00:00:00 2001 From: Richard van der Hoff Date: Thu, 7 Mar 2024 18:03:54 +0000 Subject: [PATCH 7/7] formatting --- crates/matrix-sdk-crypto/src/machine.rs | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/crates/matrix-sdk-crypto/src/machine.rs b/crates/matrix-sdk-crypto/src/machine.rs index 4578b6a84ba..0f558b95db5 100644 --- a/crates/matrix-sdk-crypto/src/machine.rs +++ b/crates/matrix-sdk-crypto/src/machine.rs @@ -1548,7 +1548,8 @@ impl OlmMachine { .record("event_id", debug(&event.event_id)) .record( "origin_server_ts", - timestamp_to_iso8601(event.origin_server_ts).unwrap_or_else(|| "".to_owned()), + timestamp_to_iso8601(event.origin_server_ts) + .unwrap_or_else(|| "".to_owned()), ) .record("algorithm", debug(event.content.algorithm()));