From c112acb33de63c5096c7a080fbaeb941d414345a Mon Sep 17 00:00:00 2001 From: Rodolfo Carvalho Date: Fri, 25 Sep 2020 19:07:23 +0200 Subject: [PATCH] fix: Reimplement timestamp computation This is a partial improvement to address inconsistencies in browsers and how they implement performance.now(). It mitigates observing timestamps in the past for pageload transactions, but gives no guarantees to navigation transactions. Depending on the platform, the clock used in performance.now() may stop when the computer goes to sleep, creating an ever increasing skew. This skew is more likely to manifest in navigation transactions. Notable Changes - Do not polyfill/patch performance.timeOrigin to avoid changing behavior of third parties that may depend on it. Instead, use an explicit browserPerformanceTimeOrigin where needed. - Use a timestamp based on the Date API for error events, breadcrumbs and envelope header. This should fully resolve the problem of ingesting events with timestamps in the past, as long as the client wall clock is reasonably in sync. - Apply an equivalent workaround that we used for React Native to all JavaScript environments, essentially resetting the timeOrigin used to compute monotonic timestamps when execution starts. --- packages/apm/src/integrations/tracing.ts | 5 +- packages/core/src/baseclient.ts | 4 +- packages/core/src/request.ts | 3 +- packages/core/test/lib/base.test.ts | 3 + packages/hub/src/hub.ts | 4 +- packages/hub/src/scope.ts | 4 +- packages/tracing/src/browser/metrics.ts | 6 +- packages/utils/src/time.ts | 186 ++++++++++++++--------- 8 files changed, 134 insertions(+), 81 deletions(-) diff --git a/packages/apm/src/integrations/tracing.ts b/packages/apm/src/integrations/tracing.ts index 8bf32092c05c..143aea24bbf4 100644 --- a/packages/apm/src/integrations/tracing.ts +++ b/packages/apm/src/integrations/tracing.ts @@ -4,6 +4,7 @@ import { Hub } from '@sentry/hub'; import { Event, EventProcessor, Integration, Severity, Span, SpanContext, TransactionContext } from '@sentry/types'; import { addInstrumentationHandler, + browserPerformanceTimeOrigin, getGlobalObject, isInstanceOf, isMatchingPattern, @@ -570,7 +571,7 @@ export class Tracing implements Integration { * @param transactionSpan The transaction span */ private static _addPerformanceEntries(transactionSpan: SpanClass): void { - if (!global.performance || !global.performance.getEntries) { + if (!global.performance || !global.performance.getEntries || !browserPerformanceTimeOrigin) { // Gatekeeper if performance API not available return; } @@ -587,7 +588,7 @@ export class Tracing implements Integration { } } - const timeOrigin = Tracing._msToSec(performance.timeOrigin); + const timeOrigin = Tracing._msToSec(browserPerformanceTimeOrigin); // eslint-disable-next-line jsdoc/require-jsdoc function addPerformanceNavigationTiming(parent: Span, entry: { [key: string]: number }, event: string): void { diff --git a/packages/core/src/baseclient.ts b/packages/core/src/baseclient.ts index 299cfc4a77a8..6b77eeb5da5e 100644 --- a/packages/core/src/baseclient.ts +++ b/packages/core/src/baseclient.ts @@ -2,13 +2,13 @@ import { Scope } from '@sentry/hub'; import { Client, Event, EventHint, Integration, IntegrationClass, Options, Severity } from '@sentry/types'; import { + dateTimestampInSeconds, Dsn, isPrimitive, isThenable, logger, normalize, SyncPromise, - timestampWithMs, truncate, uuid4, } from '@sentry/utils'; @@ -256,7 +256,7 @@ export abstract class BaseClient implement const prepared: Event = { ...event, event_id: event.event_id || (hint && hint.event_id ? hint.event_id : uuid4()), - timestamp: event.timestamp || timestampWithMs(), + timestamp: event.timestamp || dateTimestampInSeconds(), }; this._applyClientOptions(prepared); diff --git a/packages/core/src/request.ts b/packages/core/src/request.ts index 611283a01a32..d11b486ebc95 100644 --- a/packages/core/src/request.ts +++ b/packages/core/src/request.ts @@ -1,5 +1,4 @@ import { Event } from '@sentry/types'; -import { timestampWithMs } from '@sentry/utils'; import { API } from './api'; @@ -34,7 +33,7 @@ export function eventToSentryRequest(event: Event, api: API): SentryRequest { event_id: event.event_id, // We need to add * 1000 since we divide it by 1000 by default but JS works with ms precision // The reason we use timestampWithMs here is that all clocks across the SDK use the same clock - sent_at: new Date(timestampWithMs() * 1000).toISOString(), + sent_at: new Date().toISOString(), }); const itemHeaders = JSON.stringify({ type: event.type, diff --git a/packages/core/test/lib/base.test.ts b/packages/core/test/lib/base.test.ts index ba4d8061a620..983cafc6a92a 100644 --- a/packages/core/test/lib/base.test.ts +++ b/packages/core/test/lib/base.test.ts @@ -43,6 +43,9 @@ jest.mock('@sentry/utils', () => { timestampWithMs(): number { return 2020; }, + dateTimestampInSeconds(): number { + return 2020; + }, }; }); diff --git a/packages/hub/src/hub.ts b/packages/hub/src/hub.ts index 61d4609a333e..93f8f65a7142 100644 --- a/packages/hub/src/hub.ts +++ b/packages/hub/src/hub.ts @@ -18,7 +18,7 @@ import { TransactionContext, User, } from '@sentry/types'; -import { consoleSandbox, getGlobalObject, isNodeEnv, logger, timestampWithMs, uuid4 } from '@sentry/utils'; +import { consoleSandbox, dateTimestampInSeconds, getGlobalObject, isNodeEnv, logger, uuid4 } from '@sentry/utils'; import { Carrier, DomainAsCarrier, Layer } from './interfaces'; import { Scope } from './scope'; @@ -242,7 +242,7 @@ export class Hub implements HubInterface { return; } - const timestamp = timestampWithMs(); + const timestamp = dateTimestampInSeconds(); const mergedBreadcrumb = { timestamp, ...breadcrumb }; const finalBreadcrumb = beforeBreadcrumb ? (consoleSandbox(() => beforeBreadcrumb(mergedBreadcrumb, hint)) as Breadcrumb | null) diff --git a/packages/hub/src/scope.ts b/packages/hub/src/scope.ts index d52a1814ab86..7f0905ab7bc2 100644 --- a/packages/hub/src/scope.ts +++ b/packages/hub/src/scope.ts @@ -16,7 +16,7 @@ import { Transaction, User, } from '@sentry/types'; -import { getGlobalObject, isPlainObject, isThenable, SyncPromise, timestampWithMs } from '@sentry/utils'; +import { dateTimestampInSeconds, getGlobalObject, isPlainObject, isThenable, SyncPromise } from '@sentry/utils'; /** * Holds additional event information. {@link Scope.applyToEvent} will be @@ -302,7 +302,7 @@ export class Scope implements ScopeInterface { */ public addBreadcrumb(breadcrumb: Breadcrumb, maxBreadcrumbs?: number): this { const mergedBreadcrumb = { - timestamp: timestampWithMs(), + timestamp: dateTimestampInSeconds(), ...breadcrumb, }; diff --git a/packages/tracing/src/browser/metrics.ts b/packages/tracing/src/browser/metrics.ts index c729248caf95..82d3741d3b86 100644 --- a/packages/tracing/src/browser/metrics.ts +++ b/packages/tracing/src/browser/metrics.ts @@ -1,7 +1,7 @@ /* eslint-disable max-lines */ /* eslint-disable @typescript-eslint/no-explicit-any */ import { SpanContext } from '@sentry/types'; -import { getGlobalObject, logger } from '@sentry/utils'; +import { browserPerformanceTimeOrigin, getGlobalObject, logger } from '@sentry/utils'; import { Span } from '../span'; import { Transaction } from '../transaction'; @@ -27,7 +27,7 @@ export class MetricsInstrumentation { /** Add performance related spans to a transaction */ public addPerformanceEntries(transaction: Transaction): void { - if (!global || !global.performance || !global.performance.getEntries) { + if (!global || !global.performance || !global.performance.getEntries || !browserPerformanceTimeOrigin) { // Gatekeeper if performance API not available return; } @@ -44,7 +44,7 @@ export class MetricsInstrumentation { } } - const timeOrigin = msToSec(performance.timeOrigin); + const timeOrigin = msToSec(browserPerformanceTimeOrigin); let entryScriptSrc: string | undefined; if (global.document) { diff --git a/packages/utils/src/time.ts b/packages/utils/src/time.ts index 68bd5c600d45..83920c2417c6 100644 --- a/packages/utils/src/time.ts +++ b/packages/utils/src/time.ts @@ -1,98 +1,148 @@ import { getGlobalObject } from './misc'; import { dynamicRequire, isNodeEnv } from './node'; -const INITIAL_TIME = Date.now(); +/** + * An object that can return the current timestamp in seconds since the UNIX epoch. + */ +interface TimestampSource { + nowSeconds(): number; +} + +/** + * A TimestampSource implementation for environments that do not support the Performance Web API natively. + * + * Note that this TimestampSource does not use a monotonic clock. A call to `nowSeconds` may return a timestamp earlier + * than a previously returned value. We do not try to emulate a monotonic behavior in order to facilitate debugging. It + * is more obvious to explain "why does my span have negative duration" than "why my spans have zero duration". + */ +const dateTimestampSource: TimestampSource = { + nowSeconds: () => Date.now() / 1000, +}; /** - * Cross platform compatible partial performance implementation + * A partial definition of the [Performance Web API]{@link https://developer.mozilla.org/en-US/docs/Web/API/Performance} + * for accessing a high resolution monotonic clock. */ -interface CrossPlatformPerformance { +interface Performance { + /** + * The millisecond timestamp at which measurement began, measured in Unix time. + */ timeOrigin: number; /** - * Returns the current timestamp in ms + * Returns the current millisecond timestamp, where 0 represents the start of measurement. */ now(): number; } -let prevNow = 0; - -const performanceFallback: CrossPlatformPerformance = { - now(): number { - let now = Date.now() - INITIAL_TIME; - if (now < prevNow) { - now = prevNow; - } - prevNow = now; - return now; - }, - timeOrigin: INITIAL_TIME, -}; - -const crossPlatformPerformance: CrossPlatformPerformance = ((): CrossPlatformPerformance => { - // React Native's performance.now() starts with a gigantic offset, so we need to wrap it. - if (isReactNative()) { - return getReactNativePerformanceWrapper(); - } - - if (isNodeEnv()) { - try { - const perfHooks = dynamicRequire(module, 'perf_hooks') as { performance: CrossPlatformPerformance }; - return perfHooks.performance; - } catch (_) { - return performanceFallback; - } - } - +/** + * Returns a wrapper around the native Performance API browser implementation, or undefined for browsers that do not + * support the API. + * + * Wrapping the native API works around differences in behavior from different browsers. + */ +function getBrowserPerformance(): Performance | undefined { const { performance } = getGlobalObject(); - if (!performance || !performance.now) { - return performanceFallback; + return undefined; } - // Polyfill for performance.timeOrigin. + // Replace performance.timeOrigin with our own timeOrigin based on Date.now(). // - // While performance.timing.navigationStart is deprecated in favor of performance.timeOrigin, performance.timeOrigin - // is not as widely supported. Namely, performance.timeOrigin is undefined in Safari as of writing. - if (performance.timeOrigin === undefined) { - // As of writing, performance.timing is not available in Web Workers in mainstream browsers, so it is not always a - // valid fallback. In the absence of a initial time provided by the browser, fallback to INITIAL_TIME. - // @ts-ignore ignored because timeOrigin is a readonly property but we want to override - // eslint-disable-next-line deprecation/deprecation - performance.timeOrigin = (performance.timing && performance.timing.navigationStart) || INITIAL_TIME; - } + // This is a partial workaround for browsers reporting performance.timeOrigin such that performance.timeOrigin + + // performance.now() gives a date arbitrarily in the past. + // + // Additionally, computing timeOrigin in this way fills the gap for browsers where performance.timeOrigin is + // undefined. + // + // The assumption that performance.timeOrigin + performance.now() ~= Date.now() is flawed, but we depend on it to + // interact with data coming out of performance entries. + // + // Note that despite recommendations against it in the spec, browsers implement the Performance API with a clock that + // might stop when the computer is asleep (and perhaps under other circumstances). Such behavior causes + // performance.timeOrigin + performance.now() to have an arbitrary skew over Date.now(). In laptop computers, we have + // observed skews that can be as long as days, weeks or months. + // + // See https://github.com/getsentry/sentry-javascript/issues/2590. + // + // BUG: despite our best intentions, this workaround has its limitations. It mostly addresses timings of pageload + // transactions, but ignores the skew built up over time that can aversely affect timestamps of navigation + // transactions of long-lived web pages. + const timeOrigin = Date.now() - performance.now(); - return performance; -})(); + return { + now: () => performance.now(), + timeOrigin, + }; +} /** - * Returns a timestamp in seconds with milliseconds precision since the UNIX epoch calculated with the monotonic clock. + * Returns the native Performance API implementation from Node.js. Returns undefined in old Node.js versions that don't + * implement the API. */ -export function timestampWithMs(): number { - return (crossPlatformPerformance.timeOrigin + crossPlatformPerformance.now()) / 1000; +function getNodePerformance(): Performance | undefined { + try { + const perfHooks = dynamicRequire(module, 'perf_hooks') as { performance: Performance }; + return perfHooks.performance; + } catch (_) { + return undefined; + } } /** - * Determines if running in react native + * The Performance API implementation for the current platform, if available. */ -function isReactNative(): boolean { - return getGlobalObject().navigator?.product === 'ReactNative'; -} +const platformPerformance: Performance | undefined = isNodeEnv() ? getNodePerformance() : getBrowserPerformance(); + +const timestampSource: TimestampSource = + platformPerformance === undefined + ? dateTimestampSource + : { + nowSeconds: () => (platformPerformance.timeOrigin + platformPerformance.now()) / 1000, + }; /** - * Performance wrapper for react native as performance.now() has been found to start off with an unusual offset. + * Returns a timestamp in seconds since the UNIX epoch using the Date API. */ -function getReactNativePerformanceWrapper(): CrossPlatformPerformance { - // Performance only available >= RN 0.63 - const { performance } = getGlobalObject(); - if (performance && typeof performance.now === 'function') { - const INITIAL_OFFSET = performance.now(); +export const dateTimestampInSeconds = dateTimestampSource.nowSeconds.bind(dateTimestampSource); + +/** + * Returns a timestamp in seconds since the UNIX epoch using either the Performance or Date APIs, depending on the + * availability of the Performance API. + * + * See `usingPerformanceAPI` to test whether the Performance API is used. + * + * BUG: Note that because of how browsers implement the Performance API, the clock might stop when the computer is + * asleep. This creates a skew between `dateTimestampInSeconds` and `timestampInSeconds`. The + * skew can grow to arbitrary amounts like days, weeks or months. + * See https://github.com/getsentry/sentry-javascript/issues/2590. + */ +export const timestampInSeconds = timestampSource.nowSeconds.bind(timestampSource); - return { - now(): number { - return performance.now() - INITIAL_OFFSET; - }, - timeOrigin: INITIAL_TIME, - }; +// Re-exported with an old name for backwards-compatibility. +export const timestampWithMs = timestampInSeconds; + +/** + * A boolean that is true when timestampInSeconds uses the Performance API to produce monotonic timestamps. + */ +export const usingPerformanceAPI = platformPerformance !== undefined; + +/** + * The number of milliseconds since the UNIX epoch. This value is only usable in a browser, and only when the + * performance API is available. + */ +export const browserPerformanceTimeOrigin = ((): number | undefined => { + const { performance } = getGlobalObject(); + if (!performance) { + return undefined; } - return performanceFallback; -} + if (performance.timeOrigin) { + return performance.timeOrigin; + } + // While performance.timing.navigationStart is deprecated in favor of performance.timeOrigin, performance.timeOrigin + // is not as widely supported. Namely, performance.timeOrigin is undefined in Safari as of writing. + // Also as of writing, performance.timing is not available in Web Workers in mainstream browsers, so it is not always + // a valid fallback. In the absence of an initial time provided by the browser, fallback to the current time from the + // Date API. + // eslint-disable-next-line deprecation/deprecation + return (performance.timing && performance.timing.navigationStart) || Date.now(); +})();