From 77df55374bae45980d2a1d63ccd3b3310f52f79a Mon Sep 17 00:00:00 2001 From: Kev Date: Thu, 6 Mar 2025 12:17:58 -0500 Subject: [PATCH 1/7] feat(ourlogs): Always set observed time for logs Observed time nanos should be set by the collector in OTel. In the case of Sentry the collector will always be Relay. We may want to allow passing observed time nanos in the future, but we can address that after we move to using EAP items consumers since they rely on 'received' instead of observed time. --- relay-ourlogs/src/ourlog.rs | 64 ++++++++++++++++++++++++++++++++++++- 1 file changed, 63 insertions(+), 1 deletion(-) diff --git a/relay-ourlogs/src/ourlog.rs b/relay-ourlogs/src/ourlog.rs index 189f6649658..95f54ea8bdb 100644 --- a/relay-ourlogs/src/ourlog.rs +++ b/relay-ourlogs/src/ourlog.rs @@ -1,3 +1,4 @@ +use chrono::Utc; use opentelemetry_proto::tonic::common::v1::any_value::Value as OtelValue; use crate::OtelLog; @@ -29,6 +30,10 @@ pub fn otel_to_sentry_log(otel_log: OtelLog) -> OurLog { let mut attribute_data = Object::new(); + // We ignore the passed observed time since Relay always acts as the collector in Sentry. + // We may change this in the future with forwarding Relays. + let observed_time_unix_nano = Utc::now().timestamp_nanos_opt().unwrap_or(0) as u64; + for attribute in attributes.into_iter() { if let Some(value) = attribute.value.and_then(|v| v.value) { let key = attribute.key; @@ -58,7 +63,7 @@ pub fn otel_to_sentry_log(otel_log: OtelLog) -> OurLog { OurLog { timestamp_nanos: Annotated::new(otel_log.time_unix_nano), - observed_timestamp_nanos: Annotated::new(otel_log.observed_time_unix_nano), + observed_timestamp_nanos: Annotated::new(observed_time_unix_nano), trace_id: TraceId(trace_id).into(), span_id: Annotated::new(SpanId(span_id)), trace_flags: Annotated::new(0), @@ -201,4 +206,61 @@ mod tests { Some(&"SELECT \"table\".\"col\" FROM \"table\" WHERE \"table\".\"col\" = %s".into()) ); } + + #[test] + fn parse_log_without_observed_time() { + let json_without_observed_time = r#"{ + "timeUnixNano": "1544712660300000000", + "observedTimeUnixNano": "0", + "severityNumber": 10, + "severityText": "Information", + "traceId": "5B8EFFF798038103D269B633813FC60C", + "spanId": "EEE19B7EC3C1B174", + "body": { + "stringValue": "Example log record" + }, + "attributes": [] + }"#; + + let before_test = Utc::now().timestamp_nanos_opt().unwrap_or(0) as u64; + let otel_log: OtelLog = serde_json::from_str(json_without_observed_time).unwrap(); + let our_log: OurLog = otel_to_sentry_log(otel_log); + let after_test = Utc::now().timestamp_nanos_opt().unwrap_or(0) as u64; + + let observed_time = our_log.observed_timestamp_nanos.value().unwrap(); + assert!(*observed_time > 0); + assert!(*observed_time >= before_test); + assert!(*observed_time <= after_test); + } + + #[test] + fn parse_log_ignores_observed_time() { + let json_with_observed_time = r#"{ + "timeUnixNano": "1544712660300000000", + "observedTimeUnixNano": "1544712660300000000", + "severityNumber": 10, + "severityText": "Information", + "traceId": "5B8EFFF798038103D269B633813FC60C", + "spanId": "EEE19B7EC3C1B174", + "body": { + "stringValue": "Example log record" + }, + "attributes": [] + }"#; + + let before_test = Utc::now().timestamp_nanos_opt().unwrap_or(0) as u64; + let otel_log: OtelLog = serde_json::from_str(json_with_observed_time).unwrap(); + let our_log: OurLog = otel_to_sentry_log(otel_log); + let after_test = Utc::now().timestamp_nanos_opt().unwrap_or(0) as u64; + + let observed_time = our_log.observed_timestamp_nanos.value().unwrap(); + assert!(*observed_time > 0); + assert!(*observed_time >= before_test); + assert!(*observed_time <= after_test); + + assert_ne!( + our_log.observed_timestamp_nanos, + Annotated::new(1544712660300000000) + ); + } } From fdb975b295765cd8168cba41624029fd8d5e0a5a Mon Sep 17 00:00:00 2001 From: Kev Date: Thu, 6 Mar 2025 14:35:00 -0500 Subject: [PATCH 2/7] Add UnixTimestamp::as_nanos() --- Cargo.lock | 1 + relay-common/src/time.rs | 5 +++++ relay-ourlogs/Cargo.toml | 1 + relay-ourlogs/src/ourlog.rs | 12 ++++++------ 4 files changed, 13 insertions(+), 6 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 519844eaccd..d87e5ebfbd2 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3772,6 +3772,7 @@ dependencies = [ "insta", "once_cell", "opentelemetry-proto", + "relay-common", "relay-event-schema", "relay-protocol", "serde_json", diff --git a/relay-common/src/time.rs b/relay-common/src/time.rs index 1b621268cc9..1368a6f7deb 100644 --- a/relay-common/src/time.rs +++ b/relay-common/src/time.rs @@ -109,6 +109,11 @@ impl UnixTimestamp { self.0 } + /// Returns the number of nanoseconds since the UNIX epoch start. Precision limited to seconds. + pub fn as_nanos(self) -> u64 { + self.0 * 1_000_000_000 + } + /// Returns the timestamp as chrono datetime. pub fn as_datetime(self) -> Option> { DateTime::from_timestamp(self.0 as i64, 0) diff --git a/relay-ourlogs/Cargo.toml b/relay-ourlogs/Cargo.toml index d7d6adb79df..d281f4d0978 100644 --- a/relay-ourlogs/Cargo.toml +++ b/relay-ourlogs/Cargo.toml @@ -23,6 +23,7 @@ opentelemetry-proto = { workspace = true, features = [ ] } relay-event-schema = { workspace = true } relay-protocol = { workspace = true } +relay-common = { workspace = true } serde_json = { workspace = true } [dev-dependencies] diff --git a/relay-ourlogs/src/ourlog.rs b/relay-ourlogs/src/ourlog.rs index 95f54ea8bdb..c6f2fafd30b 100644 --- a/relay-ourlogs/src/ourlog.rs +++ b/relay-ourlogs/src/ourlog.rs @@ -1,7 +1,7 @@ -use chrono::Utc; use opentelemetry_proto::tonic::common::v1::any_value::Value as OtelValue; use crate::OtelLog; +use relay_common::time::UnixTimestamp; use relay_event_schema::protocol::{AttributeValue, OurLog, SpanId, TraceId}; use relay_protocol::{Annotated, Object}; @@ -32,7 +32,7 @@ pub fn otel_to_sentry_log(otel_log: OtelLog) -> OurLog { // We ignore the passed observed time since Relay always acts as the collector in Sentry. // We may change this in the future with forwarding Relays. - let observed_time_unix_nano = Utc::now().timestamp_nanos_opt().unwrap_or(0) as u64; + let observed_time_unix_nano = UnixTimestamp::now().as_nanos(); for attribute in attributes.into_iter() { if let Some(value) = attribute.value.and_then(|v| v.value) { @@ -222,10 +222,10 @@ mod tests { "attributes": [] }"#; - let before_test = Utc::now().timestamp_nanos_opt().unwrap_or(0) as u64; + let before_test = UnixTimestamp::now().as_nanos(); let otel_log: OtelLog = serde_json::from_str(json_without_observed_time).unwrap(); let our_log: OurLog = otel_to_sentry_log(otel_log); - let after_test = Utc::now().timestamp_nanos_opt().unwrap_or(0) as u64; + let after_test = UnixTimestamp::now().as_nanos(); let observed_time = our_log.observed_timestamp_nanos.value().unwrap(); assert!(*observed_time > 0); @@ -248,10 +248,10 @@ mod tests { "attributes": [] }"#; - let before_test = Utc::now().timestamp_nanos_opt().unwrap_or(0) as u64; + let before_test = UnixTimestamp::now().as_nanos(); let otel_log: OtelLog = serde_json::from_str(json_with_observed_time).unwrap(); let our_log: OurLog = otel_to_sentry_log(otel_log); - let after_test = Utc::now().timestamp_nanos_opt().unwrap_or(0) as u64; + let after_test = UnixTimestamp::now().as_nanos(); let observed_time = our_log.observed_timestamp_nanos.value().unwrap(); assert!(*observed_time > 0); From 0fda92d7ddc531091b3f92570f8b6755da67cb2e Mon Sep 17 00:00:00 2001 From: Kev Date: Thu, 6 Mar 2025 14:37:10 -0500 Subject: [PATCH 3/7] Add changelog --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 817d7520d95..320e6bc7ad2 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -23,6 +23,7 @@ - Update mapping of OTLP spans to Sentry spans in the experimental OTL traces endpoint. ([#4505](https://github.com/getsentry/relay/pull/4505)) - Expose metrics for the `AsyncPool`. ([#4538](https://github.com/getsentry/relay/pull/4538)) - Expose service utilization metrics through the internal relay metric endpoint. ([#4543](https://github.com/getsentry/relay/pull/4543)) +- Always set observed time for OTel logs in Relay. ([#4559](https://github.com/getsentry/relay/pull/4559)) ## 25.2.0 From b061f581ab3721b590064fa4fbcea1e4eedfb362 Mon Sep 17 00:00:00 2001 From: Kev Date: Thu, 6 Mar 2025 17:07:26 -0500 Subject: [PATCH 4/7] Fix integration --- tests/integration/test_ourlogs.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/integration/test_ourlogs.py b/tests/integration/test_ourlogs.py index e373898f643..6da1492bf48 100644 --- a/tests/integration/test_ourlogs.py +++ b/tests/integration/test_ourlogs.py @@ -77,7 +77,6 @@ def test_ourlog_extraction( "project_id": 42, "retention_days": 90, "timestamp_nanos": int(start.timestamp() * 1e9), - "observed_timestamp_nanos": int(end.timestamp() * 1e9), "trace_id": "5b8efff798038103d269b633813fc60c", "body": "Example log record", "trace_flags": 0, @@ -93,6 +92,7 @@ def test_ourlog_extraction( } del ourlogs[0]["received"] + del ourlogs[0]["observed_timestamp_nanos"] assert ourlogs[0] == expected ourlogs_consumer.assert_empty() From 43e198a985d8a386bffcf27acc9f32b2135aed7b Mon Sep 17 00:00:00 2001 From: Kev <6111995+k-fish@users.noreply.github.com> Date: Fri, 7 Mar 2025 09:42:15 -0500 Subject: [PATCH 5/7] Update relay-common/src/time.rs Co-authored-by: David Herberth --- relay-common/src/time.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/relay-common/src/time.rs b/relay-common/src/time.rs index 1368a6f7deb..59ba8f174a8 100644 --- a/relay-common/src/time.rs +++ b/relay-common/src/time.rs @@ -111,7 +111,7 @@ impl UnixTimestamp { /// Returns the number of nanoseconds since the UNIX epoch start. Precision limited to seconds. pub fn as_nanos(self) -> u64 { - self.0 * 1_000_000_000 + self.as_secs() * 1_000_000_000 } /// Returns the timestamp as chrono datetime. From ee66bb8150d55dc3f88e32369123e68fe4c6a730 Mon Sep 17 00:00:00 2001 From: Kev Date: Fri, 7 Mar 2025 09:45:12 -0500 Subject: [PATCH 6/7] Fix to use time within delta helper function --- tests/integration/test_ourlogs.py | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/tests/integration/test_ourlogs.py b/tests/integration/test_ourlogs.py index 6da1492bf48..2085116456a 100644 --- a/tests/integration/test_ourlogs.py +++ b/tests/integration/test_ourlogs.py @@ -3,6 +3,8 @@ from sentry_sdk.envelope import Envelope, Item, PayloadRef +from .asserts.time import time_within_delta + TEST_CONFIG = { "aggregator": { @@ -77,6 +79,9 @@ def test_ourlog_extraction( "project_id": 42, "retention_days": 90, "timestamp_nanos": int(start.timestamp() * 1e9), + "observed_timestamp_nanos": time_within_delta( + start.timestamp(), expect_resolution="ns" + ), "trace_id": "5b8efff798038103d269b633813fc60c", "body": "Example log record", "trace_flags": 0, From 25e6dde78c701777dae635ba7180e27280689c05 Mon Sep 17 00:00:00 2001 From: Kev Date: Fri, 7 Mar 2025 09:58:46 -0500 Subject: [PATCH 7/7] Remove the del --- tests/integration/test_ourlogs.py | 1 - 1 file changed, 1 deletion(-) diff --git a/tests/integration/test_ourlogs.py b/tests/integration/test_ourlogs.py index 2085116456a..31b738a1a62 100644 --- a/tests/integration/test_ourlogs.py +++ b/tests/integration/test_ourlogs.py @@ -97,7 +97,6 @@ def test_ourlog_extraction( } del ourlogs[0]["received"] - del ourlogs[0]["observed_timestamp_nanos"] assert ourlogs[0] == expected ourlogs_consumer.assert_empty()