search

getsentry / relay

Sentry event forwarding and ingestion service.
https://docs.sentry.io/product/relay/
Other
320 stars 91 forks source link

Clock drift correction is applied to envelopes without sent_at #1625

Closed lucas-zimerman closed 6 months ago

lucas-zimerman commented 2 years ago

Environment

SaaS (https://sentry.io/)

Version

No response

Steps to Reproduce

set your device time to may 30, and send a transaction and an event. You'll notice that events generated by the device will have a similar warning image Where transactions will have a different error on the UI image

Expected Result

Transaction not having the time adjusted.

Actual Result

Turns out the Backend adjust the timestamp from the transactions and its breadcrumbs, resulting in events that can be separated by a huge gap of time on Discover (Example below) https://sentry.io/organizations/sentry-sdks/discover/results/?end=2022-06-03T00%3A23%3A43&field=title&field=event.type&field=project&field=user.display&field=timestamp&name=All+Events&project=5522756&query=id%3A192b99ee99334f73a97950a71f7e4161++or+id%3A8c645ff84eca4ccd9d47b1eff49fde02&sort=-timestamp&start=2022-05-30T17%3A20%3A15&userModified=true&yAxis=count%28%29 image

I believe this time adjustment may be erroneous, it makes it harder to understand on discover when filtering by the user, =>https://sentry.io/organizations/sentry-sdks/discover/results/?end=2022-06-03T00%3A23%3A43.000&field=title&field=event.type&field=project&field=user.display&field=timestamp&name=All+Events&project=5522756&query=user.display%3A0bf59fdf-6052-4aa1-84cd-adb9d2b49487+timestamp%3A%3C2022-06-02T18%3A12%3A46%2B00%3A00++timestamp%3A%3E2022-05-30T22%3A54%3A48%2B00%3A00&sort=-timestamp&start=2022-05-30T17%3A20%3A15.000&userModified=true&yAxis=count%28%29

Additionally, it may lead to folks thinking something is slow today where in reality, the slowness actually happened days ago.

getsentry-release commented 2 years ago

Routing to @getsentry/owners-ingest for triage. ⏲️

untitaker commented 2 years ago

This is expected behavior. The clock drift correction comes from the sent_at envelope header: https://develop.sentry.dev/sdk/envelopes/#data-model

Additionally, it may lead to folks thinking something is slow today where in reality, the slowness actually happened days ago.

If you are sending days old transactions and are seeing that clock drift correction is incorrectly correcting timestamps, the sent_at header is most likely set to a timestamp in the past, while it should be the time when the request has been sent out (so, now)

Where transactions will have a different error

Most likely your error events are not sent inside of an envelope, otherwise you'd see the same exact error message as with transactions.

lucas-zimerman commented 2 years ago

I see. From what I saw, both envelopes didn't have the sent_at parameter on the Envelope Headers

Not exactly the same events but those are the body values that I captured that were going to be sent to Sentry: The event

{"event_id":"284f9e9b996648f587c4ca261fd8bc95","sdk":{"name":"sentry.java.android","version":"5.7.0","packages":[{"name":"maven:io.sentry:sentry","version":"5.7.0"},{"name":"maven:io.sentry:sentry-android-core","version":"5.7.0"},{"name":"maven:io.sentry:sentry-android-ndk","version":"5.7.0"}]}}
{"content_type":"application/json","type":"event","length":5882}
{"level":"info","message":{"message":"1653952333948: Captured message on button click."},"timestamp":"2022-05-30T23:12:13.950Z","breadcrumbs":[{"category":"app.lifecycle","data":{"state":"start"},"level":"info","timestamp":"2022-05-30T23:11:51.473Z","type":"session"},{"category":"app.lifecycle","data":{"state":"foreground"},"level":"info","timestamp":"2022-05-30T23:11:51.478Z","type":"navigation"},{"category":"console","data":{"logger":"console","arguments":"[\"Ionic Native: deviceready event fired after 472 ms\"]"},"level":"debug","message":"Ionic Native: deviceready event fired after 472 ms","timestamp":"2022-05-30T23:11:51.690Z"},{"category":"console","data":{"logger":"console","arguments":"[\"Angular is running in development mode. Call enableProdMode() to enable production mode.\"]"},"level":"debug","message":"Angular is running in development mode. Call enableProdMode() to enable production mode.","timestamp":"2022-05-30T23:11:52.013Z"},{"category":"console","data":{"logger":"console","arguments":"[\"Native: tried calling StatusBar.styleDefault, but the StatusBar plugin is not installed.\"]"},"level":"warning","message":"Native: tried calling StatusBar.styleDefault, but the StatusBar plugin is not installed.","timestamp":"2022-05-30T23:11:52.104Z"},{"category":"console","data":{"logger":"console","arguments":"[\"Install the StatusBar plugin: 'ionic cordova plugin add cordova-plugin-statusbar'\"]"},"level":"warning","message":"Install the StatusBar plugin: 'ionic cordova plugin add cordova-plugin-statusbar'","timestamp":"2022-05-30T23:11:52.116Z"},{"category":"console","data":{"logger":"console","arguments":"[\"Native: tried calling SplashScreen.hide, but the SplashScreen plugin is not installed.\"]"},"level":"warning","message":"Native: tried calling SplashScreen.hide, but the SplashScreen plugin is not installed.","timestamp":"2022-05-30T23:11:52.124Z"},{"category":"console","data":{"logger":"console","arguments":"[\"Install the SplashScreen plugin: 'ionic cordova plugin add cordova-plugin-splashscreen'\"]"},"level":"warning","message":"Install the SplashScreen plugin: 'ionic cordova plugin add cordova-plugin-splashscreen'","timestamp":"2022-05-30T23:11:52.133Z"},{"category":"sentry.transaction","message":"402d8bc3f431427a9aa5bd34f51862e1","timestamp":"2022-05-30T23:11:52.518Z"},{"category":"navigation","data":{"from":"/","to":"/tabs/tab1"},"timestamp":"2022-05-30T23:11:53.646Z"},{"category":"fetch","data":{"status_code":"200","method":"GET","__span":"801769c04c17bb8b","url":"/svg/triangle.svg"},"timestamp":"2022-05-30T23:11:54.313Z","type":"http"},{"category":"fetch","data":{"status_code":"200","method":"GET","__span":"9fd4aa99a08c0194","url":"/svg/ellipse.svg"},"timestamp":"2022-05-30T23:11:54.329Z","type":"http"},{"category":"fetch","data":{"status_code":"200","method":"GET","__span":"84bc8e218694c6eb","url":"/svg/square.svg"},"timestamp":"2022-05-30T23:11:54.342Z","type":"http"},{"category":"sentry.transaction","message":"726444fa817e4c34bb8949e617721fe7","timestamp":"2022-05-30T23:11:55.364Z"},{"category":"navigation","data":{"from":"/tabs/tab1","to":"/tabs/tab2"},"timestamp":"2022-05-30T23:12:10.375Z"},{"category":"ui.click","message":"ion-icon.md.hydrated[name=\"ellipse\"]","timestamp":"2022-05-30T23:12:10.422Z"},{"category":"sentry.transaction","message":"8ddfd641115c4939b9aedb10bb8df6ae","timestamp":"2022-05-30T23:12:11.406Z"},{"category":"ui.click","message":"ion-button.md.button.button-solid.ion-activatable.ion-focusable.hydrated.ion-activated","timestamp":"2022-05-30T23:12:13.946Z"},{"category":"sentry.event","level":"info","message":"1653952333948: Captured message on button click.","timestamp":"2022-05-30T23:12:13.958Z"}],"contexts":{"app":{"app_build":"1","app_identifier":"io.ionic.starter","app_name":"ionic-angular","app_start_time":"2022-05-30T23:11:45.944Z","app_version":"1.0"},"os":{"build":"sdk_gphone64_x86_64-userdebug 12 SE1A.211012.001 7818354 dev-keys","kernel_version":"5.10.43-android12-9-00031-g02d62d5cece1-ab7792588","name":"Android","rooted":false,"version":"12"},"device":{"archs":["x86_64","arm64-v8a"],"battery_level":100.0,"battery_temperature":25.0,"boot_time":"2022-05-30T19:34:29.624Z","brand":"google","charging":false,"connection_type":"wifi","external_free_storage":534671360,"external_storage_size":534761472,"family":"sdk_gphone64_x86_64","free_memory":1103474688,"free_storage":5599006720,"id":"0bf59fdf-6052-4aa1-84cd-adb9d2b49487","language":"en","locale":"en_US","low_memory":false,"manufacturer":"Google","memory_size":2064433152,"model":"sdk_gphone64_x86_64","model_id":"SE1A.211012.001","name":"sdk_gphone64_x86_64","online":true,"orientation":"portrait","screen_density":1.0,"screen_dpi":160,"screen_height_pixels":800,"screen_width_pixels":480,"simulator":true,"storage_size":6240665600,"timezone":"America/Sao_Paulo"}},"dist":"1.0.0.1","environment":"staging","event_id":"284f9e9b996648f587c4ca261fd8bc95","platform":"javascript","release":"1.0.0","request":{"headers":{"User-Agent":"Mozilla/5.0 (Linux; Android 12; sdk_gphone64_x86_64 Build/SE1A.211012.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/91.0.4472.114 Mobile Safari/537.36"},"url":"http://localhost/tabs/tab2"},"sdk":{"integrations":["InboundFilters","FunctionToString","TryCatch","Breadcrumbs","GlobalHandlers","LinkedErrors","Dedupe","UserAgent","RewriteFrames","SdkInfo","EventOrigin","DeviceContext","BrowserTracing"],"name":"sentry.javascript.capacitor","packages":[{"name":"npm:@sentry/capacitor","version":"0.6.1"},{"name":"maven:io.sentry:sentry","version":"5.7.0"},{"name":"maven:io.sentry:sentry-android-core","version":"5.7.0"},{"name":"maven:io.sentry:sentry-android-ndk","version":"5.7.0"}],"version":"0.6.1"},"tags":{"event.origin":"javascript","event.environment":"javascript","isSideLoaded":"true"},"user":{"id":"0bf59fdf-6052-4aa1-84cd-adb9d2b49487"}}
{"content_type":"application/json","type":"session","length":245}
{"sid":"8ae9a02e-9c90-43e1-9095-8a4a235a5249","did":"0bf59fdf-6052-4aa1-84cd-adb9d2b49487","init":true,"started":"2022-05-30T23:11:51.474Z","status":"ok","timestamp":"2022-05-30T23:11:51.474Z","attrs":{"release":"1.0.0","environment":"staging"}}

Transaction

{"event_id":"8ddfd641115c4939b9aedb10bb8df6ae","sdk":{"name":"sentry.java.android","version":"5.7.0","packages":[{"name":"maven:io.sentry:sentry","version":"5.7.0"},{"name":"maven:io.sentry:sentry-android-core","version":"5.7.0"},{"name":"maven:io.sentry:sentry-android-ndk","version":"5.7.0"}]}}
{"content_type":"application/json","type":"transaction","length":5766}
{"spans":[{"data":{"Transfer Size":0.0,"Encoded Body Size":0.0,"Decoded Body Size":0.0},"description":"/assets/icon/favicon.png","op":"resource.other","parent_span_id":"946265a375e4b7ad","span_id":"bd50d1d2d059b43b","start_timestamp":"2022-05-30T23:12:10.651Z","timestamp":"2022-05-30T23:12:10.857Z","trace_id":"9e45337938d74d8b8bf4e920215cb781"}],"start_timestamp":"2022-05-30T23:12:10.391Z","timestamp":"2022-05-30T23:12:10.857Z","transaction":"/tabs/tab1","type":"transaction","breadcrumbs":[{"category":"app.lifecycle","data":{"state":"start"},"level":"info","timestamp":"2022-05-30T23:11:51.473Z","type":"session"},{"category":"app.lifecycle","data":{"state":"foreground"},"level":"info","timestamp":"2022-05-30T23:11:51.478Z","type":"navigation"},{"category":"console","data":{"logger":"console","arguments":"[\"Ionic Native: deviceready event fired after 472 ms\"]"},"level":"debug","message":"Ionic Native: deviceready event fired after 472 ms","timestamp":"2022-05-30T23:11:51.690Z"},{"category":"console","data":{"logger":"console","arguments":"[\"Angular is running in development mode. Call enableProdMode() to enable production mode.\"]"},"level":"debug","message":"Angular is running in development mode. Call enableProdMode() to enable production mode.","timestamp":"2022-05-30T23:11:52.013Z"},{"category":"console","data":{"logger":"console","arguments":"[\"Native: tried calling StatusBar.styleDefault, but the StatusBar plugin is not installed.\"]"},"level":"warning","message":"Native: tried calling StatusBar.styleDefault, but the StatusBar plugin is not installed.","timestamp":"2022-05-30T23:11:52.104Z"},{"category":"console","data":{"logger":"console","arguments":"[\"Install the StatusBar plugin: 'ionic cordova plugin add cordova-plugin-statusbar'\"]"},"level":"warning","message":"Install the StatusBar plugin: 'ionic cordova plugin add cordova-plugin-statusbar'","timestamp":"2022-05-30T23:11:52.116Z"},{"category":"console","data":{"logger":"console","arguments":"[\"Native: tried calling SplashScreen.hide, but the SplashScreen plugin is not installed.\"]"},"level":"warning","message":"Native: tried calling SplashScreen.hide, but the SplashScreen plugin is not installed.","timestamp":"2022-05-30T23:11:52.124Z"},{"category":"console","data":{"logger":"console","arguments":"[\"Install the SplashScreen plugin: 'ionic cordova plugin add cordova-plugin-splashscreen'\"]"},"level":"warning","message":"Install the SplashScreen plugin: 'ionic cordova plugin add cordova-plugin-splashscreen'","timestamp":"2022-05-30T23:11:52.133Z"},{"category":"sentry.transaction","message":"402d8bc3f431427a9aa5bd34f51862e1","timestamp":"2022-05-30T23:11:52.518Z"},{"category":"navigation","data":{"from":"/","to":"/tabs/tab1"},"timestamp":"2022-05-30T23:11:53.646Z"},{"category":"fetch","data":{"status_code":"200","method":"GET","__span":"801769c04c17bb8b","url":"/svg/triangle.svg"},"timestamp":"2022-05-30T23:11:54.313Z","type":"http"},{"category":"fetch","data":{"status_code":"200","method":"GET","__span":"9fd4aa99a08c0194","url":"/svg/ellipse.svg"},"timestamp":"2022-05-30T23:11:54.329Z","type":"http"},{"category":"fetch","data":{"status_code":"200","method":"GET","__span":"84bc8e218694c6eb","url":"/svg/square.svg"},"timestamp":"2022-05-30T23:11:54.342Z","type":"http"},{"category":"sentry.transaction","message":"726444fa817e4c34bb8949e617721fe7","timestamp":"2022-05-30T23:11:55.364Z"},{"category":"navigation","data":{"from":"/tabs/tab1","to":"/tabs/tab2"},"timestamp":"2022-05-30T23:12:10.375Z"},{"category":"ui.click","message":"ion-icon.md.hydrated[name=\"ellipse\"]","timestamp":"2022-05-30T23:12:10.422Z"},{"category":"sentry.transaction","message":"8ddfd641115c4939b9aedb10bb8df6ae","timestamp":"2022-05-30T23:12:11.406Z"}],"contexts":{"app":{"app_build":"1","app_identifier":"io.ionic.starter","app_name":"ionic-angular","app_start_time":"2022-05-30T23:11:45.944Z","app_version":"1.0"},"trace":{"op":"navigation","span_id":"946265a375e4b7ad","tags":{"effectiveConnectionType":"4g","connectionType":"wifi","deviceMemory":"2","hardwareConcurrency":"1"},"trace_id":"9e45337938d74d8b8bf4e920215cb781"},"os":{"build":"sdk_gphone64_x86_64-userdebug 12 SE1A.211012.001 7818354 dev-keys","kernel_version":"5.10.43-android12-9-00031-g02d62d5cece1-ab7792588","name":"Android","rooted":false,"version":"12"},"device":{"archs":["x86_64","arm64-v8a"],"boot_time":"2022-05-30T19:34:29.623Z","brand":"google","family":"sdk_gphone64_x86_64","id":"0bf59fdf-6052-4aa1-84cd-adb9d2b49487","language":"en","locale":"en_US","manufacturer":"Google","model":"sdk_gphone64_x86_64","model_id":"SE1A.211012.001","name":"sdk_gphone64_x86_64","orientation":"portrait","screen_density":1.0,"screen_dpi":160,"screen_height_pixels":800,"screen_width_pixels":480,"simulator":true,"timezone":"America/Sao_Paulo"}},"dist":"1.0.0.1","environment":"staging","event_id":"8ddfd641115c4939b9aedb10bb8df6ae","platform":"javascript","release":"1.0.0","request":{"headers":{"User-Agent":"Mozilla/5.0 (Linux; Android 12; sdk_gphone64_x86_64 Build/SE1A.211012.001; wv) AppleWebKit/537.36 (KHTML, like Gecko) Version/4.0 Chrome/91.0.4472.114 Mobile Safari/537.36"},"url":"http://localhost/tabs/tab2"},"sdk":{"integrations":["InboundFilters","FunctionToString","TryCatch","Breadcrumbs","GlobalHandlers","LinkedErrors","Dedupe","UserAgent","RewriteFrames","SdkInfo","EventOrigin","DeviceContext","BrowserTracing"],"name":"sentry.javascript.capacitor","packages":[{"name":"npm:@sentry/capacitor","version":"0.6.1"}],"version":"0.6.1"},"tags":{"effectiveConnectionType":"4g","connectionType":"wifi","deviceMemory":"2","hardwareConcurrency":"1","event.origin":"javascript","event.environment":"javascript","isSideLoaded":"true"},"user":{"id":"0bf59fdf-6052-4aa1-84cd-adb9d2b49487"}}

EDIT: I did a quick research and it seems like the some SDKs sets this sent_at parameter while others don't have this parameter.

untitaker commented 2 years ago

Ok, this is a bug, we should not be applying any sort of clock drift correction unless the event is really old (30 days) or sent_at exists in the envelope. Will create JIRA tickets for this but I don't know when we will get around to it.

github-actions[bot] commented 2 years ago

This issue has gone three weeks without activity. In another week, I will close it.

But! If you comment or otherwise update it, I will reset the clock, and if you label it Status: Backlog or Status: In Progress, I will leave it alone ... forever!

"A weed is but an unloved flower." ― Ella Wheeler Wilcox 🥀