diff --git a/CHANGELOG.md b/CHANGELOG.md index c8b579c25cc5..d2805f3340d4 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,13 @@ - "You miss 100 percent of the chances you don't take. — Wayne Gretzky" — Michael Scott +## 6.18.1-beta.0 + +This patch builds on top of the https://github.com/getsentry/sentry-javascript/releases/tag/6.17.8-beta.0 beta. +It adds an additional finish reason that covers the case where a transaction was getting externally finished. + +- feat(tracing): Reset IdleTimeout based on activities count ([#4531](https://github.com/getsentry/sentry-javascript/pull/4531)) + ## 6.18.1 - fix(ember): use _backburner if it exists ([#4603](https://github.com/getsentry/sentry-javascript/pull/4603)) diff --git a/packages/integration-tests/suites/tracing/browsertracing/backgroundtab-custom/test.ts b/packages/integration-tests/suites/tracing/browsertracing/backgroundtab-custom/test.ts index a21cff2f1831..8a50d643e0c9 100644 --- a/packages/integration-tests/suites/tracing/browsertracing/backgroundtab-custom/test.ts +++ b/packages/integration-tests/suites/tracing/browsertracing/backgroundtab-custom/test.ts @@ -36,5 +36,5 @@ sentryTest('should finish a custom transaction when the page goes background', a expect(id_before).toBe(id_after); expect(name_after).toBe(name_before); expect(status_after).toBe('cancelled'); - expect(tags_after).toStrictEqual({ finishReason: 'documentHidden', visibilitychange: 'document.hidden' }); + expect(tags_after).toStrictEqual({ visibilitychange: 'document.hidden' }); }); diff --git a/packages/tracing/src/browser/backgroundtab.ts b/packages/tracing/src/browser/backgroundtab.ts index 3701404b5d26..2d9a147e8bfa 100644 --- a/packages/tracing/src/browser/backgroundtab.ts +++ b/packages/tracing/src/browser/backgroundtab.ts @@ -1,6 +1,6 @@ import { getGlobalObject, logger } from '@sentry/utils'; -import { FINISH_REASON_TAG, IDLE_TRANSACTION_FINISH_REASONS } from '../constants'; +import { IDLE_TRANSACTION_FINISH_REASONS } from '../constants'; import { IdleTransaction } from '../idletransaction'; import { SpanStatusType } from '../span'; import { getActiveTransaction } from '../utils'; @@ -27,7 +27,7 @@ export function registerBackgroundTabDetection(): void { activeTransaction.setStatus(statusType); } activeTransaction.setTag('visibilitychange', 'document.hidden'); - activeTransaction.setTag(FINISH_REASON_TAG, IDLE_TRANSACTION_FINISH_REASONS[2]); + activeTransaction.finishReason = IDLE_TRANSACTION_FINISH_REASONS[2]; /* 'documentHidden' */ activeTransaction.finish(); } }); diff --git a/packages/tracing/src/browser/browsertracing.ts b/packages/tracing/src/browser/browsertracing.ts index 4218f8e84fd7..d5f23f9395c0 100644 --- a/packages/tracing/src/browser/browsertracing.ts +++ b/packages/tracing/src/browser/browsertracing.ts @@ -3,7 +3,7 @@ import { EventProcessor, Integration, Transaction, TransactionContext } from '@s import { getGlobalObject, logger } from '@sentry/utils'; import { startIdleTransaction } from '../hubextensions'; -import { DEFAULT_IDLE_TIMEOUT, IdleTransaction } from '../idletransaction'; +import { DEFAULT_FINAL_TIMEOUT, DEFAULT_IDLE_TIMEOUT, IdleTransaction } from '../idletransaction'; import { extractTraceparentData, secToMs } from '../utils'; import { registerBackgroundTabDetection } from './backgroundtab'; import { MetricsInstrumentation } from './metrics'; @@ -21,12 +21,23 @@ export interface BrowserTracingOptions extends RequestInstrumentationOptions { /** * The time to wait in ms until the transaction will be finished. The transaction will use the end timestamp of * the last finished span as the endtime for the transaction. + * * Time is in ms. * * Default: 1000 */ idleTimeout: number; + /** + * The max duration for a transaction. If a transaction duration hits the `finalTimeout` value, it + * will be finished. + * + * Time is in ms. + * + * Default: 30000 + */ + finalTimeout: number; + /** * Flag to enable/disable creation of `navigation` transaction on history changes. * @@ -93,6 +104,7 @@ export interface BrowserTracingOptions extends RequestInstrumentationOptions { const DEFAULT_BROWSER_TRACING_OPTIONS = { idleTimeout: DEFAULT_IDLE_TIMEOUT, + finalTimeout: DEFAULT_FINAL_TIMEOUT, markBackgroundTransactions: true, maxTransactionDuration: DEFAULT_MAX_TRANSACTION_DURATION_SECONDS, routingInstrumentation: instrumentRoutingWithDefaults, diff --git a/packages/tracing/src/constants.ts b/packages/tracing/src/constants.ts index 3f01982c3614..801e1d315e3a 100644 --- a/packages/tracing/src/constants.ts +++ b/packages/tracing/src/constants.ts @@ -1,5 +1,11 @@ // Store finish reasons in tuple to save on bundle size // Readonly type should enforce that this is not mutated. -export const FINISH_REASON_TAG = 'finishReason'; +export const FINISH_REASON_TAG = 'finishReason' as const; -export const IDLE_TRANSACTION_FINISH_REASONS = ['heartbeatFailed', 'idleTimeout', 'documentHidden'] as const; +export const IDLE_TRANSACTION_FINISH_REASONS = [ + 'heartbeatFailed', + 'idleTimeout', + 'documentHidden', + 'finalTimeout', + 'externalFinish', +] as const; diff --git a/packages/tracing/src/idletransaction.ts b/packages/tracing/src/idletransaction.ts index 7e876bb18660..d60b7af70c6f 100644 --- a/packages/tracing/src/idletransaction.ts +++ b/packages/tracing/src/idletransaction.ts @@ -1,14 +1,18 @@ +/* eslint-disable max-lines */ import { Hub } from '@sentry/hub'; import { TransactionContext } from '@sentry/types'; -import { logger, timestampWithMs } from '@sentry/utils'; +import { getGlobalObject, logger, timestampWithMs } from '@sentry/utils'; import { FINISH_REASON_TAG, IDLE_TRANSACTION_FINISH_REASONS } from './constants'; import { Span, SpanRecorder } from './span'; import { Transaction } from './transaction'; export const DEFAULT_IDLE_TIMEOUT = 1000; +export const DEFAULT_FINAL_TIMEOUT = 30000; export const HEARTBEAT_INTERVAL = 5000; +const global = getGlobalObject(); + /** * @inheritDoc */ @@ -56,6 +60,14 @@ export class IdleTransaction extends Transaction { // Activities store a list of active spans public activities: Record = {}; + /** + * + * Defaults to `externalFinish`, which means transaction.finish() was called outside of the idle transaction (for example, + * by a navigation transaction ending the previous pageload/navigation in some routing instrumentation). + * @default 'externalFinish' + */ + public finishReason: typeof IDLE_TRANSACTION_FINISH_REASONS[number] = IDLE_TRANSACTION_FINISH_REASONS[4]; + // Track state of activities in previous heartbeat private _prevHeartbeatString: string | undefined; @@ -71,7 +83,7 @@ export class IdleTransaction extends Transaction { * If a transaction is created and no activities are added, we want to make sure that * it times out properly. This is cleared and not used when activities are added. */ - private _initTimeout: ReturnType | undefined; + private _idleTimeoutID: ReturnType | undefined; public constructor( transactionContext: TransactionContext, @@ -79,10 +91,21 @@ export class IdleTransaction extends Transaction { /** * The time to wait in ms until the idle transaction will be finished. * @default 1000 + * + * TODO: Make _idleTimeout and _finalTimeout required to reduce duplication when setting the options + * in `BrowserTracing`. This is considered a breaking change to the IdleTransaction API, + * so we need to make sure we communicate it with react native. */ private readonly _idleTimeout: number = DEFAULT_IDLE_TIMEOUT, // Whether or not the transaction should put itself on the scope when it starts and pop itself off when it ends private readonly _onScope: boolean = false, + /** + * The final value that a transaction cannot exceed + * @default 30000 + * @experimental + * @internal + */ + private readonly _finalTimeout: number = DEFAULT_FINAL_TIMEOUT, ) { super(transactionContext, _idleHub); @@ -96,11 +119,13 @@ export class IdleTransaction extends Transaction { _idleHub.configureScope(scope => scope.setSpan(this)); } - this._initTimeout = setTimeout(() => { + this._startIdleTimeout(); + global.setTimeout(() => { if (!this._finished) { + this.finishReason = IDLE_TRANSACTION_FINISH_REASONS[3]; /* 'finalTimeout' */ this.finish(); } - }, this._idleTimeout); + }, this._finalTimeout); } /** {@inheritDoc} */ @@ -108,6 +133,8 @@ export class IdleTransaction extends Transaction { this._finished = true; this.activities = {}; + this.setTag(FINISH_REASON_TAG, this.finishReason); + if (this.spanRecorder) { logger.log('[Tracing] finishing IdleTransaction', new Date(endTimestamp * 1000).toISOString(), this.op); @@ -189,15 +216,35 @@ export class IdleTransaction extends Transaction { this.spanRecorder.add(this); } + /** + * Cancels the existing idletimeout, if there is one + */ + private _cancelIdleTimeout(): void { + if (this._idleTimeoutID) { + global.clearTimeout(this._idleTimeoutID); + this._idleTimeoutID = undefined; + } + } + + /** + * Creates an idletimeout + */ + private _startIdleTimeout(endTimestamp?: Parameters[0]): void { + this._cancelIdleTimeout(); + this._idleTimeoutID = global.setTimeout(() => { + if (!this._finished && Object.keys(this.activities).length === 0) { + this.finishReason = IDLE_TRANSACTION_FINISH_REASONS[1]; /* 'idleTimeout' */ + this.finish(endTimestamp); + } + }, this._idleTimeout); + } + /** * Start tracking a specific activity. * @param spanId The span id that represents the activity */ private _pushActivity(spanId: string): void { - if (this._initTimeout) { - clearTimeout(this._initTimeout); - this._initTimeout = undefined; - } + this._cancelIdleTimeout(); logger.log(`[Tracing] pushActivity: ${spanId}`); this.activities[spanId] = true; logger.log('[Tracing] new activities count', Object.keys(this.activities).length); @@ -219,14 +266,8 @@ export class IdleTransaction extends Transaction { const timeout = this._idleTimeout; // We need to add the timeout here to have the real endtimestamp of the transaction // Remember timestampWithMs is in seconds, timeout is in ms - const end = timestampWithMs() + timeout / 1000; - - setTimeout(() => { - if (!this._finished) { - this.setTag(FINISH_REASON_TAG, IDLE_TRANSACTION_FINISH_REASONS[1]); - this.finish(end); - } - }, timeout); + const endTimestamp = timestampWithMs() + timeout / 1000; + this._startIdleTimeout(endTimestamp); } } @@ -253,7 +294,7 @@ export class IdleTransaction extends Transaction { if (this._heartbeatCounter >= 3) { logger.log(`[Tracing] Transaction finished because of no change for 3 heart beats`); this.setStatus('deadline_exceeded'); - this.setTag(FINISH_REASON_TAG, IDLE_TRANSACTION_FINISH_REASONS[0]); + this.finishReason = IDLE_TRANSACTION_FINISH_REASONS[0]; /* 'heartbeatFailed' */ this.finish(); } else { this._pingHeartbeat(); @@ -265,7 +306,7 @@ export class IdleTransaction extends Transaction { */ private _pingHeartbeat(): void { logger.log(`pinging Heartbeat -> current counter: ${this._heartbeatCounter}`); - setTimeout(() => { + global.setTimeout(() => { this._beat(); }, HEARTBEAT_INTERVAL); } diff --git a/packages/tracing/test/browser/browsertracing.test.ts b/packages/tracing/test/browser/browsertracing.test.ts index 5658dd34858c..18d32dd285af 100644 --- a/packages/tracing/test/browser/browsertracing.test.ts +++ b/packages/tracing/test/browser/browsertracing.test.ts @@ -14,7 +14,7 @@ import { MetricsInstrumentation } from '../../src/browser/metrics'; import { defaultRequestInstrumentationOptions } from '../../src/browser/request'; import { instrumentRoutingWithDefaults } from '../../src/browser/router'; import * as hubExtensions from '../../src/hubextensions'; -import { DEFAULT_IDLE_TIMEOUT, IdleTransaction } from '../../src/idletransaction'; +import { DEFAULT_FINAL_TIMEOUT, DEFAULT_IDLE_TIMEOUT, IdleTransaction } from '../../src/idletransaction'; import { getActiveTransaction, secToMs } from '../../src/utils'; let mockChangeHistory: ({ to, from }: { to: string; from?: string }) => void = () => undefined; @@ -83,6 +83,7 @@ describe('BrowserTracing', () => { expect(browserTracing.options).toEqual({ idleTimeout: DEFAULT_IDLE_TIMEOUT, + finalTimeout: DEFAULT_FINAL_TIMEOUT, markBackgroundTransactions: true, maxTransactionDuration: DEFAULT_MAX_TRANSACTION_DURATION_SECONDS, routingInstrumentation: instrumentRoutingWithDefaults, @@ -235,9 +236,8 @@ describe('BrowserTracing', () => { describe('idleTimeout', () => { it('is created by default', () => { createBrowserTracing(true, { routingInstrumentation: customInstrumentRouting }); - const mockFinish = jest.fn(); const transaction = getActiveTransaction(hub) as IdleTransaction; - transaction.finish = mockFinish; + const mockFinish = jest.spyOn(transaction, 'finish'); const span = transaction.startChild(); // activities = 1 span.finish(); // activities = 0 @@ -251,9 +251,8 @@ describe('BrowserTracing', () => { it('can be a custom value', () => { createBrowserTracing(true, { idleTimeout: 2000, routingInstrumentation: customInstrumentRouting }); - const mockFinish = jest.fn(); const transaction = getActiveTransaction(hub) as IdleTransaction; - transaction.finish = mockFinish; + const mockFinish = jest.spyOn(transaction, 'finish'); const span = transaction.startChild(); // activities = 1 span.finish(); // activities = 0 diff --git a/packages/tracing/test/idletransaction.test.ts b/packages/tracing/test/idletransaction.test.ts index b60fec726c54..b229ae349902 100644 --- a/packages/tracing/test/idletransaction.test.ts +++ b/packages/tracing/test/idletransaction.test.ts @@ -9,7 +9,16 @@ import { } from '../src/idletransaction'; import { Span } from '../src/span'; -export class SimpleTransport extends Transports.BaseTransport {} +type TransportSendRequest = Transports.BaseTransport['_sendRequest']; + +export class SimpleTransport extends Transports.BaseTransport { + protected _sendRequest( + _req: Parameters[0], + _payload: Parameters[1], + ): ReturnType { + throw new Error('Method not implemented.'); + } +} const dsn = 'https://123@sentry.io/42'; let hub: Hub; @@ -103,7 +112,7 @@ describe('IdleTransaction', () => { expect(transaction.activities).toMatchObject({ [span.spanId]: true, [childSpan.spanId]: true }); span.finish(); - jest.runOnlyPendingTimers(); + jest.advanceTimersByTime(DEFAULT_IDLE_TIMEOUT + 1); expect(mockFinish).toHaveBeenCalledTimes(0); expect(transaction.activities).toMatchObject({ [childSpan.spanId]: true }); @@ -229,20 +238,20 @@ describe('IdleTransaction', () => { transaction.startChild({}); // Beat 1 - jest.runOnlyPendingTimers(); + jest.advanceTimersByTime(HEARTBEAT_INTERVAL); expect(mockFinish).toHaveBeenCalledTimes(0); // Beat 2 - jest.runOnlyPendingTimers(); + jest.advanceTimersByTime(HEARTBEAT_INTERVAL); expect(mockFinish).toHaveBeenCalledTimes(0); // Beat 3 - jest.runOnlyPendingTimers(); + jest.advanceTimersByTime(HEARTBEAT_INTERVAL); expect(mockFinish).toHaveBeenCalledTimes(1); }); it('resets after new activities are added', () => { - const transaction = new IdleTransaction({ name: 'foo' }, hub, DEFAULT_IDLE_TIMEOUT); + const transaction = new IdleTransaction({ name: 'foo' }, hub, DEFAULT_IDLE_TIMEOUT, false, 50000); const mockFinish = jest.spyOn(transaction, 'finish'); transaction.initSpanRecorder(10); @@ -250,42 +259,42 @@ describe('IdleTransaction', () => { transaction.startChild({}); // Beat 1 - jest.runOnlyPendingTimers(); + jest.advanceTimersByTime(HEARTBEAT_INTERVAL); expect(mockFinish).toHaveBeenCalledTimes(0); const span = transaction.startChild(); // push activity // Beat 1 - jest.runOnlyPendingTimers(); + jest.advanceTimersByTime(HEARTBEAT_INTERVAL); expect(mockFinish).toHaveBeenCalledTimes(0); // Beat 2 - jest.runOnlyPendingTimers(); + jest.advanceTimersByTime(HEARTBEAT_INTERVAL); expect(mockFinish).toHaveBeenCalledTimes(0); transaction.startChild(); // push activity transaction.startChild(); // push activity // Beat 1 - jest.runOnlyPendingTimers(); + jest.advanceTimersByTime(HEARTBEAT_INTERVAL); expect(mockFinish).toHaveBeenCalledTimes(0); // Beat 2 - jest.runOnlyPendingTimers(); + jest.advanceTimersByTime(HEARTBEAT_INTERVAL); expect(mockFinish).toHaveBeenCalledTimes(0); span.finish(); // pop activity // Beat 1 - jest.runOnlyPendingTimers(); + jest.advanceTimersByTime(HEARTBEAT_INTERVAL); expect(mockFinish).toHaveBeenCalledTimes(0); // Beat 2 - jest.runOnlyPendingTimers(); + jest.advanceTimersByTime(HEARTBEAT_INTERVAL); expect(mockFinish).toHaveBeenCalledTimes(0); // Beat 3 - jest.runOnlyPendingTimers(); + jest.advanceTimersByTime(HEARTBEAT_INTERVAL); expect(mockFinish).toHaveBeenCalledTimes(1); // Heartbeat does not keep going after finish has been called