fix(timestamps): Deal with sub-microsecond inaccuracies on parse

CHANGELOG.md

@@ -10,7 +10,8 @@
 **Bug Fixes**:
 
 - Normalize OS and Browser names in contexts when missing a version. ([#4957](https://github.com/getsentry/relay/pull/4957))
-- Normalize AI pipeline name and streaming flag to `gen_ai.*` names ([#4982](https://github.com/getsentry/relay/pull/4982))
+- Normalize AI pipeline name and streaming flag to `gen_ai.*` names. ([#4982](https://github.com/getsentry/relay/pull/4982))
+- Deal with sub-microsecond floating point inaccuracies for logs and spans correctly. ([#5002](https://github.com/getsentry/relay/pull/5002))
 
 **Internal**:
 

relay-event-schema/src/protocol/span.rs

@@ -1347,14 +1347,14 @@ mod tests {
         let span = Annotated::<Span>::from_json(
             r#"{
                 "start_timestamp": 1694732407.8367,
-                "timestamp": 1694732408.3145
+                "timestamp": 1694732408.31451233
             }"#,
         )
         .unwrap()
         .into_value()
         .unwrap();
 
-        assert_eq!(span.get_value("span.duration"), Some(Val::F64(477.800131)));
+        assert_eq!(span.get_value("span.duration"), Some(Val::F64(477.812)));
     }
 
     #[test]

relay-event-schema/src/protocol/types.rs

@@ -887,26 +887,47 @@ impl fmt::Display for Timestamp {
     }
 }
 
+/// Converts a [`DateTime`] to a `f64`, dealing with sub-microsecond float inaccuracies.
+///
+/// f64s cannot store nanoseconds. To verify this just try to fit the current timestamp in
+/// nanoseconds into a 52-bit number (which is the significand of a double).
+///
+/// Round off to microseconds to not show more decimal points than we know are correct. Anything
+/// else might trick the user into thinking the nanoseconds in those timestamps mean anything.
+///
+/// This needs to be done regardless of whether the input value was a ISO-formatted string or a
+/// number because it all ends up as a f64 on serialization.
+///
+/// If we want to support nanoseconds at some point we will probably have to start using strings
+/// everywhere. Even then it's unclear how to deal with it in Python code as a `datetime` cannot
+/// store nanoseconds.
+///
+/// See also: [`timestamp_to_datetime`].
 pub fn datetime_to_timestamp(dt: DateTime<Utc>) -> f64 {
-    // f64s cannot store nanoseconds. To verify this just try to fit the current timestamp in
-    // nanoseconds into a 52-bit number (which is the significand of a double).
-    //
-    // Round off to microseconds to not show more decimal points than we know are correct. Anything
-    // else might trick the user into thinking the nanoseconds in those timestamps mean anything.
-    //
-    // This needs to be done regardless of whether the input value was a ISO-formatted string or a
-    // number because it all ends up as a f64 on serialization.
-    //
-    // If we want to support nanoseconds at some point we will probably have to start using strings
-    // everywhere. Even then it's unclear how to deal with it in Python code as a `datetime` cannot
-    // store nanoseconds.
-    //
     // We use `timestamp_subsec_nanos` instead of `timestamp_subsec_micros` anyway to get better
     // rounding behavior.
     let micros = (f64::from(dt.timestamp_subsec_nanos()) / 1_000f64).round();
     dt.timestamp() as f64 + (micros / 1_000_000f64)
 }
 
+/// Converts a `f64` Unix timestamp to a [`DateTime`], dealing with sub-microsecond float
+/// inaccuracies.
+///
+/// See also: [`datetime_to_timestamp`].
+pub fn timestamp_to_datetime(ts: f64) -> LocalResult<DateTime<Utc>> {
+    // Always floor, this works correctly for negative numbers as well.
+    let secs = ts.floor();
+    // This is always going to be positive, because we floored the seconds.
+    let fract = ts - secs;
+    let micros = (fract * 1_000_000f64).round() as u32;
+    // Rounding may produce another full second, in which case we need to manually handle the extra
+    // second.
+    match micros == 1_000_000 {
+        true => Utc.timestamp_opt(secs as i64 + 1, 0),
+        false => Utc.timestamp_opt(secs as i64, micros * 1_000),
+    }
+}
+
 fn utc_result_to_annotated<V: IntoValue>(
     result: LocalResult<DateTime<Utc>>,
     original_value: V,
@@ -959,11 +980,7 @@ impl FromValue for Timestamp {
                 utc_result_to_annotated(Utc.timestamp_opt(ts, 0), ts, meta)
             }
             Annotated(Some(Value::F64(ts)), meta) => {
-                let secs = ts as i64;
-                // at this point we probably already lose nanosecond precision, but we deal with
-                // this in `datetime_to_timestamp`.
-                let nanos = (ts.fract() * 1_000_000_000f64) as u32;
-                utc_result_to_annotated(Utc.timestamp_opt(secs, nanos), ts, meta)
+                utc_result_to_annotated(timestamp_to_datetime(ts), ts, meta)
             }
             Annotated(None, meta) => Annotated(None, meta),
             Annotated(Some(value), mut meta) => {
@@ -1017,6 +1034,34 @@ mod tests {
 
     use super::*;
 
+    #[test]
+    fn test_timestamp_to_datetime() {
+        assert_eq!(timestamp_to_datetime(0.), Utc.timestamp_opt(0, 0));
+        assert_eq!(timestamp_to_datetime(1000.), Utc.timestamp_opt(1000, 0));
+        assert_eq!(timestamp_to_datetime(-1000.), Utc.timestamp_opt(-1000, 0));
+        assert_eq!(
+            timestamp_to_datetime(1.234_567),
+            Utc.timestamp_opt(1, 234_567_000)
+        );
+        assert_eq!(timestamp_to_datetime(2.999_999_51), Utc.timestamp_opt(3, 0));
+        assert_eq!(
+            timestamp_to_datetime(2.999_999_45),
+            Utc.timestamp_opt(2, 999_999_000)
+        );
+        assert_eq!(
+            timestamp_to_datetime(-0.000_001),
+            Utc.timestamp_opt(-1, 999_999_000)
+        );
+        assert_eq!(
+            timestamp_to_datetime(-3.000_000_49),
+            Utc.timestamp_opt(-3, 0)
+        );
+        assert_eq!(
+            timestamp_to_datetime(-3.000_000_51),
+            Utc.timestamp_opt(-4, 999_999_000)
+        );
+    }
+
     #[test]
     fn test_values_serialization() {
         let value = Annotated::new(Values {

relay-spans/src/v2_to_v1.rs

@@ -961,7 +961,7 @@ mod tests {
         {
           "timestamp": 123.1,
           "start_timestamp": 123.0,
-          "exclusive_time": 99.999999,
+          "exclusive_time": 100.0,
           "op": "cache.hit",
           "span_id": "e342abb1214ca181",
           "parent_span_id": "0c7a7dea069bf5a6",

tests/integration/test_metrics.py

@@ -791,17 +791,11 @@ def test_transaction_metrics(
 
     def assert_transaction():
         event, _ = transactions_consumer.get_event()
-        if with_external_relay:
-            # there is some rounding error while serializing/deserializing
-            # timestamps... haven't investigated too closely
-            span_time = 9.910107
-        else:
-            span_time = 9.910106
 
         assert event["breakdowns"] == {
             "span_ops": {
-                "ops.react.mount": {"value": span_time, "unit": "millisecond"},
-                "total.time": {"value": span_time, "unit": "millisecond"},
+                "ops.react.mount": {"value": 9.91, "unit": "millisecond"},
+                "total.time": {"value": 9.91, "unit": "millisecond"},
             }
         }
 
@@ -866,7 +860,7 @@ def assert_transaction():
         **common,
         "name": "d:transactions/breakdowns.span_ops.ops.react.mount@millisecond",
         "type": "d",
-        "value": [9.910106, 9.910106],
+        "value": [9.91, 9.91],
     }
     assert metrics["c:transactions/count_per_root_project@none"] == {
         "timestamp": time_after(timestamp),

tests/integration/test_ourlogs.py

@@ -73,7 +73,7 @@ def envelope_with_otel_logs(ts: datetime) -> Envelope:
 def timestamps(ts: datetime):
     return {
         "sentry.observed_timestamp_nanos": {
-            "stringValue": time_within(ts, expect_resolution="ns", precision="s")
+            "stringValue": time_within(ts, expect_resolution="ns")
         },
         "sentry.timestamp_nanos": {
             "stringValue": time_within_delta(