From fdde150d0b840acf02ec35d185fee849275c8669 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Thu, 5 May 2022 15:15:46 -0400 Subject: [PATCH 1/2] ref(tracing): Reset IdleTimeout based on activities count --- MIGRATION.md | 1 + .../backgroundtab-custom/test.ts | 2 +- .../backgroundtab-pageload/test.ts | 1 - packages/tracing/src/browser/backgroundtab.ts | 2 - .../tracing/src/browser/browsertracing.ts | 55 ++++------- packages/tracing/src/constants.ts | 5 - packages/tracing/src/hubextensions.ts | 6 +- packages/tracing/src/idletransaction.ts | 71 ++++++++----- .../test/browser/browsertracing.test.ts | 48 +-------- packages/tracing/test/idletransaction.test.ts | 99 +++++++++++++------ 10 files changed, 146 insertions(+), 144 deletions(-) delete mode 100644 packages/tracing/src/constants.ts diff --git a/MIGRATION.md b/MIGRATION.md index cac9ad2feb96..cda6cb2836db 100644 --- a/MIGRATION.md +++ b/MIGRATION.md @@ -291,6 +291,7 @@ For our efforts to reduce bundle size of the SDK we had to remove and refactor p - Rename `UserAgent` integration to `HttpContext`. (see [#5027](https://github.com/getsentry/sentry-javascript/pull/5027)) - Remove `SDK_NAME` export from `@sentry/browser`, `@sentry/node`, `@sentry/tracing` and `@sentry/vue` packages. - Removed `eventStatusFromHttpCode` to save on bundle size. +- Replace `BrowserTracing` `maxTransactionDuration` option with `finalTimeout` option ## Sentry Angular SDK Changes 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/integration-tests/suites/tracing/browsertracing/backgroundtab-pageload/test.ts b/packages/integration-tests/suites/tracing/browsertracing/backgroundtab-pageload/test.ts index 47f695b0440c..149eb3e87a33 100644 --- a/packages/integration-tests/suites/tracing/browsertracing/backgroundtab-pageload/test.ts +++ b/packages/integration-tests/suites/tracing/browsertracing/backgroundtab-pageload/test.ts @@ -17,6 +17,5 @@ sentryTest('should finish pageload transaction when the page goes background', a expect(pageloadTransaction.contexts?.trace.status).toBe('cancelled'); expect(pageloadTransaction.contexts?.trace.tags).toMatchObject({ visibilitychange: 'document.hidden', - finishReason: 'documentHidden', }); }); diff --git a/packages/tracing/src/browser/backgroundtab.ts b/packages/tracing/src/browser/backgroundtab.ts index 2448247188bd..64bb06d2d70f 100644 --- a/packages/tracing/src/browser/backgroundtab.ts +++ b/packages/tracing/src/browser/backgroundtab.ts @@ -1,6 +1,5 @@ import { getGlobalObject, logger } from '@sentry/utils'; -import { FINISH_REASON_TAG, IDLE_TRANSACTION_FINISH_REASONS } from '../constants'; import { IS_DEBUG_BUILD } from '../flags'; import { IdleTransaction } from '../idletransaction'; import { SpanStatusType } from '../span'; @@ -29,7 +28,6 @@ export function registerBackgroundTabDetection(): void { activeTransaction.setStatus(statusType); } activeTransaction.setTag('visibilitychange', 'document.hidden'); - activeTransaction.setTag(FINISH_REASON_TAG, IDLE_TRANSACTION_FINISH_REASONS[2]); activeTransaction.finish(); } }); diff --git a/packages/tracing/src/browser/browsertracing.ts b/packages/tracing/src/browser/browsertracing.ts index e9d02db6d7d7..780edf9052d4 100644 --- a/packages/tracing/src/browser/browsertracing.ts +++ b/packages/tracing/src/browser/browsertracing.ts @@ -4,8 +4,8 @@ import { getGlobalObject, logger } from '@sentry/utils'; import { IS_DEBUG_BUILD } from '../flags'; import { startIdleTransaction } from '../hubextensions'; -import { DEFAULT_IDLE_TIMEOUT, IdleTransaction } from '../idletransaction'; -import { extractTraceparentData, secToMs } from '../utils'; +import { DEFAULT_FINAL_TIMEOUT, DEFAULT_IDLE_TIMEOUT } from '../idletransaction'; +import { extractTraceparentData } from '../utils'; import { registerBackgroundTabDetection } from './backgroundtab'; import { MetricsInstrumentation } from './metrics'; import { @@ -15,19 +15,29 @@ import { } from './request'; import { instrumentRoutingWithDefaults } from './router'; -export const DEFAULT_MAX_TRANSACTION_DURATION_SECONDS = 600; - /** Options for Browser Tracing integration */ 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. + * The time to wait in ms until the transaction will be finished during an idle state. An idle state is defined + * by a moment where there are no in-progress spans. + * + * The transaction will use the end timestamp of the last finished span as the endtime for the transaction. + * If there are still active spans when this the `idleTimeout` is set, the `idleTimeout` will get reset. * 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. * @@ -42,15 +52,6 @@ export interface BrowserTracingOptions extends RequestInstrumentationOptions { */ startTransactionOnPageLoad: boolean; - /** - * The maximum duration of a transaction before it will be marked as "deadline_exceeded". - * If you never want to mark a transaction set it to 0. - * Time is in seconds. - * - * Default: 600 - */ - maxTransactionDuration: number; - /** * Flag Transactions where tabs moved to background with "cancelled". Browser background tab timing is * not suited towards doing precise measurements of operations. By default, we recommend that this option @@ -94,8 +95,8 @@ 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, startTransactionOnLocationChange: true, startTransactionOnPageLoad: true, @@ -129,14 +130,10 @@ export class BrowserTracing implements Integration { private readonly _emitOptionsWarning?: boolean; - /** Store configured idle timeout so that it can be added as a tag to transactions */ - private _configuredIdleTimeout: BrowserTracingOptions['idleTimeout'] | undefined = undefined; - public constructor(_options?: Partial) { let tracingOrigins = defaultRequestInstrumentationOptions.tracingOrigins; // NOTE: Logger doesn't work in constructors, as it's initialized after integrations instances if (_options) { - this._configuredIdleTimeout = _options.idleTimeout; if (_options.tracingOrigins && Array.isArray(_options.tracingOrigins) && _options.tracingOrigins.length !== 0) { tracingOrigins = _options.tracingOrigins; } else { @@ -205,7 +202,7 @@ export class BrowserTracing implements Integration { } // eslint-disable-next-line @typescript-eslint/unbound-method - const { beforeNavigate, idleTimeout, maxTransactionDuration } = this.options; + const { beforeNavigate, idleTimeout, finalTimeout } = this.options; const parentContextFromHeader = context.op === 'pageload' ? getHeaderContext() : undefined; @@ -233,16 +230,14 @@ export class BrowserTracing implements Integration { hub, finalContext, idleTimeout, + finalTimeout, true, { location }, // for use in the tracesSampler ); - idleTransaction.registerBeforeFinishCallback((transaction, endTimestamp) => { + idleTransaction.registerBeforeFinishCallback(transaction => { this._metrics.addPerformanceEntries(transaction); - adjustTransactionDuration(secToMs(maxTransactionDuration), transaction, endTimestamp); }); - idleTransaction.setTag('idleTimeout', this._configuredIdleTimeout); - return idleTransaction as Transaction; } } @@ -266,13 +261,3 @@ export function getMetaContent(metaName: string): string | null { const el = getGlobalObject().document.querySelector(`meta[name=${metaName}]`); return el ? el.getAttribute('content') : null; } - -/** Adjusts transaction value based on max transaction duration */ -function adjustTransactionDuration(maxDuration: number, transaction: IdleTransaction, endTimestamp: number): void { - const diff = endTimestamp - transaction.startTimestamp; - const isOutdatedTransaction = endTimestamp && (diff > maxDuration || diff < 0); - if (isOutdatedTransaction) { - transaction.setStatus('deadline_exceeded'); - transaction.setTag('maxTransactionDurationExceeded', 'true'); - } -} diff --git a/packages/tracing/src/constants.ts b/packages/tracing/src/constants.ts deleted file mode 100644 index 3f01982c3614..000000000000 --- a/packages/tracing/src/constants.ts +++ /dev/null @@ -1,5 +0,0 @@ -// 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 IDLE_TRANSACTION_FINISH_REASONS = ['heartbeatFailed', 'idleTimeout', 'documentHidden'] as const; diff --git a/packages/tracing/src/hubextensions.ts b/packages/tracing/src/hubextensions.ts index 80bd7a5783c8..dbcb4fb66029 100644 --- a/packages/tracing/src/hubextensions.ts +++ b/packages/tracing/src/hubextensions.ts @@ -1,3 +1,4 @@ +/* eslint-disable max-lines */ import { getMainCarrier, Hub } from '@sentry/hub'; import { ClientOptions, @@ -196,14 +197,15 @@ function _startTransaction( export function startIdleTransaction( hub: Hub, transactionContext: TransactionContext, - idleTimeout?: number, + idleTimeout: number, + finalTimeout: number, onScope?: boolean, customSamplingContext?: CustomSamplingContext, ): IdleTransaction { const client = hub.getClient(); const options: Partial = (client && client.getOptions()) || {}; - let transaction = new IdleTransaction(transactionContext, hub, idleTimeout, onScope); + let transaction = new IdleTransaction(transactionContext, hub, idleTimeout, finalTimeout, onScope); transaction = sample(transaction, options, { parentSampled: transactionContext.parentSampled, transactionContext, diff --git a/packages/tracing/src/idletransaction.ts b/packages/tracing/src/idletransaction.ts index 0d292eebba65..103576bd5b4c 100644 --- a/packages/tracing/src/idletransaction.ts +++ b/packages/tracing/src/idletransaction.ts @@ -1,15 +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 { IS_DEBUG_BUILD } from './flags'; 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 */ @@ -17,7 +20,7 @@ export class IdleTransactionSpanRecorder extends SpanRecorder { public constructor( private readonly _pushActivity: (id: string) => void, private readonly _popActivity: (id: string) => void, - public transactionSpanId: string = '', + public transactionSpanId: string, maxlen?: number, ) { super(maxlen); @@ -69,25 +72,27 @@ export class IdleTransaction extends Transaction { private readonly _beforeFinishCallbacks: BeforeFinishCallback[] = []; /** - * 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. + * Timer that tracks a */ - private _initTimeout: ReturnType | undefined; + private _idleTimeoutID: ReturnType | undefined; public constructor( transactionContext: TransactionContext, - private readonly _idleHub?: Hub, + private readonly _idleHub: Hub, /** * The time to wait in ms until the idle transaction will be finished. - * @default 1000 */ private readonly _idleTimeout: number = DEFAULT_IDLE_TIMEOUT, + /** + * The final value in ms that a transaction cannot exceed + */ + private readonly _finalTimeout: number = DEFAULT_FINAL_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, ) { super(transactionContext, _idleHub); - if (_idleHub && _onScope) { + if (_onScope) { // There should only be one active transaction on the scope clearActiveTransaction(_idleHub); @@ -97,16 +102,19 @@ export class IdleTransaction extends Transaction { _idleHub.configureScope(scope => scope.setSpan(this)); } - this._initTimeout = setTimeout(() => { + this._startIdleTimeout(); + global.setTimeout(() => { if (!this._finished) { + this.setStatus('deadline_exceeded'); this.finish(); } - }, this._idleTimeout); + }, this._finalTimeout); } /** {@inheritDoc} */ public finish(endTimestamp: number = timestampWithMs()): string | undefined { this._finished = true; + this._cancelIdleTimeout(); this.activities = {}; if (this.spanRecorder) { @@ -193,15 +201,34 @@ 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.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(); IS_DEBUG_BUILD && logger.log(`[Tracing] pushActivity: ${spanId}`); this.activities[spanId] = true; IS_DEBUG_BUILD && logger.log('[Tracing] new activities count', Object.keys(this.activities).length); @@ -220,17 +247,10 @@ export class IdleTransaction extends Transaction { } if (Object.keys(this.activities).length === 0) { - 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() + this._idleTimeout / 1000; + this._startIdleTimeout(endTimestamp); } } @@ -257,7 +277,6 @@ export class IdleTransaction extends Transaction { if (this._heartbeatCounter >= 3) { IS_DEBUG_BUILD && 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.finish(); } else { this._pingHeartbeat(); @@ -269,7 +288,7 @@ export class IdleTransaction extends Transaction { */ private _pingHeartbeat(): void { IS_DEBUG_BUILD && 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 5cb144cfd207..4bfc093fbe2b 100644 --- a/packages/tracing/test/browser/browsertracing.test.ts +++ b/packages/tracing/test/browser/browsertracing.test.ts @@ -6,7 +6,6 @@ import { JSDOM } from 'jsdom'; import { BrowserTracing, BrowserTracingOptions, - DEFAULT_MAX_TRANSACTION_DURATION_SECONDS, getHeaderContext, getMetaContent, } from '../../src/browser/browsertracing'; @@ -14,8 +13,8 @@ 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 { getActiveTransaction, secToMs } from '../../src/utils'; +import { DEFAULT_FINAL_TIMEOUT, DEFAULT_IDLE_TIMEOUT, IdleTransaction } from '../../src/idletransaction'; +import { getActiveTransaction } from '../../src/utils'; import { getDefaultBrowserClientOptions } from '../testutils'; let mockChangeHistory: ({ to, from }: { to: string; from?: string }) => void = () => undefined; @@ -85,8 +84,8 @@ describe('BrowserTracing', () => { expect(browserTracing.options).toEqual({ idleTimeout: DEFAULT_IDLE_TIMEOUT, + finalTimeout: DEFAULT_FINAL_TIMEOUT, markBackgroundTransactions: true, - maxTransactionDuration: DEFAULT_MAX_TRANSACTION_DURATION_SECONDS, routingInstrumentation: instrumentRoutingWithDefaults, startTransactionOnLocationChange: true, startTransactionOnPageLoad: true, @@ -229,6 +228,7 @@ describe('BrowserTracing', () => { parentSampled: true, }), expect.any(Number), + expect.any(Number), expect.any(Boolean), expect.any(Object), ); @@ -247,8 +247,6 @@ describe('BrowserTracing', () => { expect(mockFinish).toHaveBeenCalledTimes(0); jest.advanceTimersByTime(DEFAULT_IDLE_TIMEOUT); expect(mockFinish).toHaveBeenCalledTimes(1); - - expect(transaction.tags).toEqual({ finishReason: 'idleTimeout', idleTimeout: undefined }); }); it('can be a custom value', () => { @@ -263,44 +261,6 @@ describe('BrowserTracing', () => { expect(mockFinish).toHaveBeenCalledTimes(0); jest.advanceTimersByTime(2000); expect(mockFinish).toHaveBeenCalledTimes(1); - - expect(transaction.tags).toEqual({ finishReason: 'idleTimeout', idleTimeout: 2000 }); - }); - }); - - describe('maxTransactionDuration', () => { - it('cancels a transaction if exceeded', () => { - createBrowserTracing(true, { routingInstrumentation: customInstrumentRouting }); - const transaction = getActiveTransaction(hub) as IdleTransaction; - transaction.finish(transaction.startTimestamp + secToMs(DEFAULT_MAX_TRANSACTION_DURATION_SECONDS) + 1); - - expect(transaction.status).toBe('deadline_exceeded'); - expect(transaction.tags.maxTransactionDurationExceeded).toBeDefined(); - }); - - it('does not cancel a transaction if not exceeded', () => { - createBrowserTracing(true, { routingInstrumentation: customInstrumentRouting }); - const transaction = getActiveTransaction(hub) as IdleTransaction; - transaction.finish(transaction.startTimestamp + secToMs(DEFAULT_MAX_TRANSACTION_DURATION_SECONDS)); - - expect(transaction.status).toBe(undefined); - expect(transaction.tags.maxTransactionDurationExceeded).not.toBeDefined(); - }); - - it('can have a custom value', () => { - const customMaxTransactionDuration = 700; - // Test to make sure default duration is less than tested custom value. - expect(DEFAULT_MAX_TRANSACTION_DURATION_SECONDS < customMaxTransactionDuration).toBe(true); - createBrowserTracing(true, { - maxTransactionDuration: customMaxTransactionDuration, - routingInstrumentation: customInstrumentRouting, - }); - const transaction = getActiveTransaction(hub) as IdleTransaction; - - transaction.finish(transaction.startTimestamp + secToMs(customMaxTransactionDuration)); - - expect(transaction.status).toBe(undefined); - expect(transaction.tags.maxTransactionDurationExceeded).not.toBeDefined(); }); }); }); diff --git a/packages/tracing/test/idletransaction.test.ts b/packages/tracing/test/idletransaction.test.ts index bf4d5d51af41..956de96b5ea5 100644 --- a/packages/tracing/test/idletransaction.test.ts +++ b/packages/tracing/test/idletransaction.test.ts @@ -2,6 +2,7 @@ import { BrowserClient } from '@sentry/browser'; import { Hub } from '@sentry/hub'; import { + DEFAULT_FINAL_TIMEOUT, DEFAULT_IDLE_TIMEOUT, HEARTBEAT_INTERVAL, IdleTransaction, @@ -20,7 +21,7 @@ beforeEach(() => { describe('IdleTransaction', () => { describe('onScope', () => { it('sets the transaction on the scope on creation if onScope is true', () => { - const transaction = new IdleTransaction({ name: 'foo' }, hub, DEFAULT_IDLE_TIMEOUT, true); + const transaction = new IdleTransaction({ name: 'foo' }, hub, DEFAULT_IDLE_TIMEOUT, DEFAULT_FINAL_TIMEOUT, true); transaction.initSpanRecorder(10); hub.configureScope(s => { @@ -29,7 +30,7 @@ describe('IdleTransaction', () => { }); it('does not set the transaction on the scope on creation if onScope is falsey', () => { - const transaction = new IdleTransaction({ name: 'foo' }, hub, DEFAULT_IDLE_TIMEOUT); + const transaction = new IdleTransaction({ name: 'foo' }, hub); transaction.initSpanRecorder(10); hub.configureScope(s => { @@ -38,7 +39,7 @@ describe('IdleTransaction', () => { }); it('removes sampled transaction from scope on finish if onScope is true', () => { - const transaction = new IdleTransaction({ name: 'foo' }, hub, DEFAULT_IDLE_TIMEOUT, true); + const transaction = new IdleTransaction({ name: 'foo' }, hub, DEFAULT_IDLE_TIMEOUT, DEFAULT_FINAL_TIMEOUT, true); transaction.initSpanRecorder(10); transaction.finish(); @@ -50,7 +51,13 @@ describe('IdleTransaction', () => { }); it('removes unsampled transaction from scope on finish if onScope is true', () => { - const transaction = new IdleTransaction({ name: 'foo', sampled: false }, hub, DEFAULT_IDLE_TIMEOUT, true); + const transaction = new IdleTransaction( + { name: 'foo', sampled: false }, + hub, + DEFAULT_IDLE_TIMEOUT, + DEFAULT_FINAL_TIMEOUT, + true, + ); transaction.finish(); jest.runAllTimers(); @@ -66,7 +73,7 @@ describe('IdleTransaction', () => { }); it('push and pops activities', () => { - const transaction = new IdleTransaction({ name: 'foo' }, hub, DEFAULT_IDLE_TIMEOUT); + const transaction = new IdleTransaction({ name: 'foo' }, hub); const mockFinish = jest.spyOn(transaction, 'finish'); transaction.initSpanRecorder(10); expect(transaction.activities).toMatchObject({}); @@ -84,7 +91,7 @@ describe('IdleTransaction', () => { }); it('does not push activities if a span already has an end timestamp', () => { - const transaction = new IdleTransaction({ name: 'foo' }, hub, DEFAULT_IDLE_TIMEOUT); + const transaction = new IdleTransaction({ name: 'foo' }, hub); transaction.initSpanRecorder(10); expect(transaction.activities).toMatchObject({}); @@ -93,7 +100,7 @@ describe('IdleTransaction', () => { }); it('does not finish if there are still active activities', () => { - const transaction = new IdleTransaction({ name: 'foo' }, hub, DEFAULT_IDLE_TIMEOUT); + const transaction = new IdleTransaction({ name: 'foo' }, hub); const mockFinish = jest.spyOn(transaction, 'finish'); transaction.initSpanRecorder(10); expect(transaction.activities).toMatchObject({}); @@ -103,7 +110,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 }); @@ -112,7 +119,7 @@ describe('IdleTransaction', () => { it('calls beforeFinish callback before finishing', () => { const mockCallback1 = jest.fn(); const mockCallback2 = jest.fn(); - const transaction = new IdleTransaction({ name: 'foo' }, hub, DEFAULT_IDLE_TIMEOUT); + const transaction = new IdleTransaction({ name: 'foo' }, hub); transaction.initSpanRecorder(10); transaction.registerBeforeFinishCallback(mockCallback1); transaction.registerBeforeFinishCallback(mockCallback2); @@ -131,7 +138,7 @@ describe('IdleTransaction', () => { }); it('filters spans on finish', () => { - const transaction = new IdleTransaction({ name: 'foo', startTimestamp: 1234 }, hub, DEFAULT_IDLE_TIMEOUT); + const transaction = new IdleTransaction({ name: 'foo', startTimestamp: 1234 }, hub); transaction.initSpanRecorder(10); // regular child - should be kept @@ -176,9 +183,9 @@ describe('IdleTransaction', () => { expect(recordDroppedEventSpy).toHaveBeenCalledWith('sample_rate', 'transaction'); }); - describe('_initTimeout', () => { + describe('_idleTimeout', () => { it('finishes if no activities are added to the transaction', () => { - const transaction = new IdleTransaction({ name: 'foo', startTimestamp: 1234 }, hub, DEFAULT_IDLE_TIMEOUT); + const transaction = new IdleTransaction({ name: 'foo', startTimestamp: 1234 }, hub); transaction.initSpanRecorder(10); jest.advanceTimersByTime(DEFAULT_IDLE_TIMEOUT); @@ -186,13 +193,49 @@ describe('IdleTransaction', () => { }); it('does not finish if a activity is started', () => { - const transaction = new IdleTransaction({ name: 'foo', startTimestamp: 1234 }, hub, DEFAULT_IDLE_TIMEOUT); + const transaction = new IdleTransaction({ name: 'foo', startTimestamp: 1234 }, hub); transaction.initSpanRecorder(10); transaction.startChild({}); jest.advanceTimersByTime(DEFAULT_IDLE_TIMEOUT); expect(transaction.endTimestamp).toBeUndefined(); }); + + it('does not finish when idleTimeout is not exceed after last activity finished', () => { + const idleTimeout = 10; + const transaction = new IdleTransaction({ name: 'foo', startTimestamp: 1234 }, hub, idleTimeout); + transaction.initSpanRecorder(10); + + const span = transaction.startChild({}); + span.finish(); + + jest.advanceTimersByTime(2); + + const span2 = transaction.startChild({}); + span2.finish(); + + jest.advanceTimersByTime(8); + + expect(transaction.endTimestamp).toBeUndefined(); + }); + + it('finish when idleTimeout is exceeded after last activity finished', () => { + const idleTimeout = 10; + const transaction = new IdleTransaction({ name: 'foo', startTimestamp: 1234 }, hub, idleTimeout); + transaction.initSpanRecorder(10); + + const span = transaction.startChild({}); + span.finish(); + + jest.advanceTimersByTime(2); + + const span2 = transaction.startChild({}); + span2.finish(); + + jest.advanceTimersByTime(10); + + expect(transaction.endTimestamp).toBeDefined(); + }); }); describe('heartbeat', () => { @@ -229,20 +272,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, 50000); const mockFinish = jest.spyOn(transaction, 'finish'); transaction.initSpanRecorder(10); @@ -250,42 +293,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 @@ -299,7 +342,7 @@ describe('IdleTransactionSpanRecorder', () => { it('pushes and pops activities', () => { const mockPushActivity = jest.fn(); const mockPopActivity = jest.fn(); - const spanRecorder = new IdleTransactionSpanRecorder(mockPushActivity, mockPopActivity, undefined, 10); + const spanRecorder = new IdleTransactionSpanRecorder(mockPushActivity, mockPopActivity, '', 10); expect(mockPushActivity).toHaveBeenCalledTimes(0); expect(mockPopActivity).toHaveBeenCalledTimes(0); @@ -322,7 +365,7 @@ describe('IdleTransactionSpanRecorder', () => { it('does not push activities if a span has a timestamp', () => { const mockPushActivity = jest.fn(); const mockPopActivity = jest.fn(); - const spanRecorder = new IdleTransactionSpanRecorder(mockPushActivity, mockPopActivity, undefined, 10); + const spanRecorder = new IdleTransactionSpanRecorder(mockPushActivity, mockPopActivity, '', 10); const span = new Span({ sampled: true, startTimestamp: 765, endTimestamp: 345 }); spanRecorder.add(span); @@ -334,7 +377,7 @@ describe('IdleTransactionSpanRecorder', () => { const mockPushActivity = jest.fn(); const mockPopActivity = jest.fn(); - const transaction = new IdleTransaction({ name: 'foo' }, hub, DEFAULT_IDLE_TIMEOUT); + const transaction = new IdleTransaction({ name: 'foo' }, hub); const spanRecorder = new IdleTransactionSpanRecorder(mockPushActivity, mockPopActivity, transaction.spanId, 10); spanRecorder.add(transaction); From fb3ea9605c5f83d9f11804c36d846841bf290719 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Fri, 6 May 2022 14:26:34 -0400 Subject: [PATCH 2/2] PR review changes --- packages/tracing/src/idletransaction.ts | 34 +++++++++++-------------- 1 file changed, 15 insertions(+), 19 deletions(-) diff --git a/packages/tracing/src/idletransaction.ts b/packages/tracing/src/idletransaction.ts index 103576bd5b4c..9353f552fcc9 100644 --- a/packages/tracing/src/idletransaction.ts +++ b/packages/tracing/src/idletransaction.ts @@ -1,7 +1,7 @@ /* eslint-disable max-lines */ import { Hub } from '@sentry/hub'; import { TransactionContext } from '@sentry/types'; -import { getGlobalObject, logger, timestampWithMs } from '@sentry/utils'; +import { logger, timestampWithMs } from '@sentry/utils'; import { IS_DEBUG_BUILD } from './flags'; import { Span, SpanRecorder } from './span'; @@ -11,8 +11,6 @@ export const DEFAULT_IDLE_TIMEOUT = 1000; export const DEFAULT_FINAL_TIMEOUT = 30000; export const HEARTBEAT_INTERVAL = 5000; -const global = getGlobalObject(); - /** * @inheritDoc */ @@ -72,15 +70,16 @@ export class IdleTransaction extends Transaction { private readonly _beforeFinishCallbacks: BeforeFinishCallback[] = []; /** - * Timer that tracks a + * Timer that tracks Transaction idleTimeout */ - private _idleTimeoutID: ReturnType | undefined; + private _idleTimeoutID: ReturnType | undefined; public constructor( transactionContext: TransactionContext, private readonly _idleHub: Hub, /** - * The time to wait in ms until the idle transaction will be finished. + * The time to wait in ms until the idle transaction will be finished. This timer is started each time + * there are no active spans on this transaction. */ private readonly _idleTimeout: number = DEFAULT_IDLE_TIMEOUT, /** @@ -103,7 +102,7 @@ export class IdleTransaction extends Transaction { } this._startIdleTimeout(); - global.setTimeout(() => { + setTimeout(() => { if (!this._finished) { this.setStatus('deadline_exceeded'); this.finish(); @@ -114,7 +113,6 @@ export class IdleTransaction extends Transaction { /** {@inheritDoc} */ public finish(endTimestamp: number = timestampWithMs()): string | undefined { this._finished = true; - this._cancelIdleTimeout(); this.activities = {}; if (this.spanRecorder) { @@ -206,7 +204,7 @@ export class IdleTransaction extends Transaction { */ private _cancelIdleTimeout(): void { if (this._idleTimeoutID) { - global.clearTimeout(this._idleTimeoutID); + clearTimeout(this._idleTimeoutID); this._idleTimeoutID = undefined; } } @@ -216,7 +214,7 @@ export class IdleTransaction extends Transaction { */ private _startIdleTimeout(endTimestamp?: Parameters[0]): void { this._cancelIdleTimeout(); - this._idleTimeoutID = global.setTimeout(() => { + this._idleTimeoutID = setTimeout(() => { if (!this._finished && Object.keys(this.activities).length === 0) { this.finish(endTimestamp); } @@ -288,7 +286,7 @@ export class IdleTransaction extends Transaction { */ private _pingHeartbeat(): void { IS_DEBUG_BUILD && logger.log(`pinging Heartbeat -> current counter: ${this._heartbeatCounter}`); - global.setTimeout(() => { + setTimeout(() => { this._beat(); }, HEARTBEAT_INTERVAL); } @@ -297,14 +295,12 @@ export class IdleTransaction extends Transaction { /** * Reset transaction on scope to `undefined` */ -function clearActiveTransaction(hub?: Hub): void { - if (hub) { - const scope = hub.getScope(); - if (scope) { - const transaction = scope.getTransaction(); - if (transaction) { - scope.setSpan(undefined); - } +function clearActiveTransaction(hub: Hub): void { + const scope = hub.getScope(); + if (scope) { + const transaction = scope.getTransaction(); + if (transaction) { + scope.setSpan(undefined); } } }