Skip to content

Commit 3aea457

Browse files
antonisclaude
andcommitted
fix(core): Use wall clock for structured log timestamps
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>
1 parent b5bf632 commit 3aea457

2 files changed

Lines changed: 35 additions & 5 deletions

File tree

‎packages/core/src/logs/internal.ts‎

Lines changed: 8 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -10,7 +10,7 @@ import { consoleSandbox, debug } from '../utils/debug-logger';
1010
import { isParameterizedString } from '../utils/is';
1111
import { getCombinedScopeData } from '../utils/scopeData';
1212
import { _getSpanForScope } from '../utils/spanOnScope';
13-
import { timestampInSeconds } from '../utils/time';
13+
import { dateTimestampInSeconds } from '../utils/time';
1414
import { getSequenceAttribute } from '../utils/timestampSequence';
1515
import { _getTraceInfoFromScope } from '../utils/trace-info';
1616
import { SEVERITY_TEXT_TO_SEVERITY_NUMBER } from './constants';
@@ -156,7 +156,13 @@ export function _INTERNAL_captureLog(
156156

157157
const { level, message, attributes: logAttributes = {}, severityNumber } = log;
158158

159-
const timestamp = timestampInSeconds();
159+
// Use the wall-clock (`Date.now()`) rather than `timestampInSeconds()`, which is derived from
160+
// `performance.timeOrigin + performance.now()`. On some platforms (notably React Native/Hermes) that performance
161+
// clock is anchored to process/device uptime instead of the UNIX epoch, which would stamp logs with a timestamp off
162+
// by a large, constant offset. Using the wall clock keeps log timestamps consistent with error-event timestamps
163+
// (which also use `dateTimestampInSeconds()`). Sub-second ordering is preserved via the `sentry.timestamp.sequence`
164+
// attribute below. See: https://github.com/getsentry/sentry-react-native/issues/6510
165+
const timestamp = dateTimestampInSeconds();
160166
const sequenceAttr = getSequenceAttribute(timestamp);
161167

162168
const serializedLog: SerializedLog = {

‎packages/core/test/lib/logs/internal.test.ts‎

Lines changed: 27 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -43,6 +43,30 @@ describe('_INTERNAL_captureLog', () => {
4343
);
4444
});
4545

46+
it('stamps logs with the wall clock (`dateTimestampInSeconds`), not the performance clock', () => {
47+
// On platforms where the performance clock is not anchored to the UNIX epoch (e.g. React Native/Hermes),
48+
// `timestampInSeconds()` would be off by a large constant. Logs must use the wall clock so their timestamps match
49+
// error-event timestamps. See https://github.com/getsentry/sentry-react-native/issues/6510
50+
const wallClockSeconds = 1_784_820_130.576;
51+
const performanceClockSeconds = 1_784_453_353.186;
52+
const dateSpy = vi.spyOn(timeModule, 'dateTimestampInSeconds').mockReturnValue(wallClockSeconds);
53+
const perfSpy = vi.spyOn(timeModule, 'timestampInSeconds').mockReturnValue(performanceClockSeconds);
54+
55+
const options = getDefaultTestClientOptions({ dsn: PUBLIC_DSN, enableLogs: true });
56+
const client = new TestClient(options);
57+
const scope = new Scope();
58+
scope.setClient(client);
59+
60+
_INTERNAL_captureLog({ level: 'info', message: 'clock check' }, scope);
61+
62+
expect(_INTERNAL_getLogBuffer(client)?.[0]?.timestamp).toBe(wallClockSeconds);
63+
expect(dateSpy).toHaveBeenCalled();
64+
expect(perfSpy).not.toHaveBeenCalled();
65+
66+
dateSpy.mockRestore();
67+
perfSpy.mockRestore();
68+
});
69+
4670
it('does not capture logs when enableLogs is not enabled', () => {
4771
const logWarnSpy = vi.spyOn(loggerModule.debug, 'warn').mockImplementation(() => undefined);
4872
const options = getDefaultTestClientOptions({ dsn: PUBLIC_DSN });
@@ -1186,7 +1210,7 @@ describe('_INTERNAL_captureLog', () => {
11861210

11871211
describe('sentry.timestamp.sequence', () => {
11881212
it('increments the sequence number across consecutive logs', () => {
1189-
vi.spyOn(timeModule, 'timestampInSeconds').mockReturnValue(1000.001);
1213+
vi.spyOn(timeModule, 'dateTimestampInSeconds').mockReturnValue(1000.001);
11901214

11911215
const options = getDefaultTestClientOptions({ dsn: PUBLIC_DSN, enableLogs: true });
11921216
const client = new TestClient(options);
@@ -1206,7 +1230,7 @@ describe('_INTERNAL_captureLog', () => {
12061230
});
12071231

12081232
it('does not increment the sequence number for dropped logs', () => {
1209-
vi.spyOn(timeModule, 'timestampInSeconds').mockReturnValue(1000.001);
1233+
vi.spyOn(timeModule, 'dateTimestampInSeconds').mockReturnValue(1000.001);
12101234

12111235
const beforeSendLog = vi.fn().mockImplementation(log => {
12121236
if (log.message === 'drop me') {
@@ -1233,7 +1257,7 @@ describe('_INTERNAL_captureLog', () => {
12331257
});
12341258

12351259
it('produces monotonically increasing sequence numbers within the same millisecond', () => {
1236-
vi.spyOn(timeModule, 'timestampInSeconds').mockReturnValue(1000.001);
1260+
vi.spyOn(timeModule, 'dateTimestampInSeconds').mockReturnValue(1000.001);
12371261

12381262
const options = getDefaultTestClientOptions({ dsn: PUBLIC_DSN, enableLogs: true });
12391263
const client = new TestClient(options);

0 commit comments

Comments
 (0)