diff --git a/packages/browser/src/client.ts b/packages/browser/src/client.ts index 0e5b3fb6214c..4ae9562f7ea3 100644 --- a/packages/browser/src/client.ts +++ b/packages/browser/src/client.ts @@ -15,11 +15,14 @@ import { addAutoIpAddressToUser, applySdkMetadata, getSDKSource, + _INTERNAL_flushLogsBuffer, } from '@sentry/core'; import { eventFromException, eventFromMessage } from './eventbuilder'; import { WINDOW } from './helpers'; import type { BrowserTransportOptions } from './transports/types'; +const DEFAULT_FLUSH_INTERVAL = 5000; + /** * Configuration options for the Sentry Browser SDK. * @see @sentry/core Options for more information. @@ -65,6 +68,7 @@ export type BrowserClientOptions = ClientOptions & * @see SentryClient for usage documentation. */ export class BrowserClient extends Client { + private _logFlushIdleTimeout: ReturnType | undefined; /** * Creates a new Browser SDK instance. * @@ -81,17 +85,41 @@ export class BrowserClient extends Client { super(opts); + // eslint-disable-next-line @typescript-eslint/no-this-alias + const client = this; + const { sendDefaultPii, _experiments } = client._options; + const enableLogs = _experiments?.enableLogs; + if (opts.sendClientReports && WINDOW.document) { WINDOW.document.addEventListener('visibilitychange', () => { if (WINDOW.document.visibilityState === 'hidden') { this._flushOutcomes(); + if (enableLogs) { + _INTERNAL_flushLogsBuffer(client); + } } }); } - if (this._options.sendDefaultPii) { - this.on('postprocessEvent', addAutoIpAddressToUser); - this.on('beforeSendSession', addAutoIpAddressToSession); + if (enableLogs) { + client.on('flush', () => { + _INTERNAL_flushLogsBuffer(client); + }); + + client.on('afterCaptureLog', () => { + if (client._logFlushIdleTimeout) { + clearTimeout(client._logFlushIdleTimeout); + } + + client._logFlushIdleTimeout = setTimeout(() => { + _INTERNAL_flushLogsBuffer(client); + }, DEFAULT_FLUSH_INTERVAL); + }); + } + + if (sendDefaultPii) { + client.on('postprocessEvent', addAutoIpAddressToUser); + client.on('beforeSendSession', addAutoIpAddressToSession); } } diff --git a/packages/browser/src/log.ts b/packages/browser/src/log.ts index 23322c168a67..ba4783e0c1c4 100644 --- a/packages/browser/src/log.ts +++ b/packages/browser/src/log.ts @@ -1,53 +1,5 @@ -import type { LogSeverityLevel, Log, Client, ParameterizedString } from '@sentry/core'; -import { getClient, _INTERNAL_captureLog, _INTERNAL_flushLogsBuffer } from '@sentry/core'; - -import { WINDOW } from './helpers'; - -/** - * TODO: Make this configurable - */ -const DEFAULT_FLUSH_INTERVAL = 5000; - -let timeout: ReturnType | undefined; - -/** - * This is a global timeout that is used to flush the logs buffer. - * It is used to ensure that logs are flushed even if the client is not flushed. - */ -function startFlushTimeout(client: Client): void { - if (timeout) { - clearTimeout(timeout); - } - - timeout = setTimeout(() => { - _INTERNAL_flushLogsBuffer(client); - }, DEFAULT_FLUSH_INTERVAL); -} - -let isClientListenerAdded = false; -/** - * This is a function that is used to add a flush listener to the client. - * It is used to ensure that the logger buffer is flushed when the client is flushed. - */ -function addFlushingListeners(client: Client): void { - if (isClientListenerAdded || !client.getOptions()._experiments?.enableLogs) { - return; - } - - isClientListenerAdded = true; - - if (WINDOW.document) { - WINDOW.document.addEventListener('visibilitychange', () => { - if (WINDOW.document.visibilityState === 'hidden') { - _INTERNAL_flushLogsBuffer(client); - } - }); - } - - client.on('flush', () => { - _INTERNAL_flushLogsBuffer(client); - }); -} +import type { LogSeverityLevel, Log, ParameterizedString } from '@sentry/core'; +import { _INTERNAL_captureLog } from '@sentry/core'; /** * Capture a log with the given level. @@ -63,14 +15,7 @@ function captureLog( attributes?: Log['attributes'], severityNumber?: Log['severityNumber'], ): void { - const client = getClient(); - if (client) { - addFlushingListeners(client); - - startFlushTimeout(client); - } - - _INTERNAL_captureLog({ level, message, attributes, severityNumber }, client, undefined); + _INTERNAL_captureLog({ level, message, attributes, severityNumber }); } /** diff --git a/packages/browser/test/client.test.ts b/packages/browser/test/client.test.ts new file mode 100644 index 000000000000..66d825eea892 --- /dev/null +++ b/packages/browser/test/client.test.ts @@ -0,0 +1,120 @@ +/** + * @vitest-environment jsdom + */ + +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; +import * as sentryCore from '@sentry/core'; +import { BrowserClient } from '../src/client'; +import { WINDOW } from '../src/helpers'; +import { getDefaultBrowserClientOptions } from './helper/browser-client-options'; + +vi.mock('@sentry/core', async requireActual => { + return { + ...((await requireActual()) as any), + _INTERNAL_flushLogsBuffer: vi.fn(), + }; +}); + +describe('BrowserClient', () => { + let client: BrowserClient; + const DEFAULT_FLUSH_INTERVAL = 5000; + + afterEach(() => { + vi.useRealTimers(); + vi.clearAllMocks(); + }); + + it('does not flush logs when logs are disabled', () => { + client = new BrowserClient( + getDefaultBrowserClientOptions({ + _experiments: { enableLogs: false }, + sendClientReports: true, + }), + ); + + // Add some logs + sentryCore._INTERNAL_captureLog({ level: 'info', message: 'test log 1' }, client); + sentryCore._INTERNAL_captureLog({ level: 'info', message: 'test log 2' }, client); + + // Simulate visibility change to hidden + if (WINDOW.document) { + Object.defineProperty(WINDOW.document, 'visibilityState', { value: 'hidden' }); + WINDOW.document.dispatchEvent(new Event('visibilitychange')); + } + + expect(sentryCore._INTERNAL_flushLogsBuffer).not.toHaveBeenCalled(); + }); + + describe('log flushing', () => { + beforeEach(() => { + vi.useFakeTimers(); + client = new BrowserClient( + getDefaultBrowserClientOptions({ + _experiments: { enableLogs: true }, + sendClientReports: true, + }), + ); + }); + + it('flushes logs when page visibility changes to hidden', () => { + const flushOutcomesSpy = vi.spyOn(client as any, '_flushOutcomes'); + + // Add some logs + sentryCore._INTERNAL_captureLog({ level: 'info', message: 'test log 1' }, client); + sentryCore._INTERNAL_captureLog({ level: 'info', message: 'test log 2' }, client); + + // Simulate visibility change to hidden + if (WINDOW.document) { + Object.defineProperty(WINDOW.document, 'visibilityState', { value: 'hidden' }); + WINDOW.document.dispatchEvent(new Event('visibilitychange')); + } + + expect(flushOutcomesSpy).toHaveBeenCalled(); + expect(sentryCore._INTERNAL_flushLogsBuffer).toHaveBeenCalledWith(client); + }); + + it('flushes logs on flush event', () => { + // Add some logs + sentryCore._INTERNAL_captureLog({ level: 'info', message: 'test log 1' }, client); + sentryCore._INTERNAL_captureLog({ level: 'info', message: 'test log 2' }, client); + + // Trigger flush event + client.emit('flush'); + + expect(sentryCore._INTERNAL_flushLogsBuffer).toHaveBeenCalledWith(client); + }); + + it('flushes logs after idle timeout', () => { + // Add a log which will trigger afterCaptureLog event + sentryCore._INTERNAL_captureLog({ level: 'info', message: 'test log' }, client); + + // Fast forward the idle timeout + vi.advanceTimersByTime(DEFAULT_FLUSH_INTERVAL); + + expect(sentryCore._INTERNAL_flushLogsBuffer).toHaveBeenCalledWith(client); + }); + + it('resets idle timeout when new logs are captured', () => { + // Add initial log + sentryCore._INTERNAL_captureLog({ level: 'info', message: 'test log 1' }, client); + + // Fast forward part of the idle timeout + vi.advanceTimersByTime(DEFAULT_FLUSH_INTERVAL / 2); + + // Add another log which should reset the timeout + sentryCore._INTERNAL_captureLog({ level: 'info', message: 'test log 2' }, client); + + // Fast forward the remaining time + vi.advanceTimersByTime(DEFAULT_FLUSH_INTERVAL / 2); + + // Should not have flushed yet since timeout was reset + expect(sentryCore._INTERNAL_flushLogsBuffer).not.toHaveBeenCalled(); + + // Fast forward the full timeout + vi.advanceTimersByTime(DEFAULT_FLUSH_INTERVAL); + + // Now should have flushed both logs + expect(sentryCore._INTERNAL_flushLogsBuffer).toHaveBeenCalledWith(client); + }); + }); +}); diff --git a/packages/browser/test/log.test.ts b/packages/browser/test/log.test.ts index 9cddc3ecfc71..d9bf63ce5fce 100644 --- a/packages/browser/test/log.test.ts +++ b/packages/browser/test/log.test.ts @@ -68,151 +68,87 @@ describe('Logger', () => { it('should call _INTERNAL_captureLog with trace level', () => { logger.trace('Test trace message', { key: 'value' }); - expect(mockCaptureLog).toHaveBeenCalledWith( - { - level: 'trace', - message: 'Test trace message', - attributes: { key: 'value' }, - severityNumber: undefined, - }, - expect.any(Object), - undefined, - ); + expect(mockCaptureLog).toHaveBeenCalledWith({ + level: 'trace', + message: 'Test trace message', + attributes: { key: 'value' }, + severityNumber: undefined, + }); }); it('should call _INTERNAL_captureLog with debug level', () => { logger.debug('Test debug message', { key: 'value' }); - expect(mockCaptureLog).toHaveBeenCalledWith( - { - level: 'debug', - message: 'Test debug message', - attributes: { key: 'value' }, - severityNumber: undefined, - }, - expect.any(Object), - undefined, - ); + expect(mockCaptureLog).toHaveBeenCalledWith({ + level: 'debug', + message: 'Test debug message', + attributes: { key: 'value' }, + severityNumber: undefined, + }); }); it('should call _INTERNAL_captureLog with info level', () => { logger.info('Test info message', { key: 'value' }); - expect(mockCaptureLog).toHaveBeenCalledWith( - { - level: 'info', - message: 'Test info message', - attributes: { key: 'value' }, - severityNumber: undefined, - }, - expect.any(Object), - undefined, - ); + expect(mockCaptureLog).toHaveBeenCalledWith({ + level: 'info', + message: 'Test info message', + attributes: { key: 'value' }, + severityNumber: undefined, + }); }); it('should call _INTERNAL_captureLog with warn level', () => { logger.warn('Test warn message', { key: 'value' }); - expect(mockCaptureLog).toHaveBeenCalledWith( - { - level: 'warn', - message: 'Test warn message', - attributes: { key: 'value' }, - severityNumber: undefined, - }, - expect.any(Object), - undefined, - ); + expect(mockCaptureLog).toHaveBeenCalledWith({ + level: 'warn', + message: 'Test warn message', + attributes: { key: 'value' }, + severityNumber: undefined, + }); }); it('should call _INTERNAL_captureLog with error level', () => { logger.error('Test error message', { key: 'value' }); - expect(mockCaptureLog).toHaveBeenCalledWith( - { - level: 'error', - message: 'Test error message', - attributes: { key: 'value' }, - severityNumber: undefined, - }, - expect.any(Object), - undefined, - ); + expect(mockCaptureLog).toHaveBeenCalledWith({ + level: 'error', + message: 'Test error message', + attributes: { key: 'value' }, + severityNumber: undefined, + }); }); it('should call _INTERNAL_captureLog with fatal level', () => { logger.fatal('Test fatal message', { key: 'value' }); - expect(mockCaptureLog).toHaveBeenCalledWith( - { - level: 'fatal', - message: 'Test fatal message', - attributes: { key: 'value' }, - severityNumber: undefined, - }, - expect.any(Object), - undefined, - ); + expect(mockCaptureLog).toHaveBeenCalledWith({ + level: 'fatal', + message: 'Test fatal message', + attributes: { key: 'value' }, + severityNumber: undefined, + }); }); }); - describe('Automatic flushing', () => { - it('should flush logs after timeout', () => { - logger.info('Test message'); - expect(mockFlushLogsBuffer).not.toHaveBeenCalled(); - - // Fast-forward time by 5000ms (the default flush interval) - vi.advanceTimersByTime(5000); - - expect(mockFlushLogsBuffer).toHaveBeenCalledTimes(1); - expect(mockFlushLogsBuffer).toHaveBeenCalledWith(expect.any(Object)); - }); - - it('should restart the flush timeout when a new log is captured', () => { - logger.info('First message'); - - // Advance time by 3000ms (not enough to trigger flush) - vi.advanceTimersByTime(3000); - expect(mockFlushLogsBuffer).not.toHaveBeenCalled(); - - // Log another message, which should reset the timer - logger.info('Second message'); - - // Advance time by 3000ms again (should be 6000ms total, but timer was reset) - vi.advanceTimersByTime(3000); - expect(mockFlushLogsBuffer).not.toHaveBeenCalled(); - - // Advance time to complete the 5000ms after the second message - vi.advanceTimersByTime(2000); - expect(mockFlushLogsBuffer).toHaveBeenCalledTimes(1); - }); - - it('should handle parameterized strings with parameters', () => { - logger.info(logger.fmt`Hello ${'John'}, your balance is ${100}`, { userId: 123 }); - expect(mockCaptureLog).toHaveBeenCalledWith( - { - level: 'info', - message: expect.objectContaining({ - __sentry_template_string__: 'Hello %s, your balance is %s', - __sentry_template_values__: ['John', 100], - }), - attributes: { - userId: 123, - }, - }, - expect.any(Object), - undefined, - ); + it('should handle parameterized strings with parameters', () => { + logger.info(logger.fmt`Hello ${'John'}, your balance is ${100}`, { userId: 123 }); + expect(mockCaptureLog).toHaveBeenCalledWith({ + level: 'info', + message: expect.objectContaining({ + __sentry_template_string__: 'Hello %s, your balance is %s', + __sentry_template_values__: ['John', 100], + }), + attributes: { + userId: 123, + }, }); + }); - it('should handle parameterized strings without additional attributes', () => { - logger.debug(logger.fmt`User ${'Alice'} logged in from ${'mobile'}`); - expect(mockCaptureLog).toHaveBeenCalledWith( - { - level: 'debug', - message: expect.objectContaining({ - __sentry_template_string__: 'User %s logged in from %s', - __sentry_template_values__: ['Alice', 'mobile'], - }), - }, - expect.any(Object), - undefined, - ); + it('should handle parameterized strings without additional attributes', () => { + logger.debug(logger.fmt`User ${'Alice'} logged in from ${'mobile'}`); + expect(mockCaptureLog).toHaveBeenCalledWith({ + level: 'debug', + message: expect.objectContaining({ + __sentry_template_string__: 'User %s logged in from %s', + __sentry_template_values__: ['Alice', 'mobile'], + }), }); }); }); diff --git a/packages/core/src/index.ts b/packages/core/src/index.ts index 800df99e1c0e..5f5c4e6768b7 100644 --- a/packages/core/src/index.ts +++ b/packages/core/src/index.ts @@ -113,7 +113,7 @@ export { instrumentFetchRequest } from './fetch'; export { trpcMiddleware } from './trpc'; export { captureFeedback } from './feedback'; export type { ReportDialogOptions } from './report-dialog'; -export { _INTERNAL_captureLog, _INTERNAL_flushLogsBuffer } from './logs'; +export { _INTERNAL_captureLog, _INTERNAL_flushLogsBuffer } from './logs/exports'; // TODO: Make this structure pretty again and don't do "export *" export * from './utils-hoist/index'; diff --git a/packages/core/src/logs/index.ts b/packages/core/src/logs/exports.ts similarity index 94% rename from packages/core/src/logs/index.ts rename to packages/core/src/logs/exports.ts index fbe1b40493c3..5e12f5739729 100644 --- a/packages/core/src/logs/index.ts +++ b/packages/core/src/logs/exports.ts @@ -41,7 +41,7 @@ export function logAttributeToSerializedLogAttribute(key: string, value: unknown let stringValue = ''; try { stringValue = JSON.stringify(value) ?? ''; - } catch (_) { + } catch { // Do nothing } return { @@ -62,7 +62,11 @@ export function logAttributeToSerializedLogAttribute(key: string, value: unknown * @experimental This method will experience breaking changes. This is not yet part of * the stable Sentry SDK API and can be changed or removed without warning. */ -export function _INTERNAL_captureLog(beforeLog: Log, client = getClient(), scope = getCurrentScope()): void { +export function _INTERNAL_captureLog( + beforeLog: Log, + client: Client | undefined = getClient(), + scope = getCurrentScope(), +): void { if (!client) { DEBUG_BUILD && logger.warn('No client available to capture log.'); return; @@ -143,6 +147,9 @@ export function _INTERNAL_captureLog(beforeLog: Log, client = getClient(), scope * * @param client - A client. * @param maybeLogBuffer - A log buffer. Uses the log buffer for the given client if not provided. + * + * @experimental This method will experience breaking changes. This is not yet part of + * the stable Sentry SDK API and can be changed or removed without warning. */ export function _INTERNAL_flushLogsBuffer(client: Client, maybeLogBuffer?: Array): void { const logBuffer = maybeLogBuffer ?? CLIENT_TO_LOG_BUFFER_MAP.get(client) ?? []; diff --git a/packages/core/src/server-runtime-client.ts b/packages/core/src/server-runtime-client.ts index 16af7b57f7c4..dfada209fcfd 100644 --- a/packages/core/src/server-runtime-client.ts +++ b/packages/core/src/server-runtime-client.ts @@ -22,7 +22,7 @@ import { eventFromMessage, eventFromUnknownInput } from './utils-hoist/eventbuil import { logger } from './utils-hoist/logger'; import { uuid4 } from './utils-hoist/misc'; import { resolvedSyncPromise } from './utils-hoist/syncpromise'; -import { _INTERNAL_flushLogsBuffer } from './logs'; +import { _INTERNAL_flushLogsBuffer } from './logs/exports'; import { isPrimitive } from './utils-hoist'; export interface ServerRuntimeClientOptions extends ClientOptions { @@ -51,23 +51,26 @@ export class ServerRuntimeClient< this._logWeight = 0; - // eslint-disable-next-line @typescript-eslint/no-this-alias - const client = this; - this.on('flush', () => { - _INTERNAL_flushLogsBuffer(client); - }); - - this.on('afterCaptureLog', log => { - client._logWeight += estimateLogSizeInBytes(log); - - // We flush the logs buffer if it exceeds 0.8 MB - // The log weight is a rough estimate, so we flush way before - // the payload gets too big. - if (client._logWeight > 800_000) { + if (this._options._experiments?.enableLogs) { + // eslint-disable-next-line @typescript-eslint/no-this-alias + const client = this; + client.on('flush', () => { _INTERNAL_flushLogsBuffer(client); client._logWeight = 0; - } - }); + }); + + client.on('afterCaptureLog', log => { + client._logWeight += estimateLogSizeInBytes(log); + + // We flush the logs buffer if it exceeds 0.8 MB + // The log weight is a rough estimate, so we flush way before + // the payload gets too big. + if (client._logWeight >= 800_000) { + _INTERNAL_flushLogsBuffer(client); + client._logWeight = 0; + } + }); + } } /** diff --git a/packages/core/test/lib/logs/index.test.ts b/packages/core/test/lib/logs/exports.test.ts similarity index 99% rename from packages/core/test/lib/logs/index.test.ts rename to packages/core/test/lib/logs/exports.test.ts index e2b7eba781d2..acc40ba0c361 100644 --- a/packages/core/test/lib/logs/index.test.ts +++ b/packages/core/test/lib/logs/exports.test.ts @@ -4,7 +4,7 @@ import { _INTERNAL_getLogBuffer, _INTERNAL_captureLog, logAttributeToSerializedLogAttribute, -} from '../../../src/logs'; +} from '../../../src/logs/exports'; import { TestClient, getDefaultTestClientOptions } from '../../mocks/client'; import * as loggerModule from '../../../src/utils-hoist/logger'; import { Scope, fmt } from '../../../src'; diff --git a/packages/core/test/lib/server-runtime-client.test.ts b/packages/core/test/lib/server-runtime-client.test.ts index bbe1e441cad4..87c62b1567d4 100644 --- a/packages/core/test/lib/server-runtime-client.test.ts +++ b/packages/core/test/lib/server-runtime-client.test.ts @@ -4,6 +4,7 @@ import { describe, expect, it, test, vi } from 'vitest'; import { Scope, createTransport } from '../../src'; import type { ServerRuntimeClientOptions } from '../../src/server-runtime-client'; import { ServerRuntimeClient } from '../../src/server-runtime-client'; +import { _INTERNAL_captureLog } from '../../src/logs/exports'; const PUBLIC_DSN = 'https://username@domain/123'; @@ -206,4 +207,77 @@ describe('ServerRuntimeClient', () => { ]); }); }); + + describe('log weight-based flushing', () => { + it('flushes logs when weight exceeds 800KB', () => { + const options = getDefaultClientOptions({ + dsn: PUBLIC_DSN, + _experiments: { enableLogs: true }, + }); + client = new ServerRuntimeClient(options); + + const sendEnvelopeSpy = vi.spyOn(client, 'sendEnvelope'); + + // Create a large log message that will exceed the 800KB threshold + const largeMessage = 'x'.repeat(400_000); // 400KB string + _INTERNAL_captureLog({ message: largeMessage, level: 'info' }, client); + + expect(sendEnvelopeSpy).toHaveBeenCalledTimes(1); + expect(client['_logWeight']).toBe(0); // Weight should be reset after flush + }); + + it('accumulates log weight without flushing when under threshold', () => { + const options = getDefaultClientOptions({ + dsn: PUBLIC_DSN, + _experiments: { enableLogs: true }, + }); + client = new ServerRuntimeClient(options); + + const sendEnvelopeSpy = vi.spyOn(client, 'sendEnvelope'); + + // Create a log message that won't exceed the threshold + const message = 'x'.repeat(100_000); // 100KB string + _INTERNAL_captureLog({ message, level: 'info' }, client); + + expect(sendEnvelopeSpy).not.toHaveBeenCalled(); + expect(client['_logWeight']).toBeGreaterThan(0); + }); + + it('flushes logs on flush event', () => { + const options = getDefaultClientOptions({ + dsn: PUBLIC_DSN, + _experiments: { enableLogs: true }, + }); + client = new ServerRuntimeClient(options); + + const sendEnvelopeSpy = vi.spyOn(client, 'sendEnvelope'); + + // Add some logs + _INTERNAL_captureLog({ message: 'test1', level: 'info' }, client); + _INTERNAL_captureLog({ message: 'test2', level: 'info' }, client); + + // Trigger flush event + client.emit('flush'); + + expect(sendEnvelopeSpy).toHaveBeenCalledTimes(1); + expect(client['_logWeight']).toBe(0); // Weight should be reset after flush + }); + + it('does not flush logs when logs are disabled', () => { + const options = getDefaultClientOptions({ + dsn: PUBLIC_DSN, + _experiments: { enableLogs: false }, + }); + client = new ServerRuntimeClient(options); + + const sendEnvelopeSpy = vi.spyOn(client, 'sendEnvelope'); + + // Create a large log message + const largeMessage = 'x'.repeat(400_000); + _INTERNAL_captureLog({ message: largeMessage, level: 'info' }, client); + + expect(sendEnvelopeSpy).not.toHaveBeenCalled(); + expect(client['_logWeight']).toBe(0); + }); + }); });