crypto: Include event timestamp in decryption failure logs

Co-authored-by: Benjamin Bouvier <public@benj.me>
Signed-off-by: Richard van der Hoff <1389908+richvdh@users.noreply.github.com>

Cargo.lock

@@ -3121,6 +3121,7 @@ dependencies = [
  "stream_assert",
  "subtle",
  "thiserror",
+ "time",
  "tokio",
  "tokio-stream",
  "tracing",

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:

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 }

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<EncryptedEvent>,
@@ -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(|| "<out of range>".to_owned()),
+            )
             .record("algorithm", debug(event.content.algorithm()));
 
         let content: SupportedEventEncryptionSchemes<'_> = match &event.content.scheme {

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<T, U>(value: &T) -> serde_json::Result<U>
 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<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 `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::<ISO8601_WITH_MILLIS>).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);
+    }
+}