Repository navigation
Conversation
Structured logs stamped their timestamp via `timestampInSeconds()`, which returns `performance.timeOrigin + performance.now()` with no wall-clock sanity check. On platforms where the Performance API is not anchored to the UNIX epoch (notably React Native/Hermes, where it tracks device uptime), this made log timestamps off by a large, constant offset while error events (which use `Date.now()`) stayed correct. Switch the log path to `dateTimestampInSeconds()` so log timestamps use the wall clock and match error-event timestamps on every platform. Sub-second ordering is preserved via the existing `sentry.timestamp.sequence` attribute. Scope is limited to the log path; `timestampInSeconds()` and its other consumers (spans, sessions, breadcrumbs, metrics) are unchanged. Closes getsentry/sentry-react-native#6510 Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
![cursor[bot]](https://avatars.githubusercontent.com/in/1210556?s=60&v=4){kind=small}
There was a problem hiding this comment.
Cursor Bugbot has reviewed your changes and found 1 potential issue.
❌ Bugbot Autofix is OFF. To automatically fix reported issues with cloud agents, enable autofix in the Cursor dashboard.
Reviewed by Cursor Bugbot for commit 3aea457. Configure here.
| // by a large, constant offset. Using the wall clock keeps log timestamps consistent with error-event timestamps | ||
| // (which also use `dateTimestampInSeconds()`). Sub-second ordering is preserved via the `sentry.timestamp.sequence` | ||
| // attribute below. See: https://github.com/getsentry/sentry-react-native/issues/6510 | ||
| const timestamp = dateTimestampInSeconds(); |
There was a problem hiding this comment.
Shared sequence breaks across clocks
Medium Severity
Logs now call dateTimestampInSeconds() while metrics still call timestampInSeconds(), but both share one getSequenceAttribute counter keyed by millisecond. On divergent clocks (the React Native/Hermes case this fixes), an interleaved metric resets that counter, so same-ms logs can both get sentry.timestamp.sequence 0 and lose tie-break ordering.
Reviewed by Cursor Bugbot for commit 3aea457. Configure here.
There was a problem hiding this comment.
This is valid but I'd wait for feedback from the team before expanding the scope of this change
|
@antonis how urgently do you need this to land? I have some ideas how we can If you need this urgently, we can merge your fix prior to mine. |
|
Thank you for looking at this @Lms24 🙇
It is not urgent. This is a 2yo issue and the recent spike was attributed to just one user.
Sounds good to me 👍 I tried to keep the scope small on this PR but your approach would solve the root of this :) Feel free to close this PR in favor of your solution. |
|
👋 @Lms24 — Please review this PR when you get a chance! |
1 similar comment
|
👋 @Lms24 — Please review this PR when you get a chance! |
|
Hi, Just wanted to flag a customer report here: their logging backend drops any log with a timestamp more than 30 minutes old, so the clock drift is causing silent data loss. #215475359311819 |
|
👋 @Lms24 — Please review this PR when you get a chance! |
6 similar comments
|
👋 @Lms24 — Please review this PR when you get a chance! |
|
👋 @Lms24 — Please review this PR when you get a chance! |
|
👋 @Lms24 — Please review this PR when you get a chance! |
|
👋 @Lms24 — Please review this PR when you get a chance! |
|
👋 @Lms24 — Please review this PR when you get a chance! |
|
👋 @Lms24 — Please review this PR when you get a chance! |
|
Heads up that I'm working on a fix/patch for this on the React Native side getsentry/sentry-react-native#6654 since it came up on a new issue getsentry/sentry-react-native#6630 that traced back to the same problem. I'm marking this PR as draft for now since it is stale and would probably be superseded by #23054 cc @Lms24 |
|
sounds fair, apologies for the delay on my end @antonis . just be aware that only adjusting logs timestamps will skew the timing across all the other telemetry. Maybe acceptable for the moment but something I'd like to avoid in the long-run. |
|
NP @Lms24. I'll just guard this on the RN side to avoid loosing logs/traces on some configurations. |
This PR fixes* clock drift that occurs when devices go to sleep. After devices sleep for a few seconds, the browser's monotonic clock (accessed via `performance.now()`) stops counting. Once the sleep stops, the monotonic clock resumes right where it left off before the sleep, causing significant discrepancies between the actual time (wall clock) and the browser's monotonic clock time. Or in other words, there are two ways to get an absolute timestamp: - Using the monotonic clock via `peformance.timeOrigin + performance.now()` - has high, sub-millisecond precision and a guarantee that there are no time jumps or adjustments. But suffers from the sleep problem described above - Using the wall clock via `Date.now()` - lower millisecond precision, is known to be corrected (NTP or via users) and can even cause back jumps. But no sleep problem. With this fix, we make the following adjustments, to kinda get the best of both worlds: - Every `timestampInSecondsCall` checks the monotonic against the wall clock. If a threshold of difference is enocuntered, it corrects the `timeOrigin` so that we can keep using the precise monotonic clock, but anchor its relative time to a corrected time origin. - On every time origin correction, we remember the previous origin (up to 30 corrections). Needed for performance entries - Makes `browserPerformanceTimeOrigin` a time origin corrected helper function, where you pass in a relative time that comes from monotonic clock relative timestamps and it returns the time origin that was most accurate at that relative time point. - All spans and other telemetry we create from browsers `PerformanceEntry` objects carry relative times which are completely sleep-drift uncorrected. We use `browserPerformanceTimeOrigin` to return a corrected time stamp so that we can create an absolute timestamp and bring the performance entries to their respective actual time. ### FAQ If you think this sounds complicated, I agree. So let me answer the most obvious questions, because I asked myself these a lot, too: **Why not just always use `Date.now()` and avoid the complicated click drift detection and correction logic?** The main issue with this is that we still need to rely on relative monotonic clock timestamps for performance entries. We cannot correct them just with `Date.now()` alone but we still need to anchor them. So either we rely on the original `window.timeOrigin` and therefore have all performance entry telemetry happen much "earlier" than its surrounding telemetry relying on `Date.now()`, or we keep the time origin correction logic. But even in the second case (where we already pay the tax for drift detection and correction), telemetry would still have two different anchors: `Date.now()` for regular telemetry and the corrected time origin + monotonic time for performance entry telemetry. Another reason is that the monotonic clock gives us sun-millisecond precision while the wall clock stops at a millisecond resolution. **Why the reduction from a drift detection threshold of 5 minutes to just one second?** Because we keep everything centered around detection and origin offset correction, these timestamps need to be as accurate as possible. On phones, short frequent sleeps are very likely to happen. A lot of sleeps can accumulate until that 5 minutes threshold is reached. So it's really important we make these timestamps as accurate as possible. Fwiw, I reproduced this locally and the drift is already noticeable after just a few seconds of sleep. The 5 minutes threshold was arguably far too big beforehand. **Is there precedence for all of this stuff?** Somewhat, but I'd argue we're doing a bit more: OTel uses a mixture of `Date.now()` and `performance.now`: - Spans start at `Date.now()` and at start time, they record a `performance.now()` timestamp. On span end, they also take `performance.now()`, compute the diff and convert that to an end timestamp based on the start timestamp + diff. This is neat because it guarantees monotony in span durations. I stole this in #24903 In other places, OTel relies purely on Date.now(), and for performance entries, they simply take uncorrected timestamps. So our fix is more complete. \* **So... we're good now?** Well, not perfectly and we never will. With this choice we make another commitment (which we already did previously in less obvious cases) to `Date.now()`. This value can drift as well, just not for sleeps: - NTP adjustments: Can make hard correction of the wall clock, or make the clock tick just a bit faster or slower until the device wall clock synced with the network time. - User adjustments: Users can adjust the device time at any time into any direction. I think we'll have to live with both and I'm not particularly worried about them. My main objective is getting rid of the sleep drift. Fixes #2590 Supersedes #22488, #22585, #23067, #23068 --------- Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
3 participants
Before submitting a pull request, please take a look at our
Contributing guidelines and verify:
yarn lint) & (yarn test).Closes getsentry/sentry-react-native#6510
Structured logs (
Sentry.logger.*) are stamped with a timestamp that can be wrong by a large, constant offset on platforms where the Performance API is not anchored to the UNIX epoch — notably React Native/Hermes, whereperformance.timeOrigin + performance.now()tracks device uptime rather than wall-clock time. In one report the offset was ~4.25 days, while error events (which useDate.now()) were correct.Log timestamps are produced by
timestampInSeconds(), which returnsperformance.timeOrigin + performance.now()without any wall-clock sanity check. This PR switches the log path todateTimestampInSeconds()(i.e.Date.now()), so log timestamps use the wall clock and match error-event timestamps on every platform.Sub-second ordering is unaffected: logs already carry the
sentry.timestamp.sequenceattribute, which is the mechanism used to break ties when two logs share the same timestamp.Scope: this is intentionally limited to the log path only.
timestampInSeconds()and all of its other consumers (spans, sessions, breadcrumbs, metrics) are left unchanged, so tracing behavior is not affected.Background
The regression was introduced in #16133 (
ref(core): Switch to standardized log envelope), first shipped in@sentry/core@9.16.0. Before that change, logs were stamped withnew Date().getTime()(wall clock); the refactor switched them totimestampInSeconds().Related: #2590 (Performance-clock vs wall-clock skew).
How was it tested?
_INTERNAL_captureLogstamps logs withdateTimestampInSeconds()(wall clock) and does not calltimestampInSeconds().sentry.timestamp.sequencetests, which mockedtimestampInSeconds(), to mockdateTimestampInSeconds()accordingly.packages/corelogs test suites pass (104 tests).