Skip to content
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 8 additions & 2 deletions packages/core/src/logs/internal.ts
Original file line number Diff line number Diff line change
Expand Up @@ -10,7 +10,7 @@ import { consoleSandbox, debug } from '../utils/debug-logger';
import { isParameterizedString } from '../utils/is';
import { getCombinedScopeData } from '../utils/scopeData';
import { _getSpanForScope } from '../utils/spanOnScope';
import { timestampInSeconds } from '../utils/time';
import { dateTimestampInSeconds } from '../utils/time';
import { getSequenceAttribute } from '../utils/timestampSequence';
import { _getTraceInfoFromScope } from '../utils/trace-info';
import { SEVERITY_TEXT_TO_SEVERITY_NUMBER } from './constants';
Expand Down Expand Up @@ -156,7 +156,13 @@ export function _INTERNAL_captureLog(

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

const timestamp = timestampInSeconds();
// Use the wall-clock (`Date.now()`) rather than `timestampInSeconds()`, which is derived from
// `performance.timeOrigin + performance.now()`. On some platforms (notably React Native/Hermes) that performance
// clock is anchored to process/device uptime instead of the UNIX epoch, which would stamp logs with a timestamp off
// 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();

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Fix in Cursor Fix in Web

Reviewed by Cursor Bugbot for commit 3aea457. Configure here.

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is valid but I'd wait for feedback from the team before expanding the scope of this change

const sequenceAttr = getSequenceAttribute(timestamp);

const serializedLog: SerializedLog = {
Expand Down
30 changes: 27 additions & 3 deletions packages/core/test/lib/logs/internal.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -43,6 +43,30 @@ describe('_INTERNAL_captureLog', () => {
);
});

it('stamps logs with the wall clock (`dateTimestampInSeconds`), not the performance clock', () => {
// On platforms where the performance clock is not anchored to the UNIX epoch (e.g. React Native/Hermes),
// `timestampInSeconds()` would be off by a large constant. Logs must use the wall clock so their timestamps match
// error-event timestamps. See https://github.com/getsentry/sentry-react-native/issues/6510
const wallClockSeconds = 1_784_820_130.576;
const performanceClockSeconds = 1_784_453_353.186;
const dateSpy = vi.spyOn(timeModule, 'dateTimestampInSeconds').mockReturnValue(wallClockSeconds);
const perfSpy = vi.spyOn(timeModule, 'timestampInSeconds').mockReturnValue(performanceClockSeconds);

const options = getDefaultTestClientOptions({ dsn: PUBLIC_DSN, enableLogs: true });
const client = new TestClient(options);
const scope = new Scope();
scope.setClient(client);

_INTERNAL_captureLog({ level: 'info', message: 'clock check' }, scope);

expect(_INTERNAL_getLogBuffer(client)?.[0]?.timestamp).toBe(wallClockSeconds);
expect(dateSpy).toHaveBeenCalled();
expect(perfSpy).not.toHaveBeenCalled();

dateSpy.mockRestore();
perfSpy.mockRestore();
});

it('does not capture logs when enableLogs is not enabled', () => {
const logWarnSpy = vi.spyOn(loggerModule.debug, 'warn').mockImplementation(() => undefined);
const options = getDefaultTestClientOptions({ dsn: PUBLIC_DSN });
Expand Down Expand Up @@ -1186,7 +1210,7 @@ describe('_INTERNAL_captureLog', () => {

describe('sentry.timestamp.sequence', () => {
it('increments the sequence number across consecutive logs', () => {
vi.spyOn(timeModule, 'timestampInSeconds').mockReturnValue(1000.001);
vi.spyOn(timeModule, 'dateTimestampInSeconds').mockReturnValue(1000.001);

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

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

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

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

const options = getDefaultTestClientOptions({ dsn: PUBLIC_DSN, enableLogs: true });
const client = new TestClient(options);
Expand Down
Loading