From 0960f661bbf9ed3c7a5ba951b4c70cd0806478c0 Mon Sep 17 00:00:00 2001 From: Francesco Novy Date: Tue, 5 Mar 2024 11:16:17 +0000 Subject: [PATCH 1/2] ref: Emit `spanStart` and `spanEnd` hooks --- packages/core/src/baseclient.ts | 13 +++++ packages/core/src/tracing/hubextensions.ts | 2 + packages/core/src/tracing/sentrySpan.ts | 22 +++++++- packages/core/test/lib/tracing/trace.test.ts | 51 +++++++++++++++++++ .../opentelemetry/src/custom/transaction.ts | 1 + packages/opentelemetry/src/spanProcessor.ts | 3 ++ packages/types/src/client.ts | 19 +++++++ 7 files changed, 110 insertions(+), 1 deletion(-) diff --git a/packages/core/src/baseclient.ts b/packages/core/src/baseclient.ts index 8d36844a96bf..d2493fa5998f 100644 --- a/packages/core/src/baseclient.ts +++ b/packages/core/src/baseclient.ts @@ -22,6 +22,7 @@ import type { Session, SessionAggregates, SeverityLevel, + Span, StartSpanOptions, Transaction, TransactionEvent, @@ -422,6 +423,12 @@ export abstract class BaseClient implements Client { /** @inheritdoc */ public on(hook: 'finishTransaction', callback: (transaction: Transaction) => void): void; + /** @inheritdoc */ + public on(hook: 'spanStart', callback: (span: Span) => void): void; + + /** @inheritdoc */ + public on(hook: 'spanEnd', callback: (span: Span) => void): void; + /** @inheritdoc */ public on(hook: 'beforeEnvelope', callback: (envelope: Envelope) => void): void; @@ -472,6 +479,12 @@ export abstract class BaseClient implements Client { /** @inheritdoc */ public emit(hook: 'finishTransaction', transaction: Transaction): void; + /** @inheritdoc */ + public emit(hook: 'spanStart', span: Span): void; + + /** @inheritdoc */ + public emit(hook: 'spanEnd', span: Span): void; + /** @inheritdoc */ public emit(hook: 'beforeEnvelope', envelope: Envelope): void; diff --git a/packages/core/src/tracing/hubextensions.ts b/packages/core/src/tracing/hubextensions.ts index 5f30a94498b9..7c9e3843f3bc 100644 --- a/packages/core/src/tracing/hubextensions.ts +++ b/packages/core/src/tracing/hubextensions.ts @@ -48,6 +48,7 @@ function _startTransaction( } if (client) { client.emit('startTransaction', transaction); + client.emit('spanStart', transaction); } return transaction; } @@ -95,6 +96,7 @@ export function startIdleTransaction( } if (client) { client.emit('startTransaction', transaction); + client.emit('spanStart', transaction); } return transaction; } diff --git a/packages/core/src/tracing/sentrySpan.ts b/packages/core/src/tracing/sentrySpan.ts index 5a31f511cc3e..36a7acc403b0 100644 --- a/packages/core/src/tracing/sentrySpan.ts +++ b/packages/core/src/tracing/sentrySpan.ts @@ -13,6 +13,7 @@ import type { Transaction, } from '@sentry/types'; import { dropUndefinedKeys, logger, timestampInSeconds, uuid4 } from '@sentry/utils'; +import { getClient } from '../currentScopes'; import { DEBUG_BUILD } from '../debug-build'; import { getMetricSummaryJsonForSpan } from '../metrics/metric-summary'; @@ -277,7 +278,7 @@ export class SentrySpan implements Span { * @deprecated Use `startSpan()`, `startSpanManual()` or `startInactiveSpan()` instead. */ public startChild( - spanContext?: Pick>, + spanContext: Pick> = {}, ): Span { const childSpan = new SentrySpan({ ...spanContext, @@ -315,6 +316,15 @@ export class SentrySpan implements Span { this._logMessage = logMessage; } + const client = getClient(); + if (client) { + client.emit('spanStart', childSpan); + // If it has an endTimestamp, it's already ended + if (spanContext.endTimestamp) { + client.emit('spanEnd', childSpan); + } + } + return childSpan; } @@ -397,6 +407,8 @@ export class SentrySpan implements Span { } this._endTime = spanTimeInputToSeconds(endTimestamp); + + this._onSpanEnded(); } /** @@ -499,4 +511,12 @@ export class SentrySpan implements Span { return hasData ? data : attributes; } + + /** Emit `spanEnd` when the span is ended. */ + private _onSpanEnded(): void { + const client = getClient(); + if (client) { + client.emit('spanEnd', this); + } + } } diff --git a/packages/core/test/lib/tracing/trace.test.ts b/packages/core/test/lib/tracing/trace.test.ts index 43585db1225a..d92032599211 100644 --- a/packages/core/test/lib/tracing/trace.test.ts +++ b/packages/core/test/lib/tracing/trace.test.ts @@ -1168,3 +1168,54 @@ describe('continueTrace', () => { expect(ctx).toEqual(expectedContext); }); }); + +describe('span hooks', () => { + beforeEach(() => { + addTracingExtensions(); + + getCurrentScope().clear(); + getIsolationScope().clear(); + getGlobalScope().clear(); + + const options = getDefaultTestClientOptions({ tracesSampleRate: 0.0 }); + client = new TestClient(options); + setCurrentClient(client); + client.init(); + }); + + afterEach(() => { + jest.clearAllMocks(); + }); + + it('correctly emits span hooks', () => { + const startedSpans: string[] = []; + const endedSpans: string[] = []; + + client.on('spanStart', span => { + startedSpans.push(spanToJSON(span).description || ''); + }); + + client.on('spanEnd', span => { + endedSpans.push(spanToJSON(span).description || ''); + }); + + startSpan({ name: 'span1' }, () => { + startSpan({ name: 'span2' }, () => { + const span = startInactiveSpan({ name: 'span3' }); + + startSpanManual({ name: 'span5' }, span => { + startInactiveSpan({ name: 'span4' }); + span?.end(); + }); + + span?.end(); + }); + }); + + expect(startedSpans).toHaveLength(5); + expect(endedSpans).toHaveLength(4); + + expect(startedSpans).toEqual(['span1', 'span2', 'span3', 'span5', 'span4']); + expect(endedSpans).toEqual(['span5', 'span3', 'span2', 'span1']); + }); +}); diff --git a/packages/opentelemetry/src/custom/transaction.ts b/packages/opentelemetry/src/custom/transaction.ts index 5cd84892932b..6ebb8aa63f36 100644 --- a/packages/opentelemetry/src/custom/transaction.ts +++ b/packages/opentelemetry/src/custom/transaction.ts @@ -18,6 +18,7 @@ export function startTransaction(hub: HubInterface, transactionContext: Transact if (client) { client.emit('startTransaction', transaction); + client.emit('spanStart', transaction); } return transaction; } diff --git a/packages/opentelemetry/src/spanProcessor.ts b/packages/opentelemetry/src/spanProcessor.ts index 2f348cc877ff..a2f95725ff35 100644 --- a/packages/opentelemetry/src/spanProcessor.ts +++ b/packages/opentelemetry/src/spanProcessor.ts @@ -67,6 +67,9 @@ export class SentrySpanProcessor extends BatchSpanProcessor implements SpanProce public onStart(span: Span, parentContext: Context): void { onSpanStart(span, parentContext); + // TODO (v8): Trigger client `spanStart` & `spanEnd` in here, + // once we decoupled opentelemetry from SentrySpan + DEBUG_BUILD && logger.log(`[Tracing] Starting span "${span.name}" (${span.spanContext().spanId})`); return super.onStart(span, parentContext); diff --git a/packages/types/src/client.ts b/packages/types/src/client.ts index 83b48ac24d9c..df36e21a46c5 100644 --- a/packages/types/src/client.ts +++ b/packages/types/src/client.ts @@ -14,6 +14,7 @@ import type { Scope } from './scope'; import type { SdkMetadata } from './sdkmetadata'; import type { Session, SessionAggregates } from './session'; import type { SeverityLevel } from './severity'; +import type { Span } from './span'; import type { StartSpanOptions } from './startSpanOptions'; import type { Transaction } from './transaction'; import type { Transport, TransportMakeRequestResponse } from './transport'; @@ -193,6 +194,18 @@ export interface Client { */ on(hook: 'finishTransaction', callback: (transaction: Transaction) => void): void; + /** + * Register a callback for whenever a span is started. + * Receives the span as argument. + */ + on(hook: 'spanStart', callback: (span: Span) => void): void; + + /** + * Register a callback for whenever a span is ended. + * Receives the span as argument. + */ + on(hook: 'spanEnd', callback: (span: Span) => void): void; + /** * Register a callback for transaction start and finish. */ @@ -269,6 +282,12 @@ export interface Client { */ emit(hook: 'finishTransaction', transaction: Transaction): void; + /** Fire a hook whener a span starts. */ + emit(hook: 'spanStart', span: Span): void; + + /** Fire a hook whener a span ends. */ + emit(hook: 'spanEnd', span: Span): void; + /* * Fire a hook event for envelope creation and sending. Expects to be given an envelope as the * second argument. From 87745608f41feb69a2649637a5b122d9ecfd3d29 Mon Sep 17 00:00:00 2001 From: Francesco Novy Date: Tue, 5 Mar 2024 15:44:25 +0000 Subject: [PATCH 2/2] feat(core): Add `startIdleSpan()` --- packages/core/src/baseclient.ts | 6 + packages/core/src/tracing/idleSpan.ts | 333 ++++++++++++++ packages/core/src/tracing/index.ts | 2 + packages/core/src/tracing/utils.ts | 7 + .../core/test/lib/tracing/idleSpan.test.ts | 435 ++++++++++++++++++ packages/types/src/client.ts | 10 + 6 files changed, 793 insertions(+) create mode 100644 packages/core/src/tracing/idleSpan.ts create mode 100644 packages/core/test/lib/tracing/idleSpan.test.ts diff --git a/packages/core/src/baseclient.ts b/packages/core/src/baseclient.ts index d2493fa5998f..4180dde1e389 100644 --- a/packages/core/src/baseclient.ts +++ b/packages/core/src/baseclient.ts @@ -429,6 +429,9 @@ export abstract class BaseClient implements Client { /** @inheritdoc */ public on(hook: 'spanEnd', callback: (span: Span) => void): void; + /** @inheritdoc */ + public on(hook: 'idleSpanEnableAutoFinish', callback: (span: Span) => void): void; + /** @inheritdoc */ public on(hook: 'beforeEnvelope', callback: (envelope: Envelope) => void): void; @@ -485,6 +488,9 @@ export abstract class BaseClient implements Client { /** @inheritdoc */ public emit(hook: 'spanEnd', span: Span): void; + /** @inheritdoc */ + public emit(hook: 'idleSpanEnableAutoFinish', span: Span): void; + /** @inheritdoc */ public emit(hook: 'beforeEnvelope', envelope: Envelope): void; diff --git a/packages/core/src/tracing/idleSpan.ts b/packages/core/src/tracing/idleSpan.ts new file mode 100644 index 000000000000..425d5b1aa39e --- /dev/null +++ b/packages/core/src/tracing/idleSpan.ts @@ -0,0 +1,333 @@ +import type { Span, StartSpanOptions } from '@sentry/types'; +import { logger, timestampInSeconds } from '@sentry/utils'; +import { getClient, getCurrentScope } from '../currentScopes'; + +import { DEBUG_BUILD } from '../debug-build'; +import { spanToJSON } from '../utils/spanUtils'; +import { SPAN_STATUS_ERROR } from './spanstatus'; +import { startInactiveSpan } from './trace'; +import { getActiveSpan, getSpanDescendants, removeChildSpanFromSpan } from './utils'; + +export const TRACING_DEFAULTS = { + idleTimeout: 1_000, + finalTimeout: 30_000, + childSpanTimeout: 15_000, +}; + +const FINISH_REASON_TAG = 'finishReason'; + +const FINISH_REASON_HEARTBEAT_FAILED = 'heartbeatFailed'; +const FINISH_REASON_IDLE_TIMEOUT = 'idleTimeout'; +const FINISH_REASON_FINAL_TIMEOUT = 'finalTimeout'; +const FINISH_REASON_EXTERNAL_FINISH = 'externalFinish'; +const FINISH_REASON_CANCELLED = 'cancelled'; + +// unused +const FINISH_REASON_DOCUMENT_HIDDEN = 'documentHidden'; + +// unusued in this file, but used in BrowserTracing +const FINISH_REASON_INTERRUPTED = 'interactionInterrupted'; + +type IdleSpanFinishReason = + | typeof FINISH_REASON_CANCELLED + | typeof FINISH_REASON_DOCUMENT_HIDDEN + | typeof FINISH_REASON_EXTERNAL_FINISH + | typeof FINISH_REASON_FINAL_TIMEOUT + | typeof FINISH_REASON_HEARTBEAT_FAILED + | typeof FINISH_REASON_IDLE_TIMEOUT + | typeof FINISH_REASON_INTERRUPTED; + +interface IdleSpanOptions { + /** + * The time that has to pass without any span being created. + * If this time is exceeded, the idle span will finish. + */ + idleTimeout: number; + /** + * The max. time an idle span may run. + * If this time is exceeded, the idle span will finish no matter what. + */ + finalTimeout: number; + /** + * The max. time a child span may run. + * If the time since the last span was started exceeds this time, the idle span will finish. + */ + childSpanTimeout?: number; + /** + * When set to `true`, will disable the idle timeout and child timeout + * until the `idleSpanEnableAutoFinish` hook is emitted for the idle span. + * The final timeout mechanism will not be affected by this option, + * meaning the idle span will definitely be finished when the final timeout is + * reached, no matter what this option is configured to. + * + * Defaults to `false`. + */ + disableAutoFinish?: boolean; + /** Allows to configure a hook that is called when the idle span is ended, before it is processed. */ + beforeSpanEnd?: (span: Span) => void; +} + +/** + * An idle span is a span that automatically finishes. It does this by tracking child spans as activities. + * An idle span is always the active span. + */ +export function startIdleSpan( + startSpanOptions: StartSpanOptions, + options: Partial = {}, +): Span | undefined { + // Activities store a list of active spans + const activities = new Map(); + + // We should not use heartbeat if we finished a span + let _finished = false; + + // Timer that tracks idleTimeout + let _idleTimeoutID: ReturnType | undefined; + + // Timer that tracks maxSpanTime for child spans + let _childSpanTimeoutID: ReturnType | undefined; + + // The reason why the span was finished + let _finishReason: IdleSpanFinishReason = FINISH_REASON_EXTERNAL_FINISH; + + let _autoFinishAllowed: boolean = !options.disableAutoFinish; + + const { + idleTimeout = TRACING_DEFAULTS.idleTimeout, + finalTimeout = TRACING_DEFAULTS.finalTimeout, + childSpanTimeout = TRACING_DEFAULTS.childSpanTimeout, + beforeSpanEnd, + } = options; + + const client = getClient(); + + if (!client) { + return; + } + + const scope = getCurrentScope(); + const previousActiveSpan = getActiveSpan(); + const _span = _startIdleSpan(startSpanOptions); + + // Span _should_ always be defined here, but TS does not know that... + if (!_span) { + return; + } + + // For TS, so that we know everything below here has a span + const span = _span; + + /** + * Cancels the existing idle timeout, if there is one. + */ + function _cancelIdleTimeout(): void { + if (_idleTimeoutID) { + clearTimeout(_idleTimeoutID); + _idleTimeoutID = undefined; + } + } + + /** + * Cancels the existing child span timeout, if there is one. + */ + function _cancelChildSpanTimeout(): void { + if (_childSpanTimeoutID) { + clearTimeout(_childSpanTimeoutID); + _childSpanTimeoutID = undefined; + } + } + + /** + * Restarts idle timeout, if there is no running idle timeout it will start one. + */ + function _restartIdleTimeout(endTimestamp?: number): void { + _cancelIdleTimeout(); + _idleTimeoutID = setTimeout(() => { + if (!_finished && activities.size === 0 && _autoFinishAllowed) { + _finishReason = FINISH_REASON_IDLE_TIMEOUT; + span.end(endTimestamp); + } + }, idleTimeout); + } + + /** + * Restarts child span timeout, if there is none running it will start one. + */ + function _restartChildSpanTimeout(endTimestamp?: number): void { + _cancelChildSpanTimeout(); + _idleTimeoutID = setTimeout(() => { + if (!_finished && _autoFinishAllowed) { + _finishReason = FINISH_REASON_HEARTBEAT_FAILED; + span.end(endTimestamp); + } + }, childSpanTimeout); + } + + /** + * Start tracking a specific activity. + * @param spanId The span id that represents the activity + */ + function _pushActivity(spanId: string): void { + _cancelIdleTimeout(); + activities.set(spanId, true); + DEBUG_BUILD && logger.log(`[Tracing] pushActivity: ${spanId}`); + DEBUG_BUILD && logger.log('[Tracing] new activities count', activities.size); + + const endTimestamp = timestampInSeconds(); + // We need to add the timeout here to have the real endtimestamp of the idle span + // Remember timestampInSeconds is in seconds, timeout is in ms + _restartChildSpanTimeout(endTimestamp + childSpanTimeout / 1000); + } + + /** + * Remove an activity from usage + * @param spanId The span id that represents the activity + */ + function _popActivity(spanId: string): void { + if (activities.has(spanId)) { + DEBUG_BUILD && logger.log(`[Tracing] popActivity ${spanId}`); + activities.delete(spanId); + DEBUG_BUILD && logger.log('[Tracing] new activities count', activities.size); + } + + if (activities.size === 0) { + const endTimestamp = timestampInSeconds(); + // We need to add the timeout here to have the real endtimestamp of the idle span + // Remember timestampInSeconds is in seconds, timeout is in ms + _restartIdleTimeout(endTimestamp + idleTimeout / 1000); + _cancelChildSpanTimeout(); + } + } + + function endIdleSpan(): void { + _finished = true; + activities.clear(); + + if (beforeSpanEnd) { + beforeSpanEnd(span); + } + + // eslint-disable-next-line deprecation/deprecation + scope.setSpan(previousActiveSpan); + + const spanJSON = spanToJSON(span); + + const { timestamp: endTimestamp, start_timestamp: startTimestamp } = spanJSON; + // This should never happen, but to make TS happy... + if (!endTimestamp || !startTimestamp) { + return; + } + + const attributes = spanJSON.data || {}; + if (spanJSON.op === 'ui.action.click' && !attributes[FINISH_REASON_TAG]) { + span.setAttribute(FINISH_REASON_TAG, _finishReason); + } + + DEBUG_BUILD && + logger.log('[Tracing] finishing idle span', new Date(endTimestamp * 1000).toISOString(), spanJSON.op); + + const childSpans = getSpanDescendants(span).filter(child => child !== span); + + childSpans.forEach(childSpan => { + // We cancel all pending spans with status "cancelled" to indicate the idle span was finished early + if (childSpan.isRecording()) { + childSpan.setStatus({ code: SPAN_STATUS_ERROR, message: 'cancelled' }); + childSpan.end(endTimestamp); + DEBUG_BUILD && + logger.log('[Tracing] cancelling span since span ended early', JSON.stringify(childSpan, undefined, 2)); + } + + const childSpanJSON = spanToJSON(childSpan); + const { timestamp: childEndTimestamp = 0, start_timestamp: childStartTimestamp = 0 } = childSpanJSON; + + const spanStartedBeforeIdleSpanEnd = childStartTimestamp <= endTimestamp; + + // Add a delta with idle timeout so that we prevent false positives + const timeoutWithMarginOfError = (finalTimeout + idleTimeout) / 1000; + const spanEndedBeforeFinalTimeout = childEndTimestamp - childStartTimestamp < timeoutWithMarginOfError; + + if (DEBUG_BUILD) { + const stringifiedSpan = JSON.stringify(childSpan, undefined, 2); + if (!spanStartedBeforeIdleSpanEnd) { + logger.log('[Tracing] discarding Span since it happened after idle span was finished', stringifiedSpan); + } else if (!spanEndedBeforeFinalTimeout) { + logger.log('[Tracing] discarding Span since it finished after idle span final timeout', stringifiedSpan); + } + } + + if (!spanEndedBeforeFinalTimeout || !spanStartedBeforeIdleSpanEnd) { + removeChildSpanFromSpan(span, childSpan); + } + }); + + DEBUG_BUILD && logger.log('[Tracing] flushing idle span'); + } + + client.on('spanStart', startedSpan => { + // If we already finished the idle span, + // or if this is the idle span itself being started, + // or if the started span has already been closed, + // we don't care about it for activity + if (_finished || startedSpan === span || !!spanToJSON(startedSpan).timestamp) { + return; + } + + const allSpans = getSpanDescendants(span); + + // If the span that was just started is a child of the idle span, we should track it + if (allSpans.includes(startedSpan)) { + _pushActivity(startedSpan.spanContext().spanId); + } + }); + + client.on('spanEnd', endedSpan => { + if (_finished) { + return; + } + + _popActivity(endedSpan.spanContext().spanId); + + if (endedSpan === span) { + endIdleSpan(); + } + }); + + client.on('idleSpanEnableAutoFinish', spanToAllowAutoFinish => { + if (spanToAllowAutoFinish === span) { + _autoFinishAllowed = true; + _restartIdleTimeout(); + + if (activities.size) { + _restartChildSpanTimeout(); + } + } + }); + + // We only start the initial idle timeout if we are not delaying the auto finish + if (!options.disableAutoFinish) { + _restartIdleTimeout(); + } + + setTimeout(() => { + if (!_finished) { + span.setStatus({ code: SPAN_STATUS_ERROR, message: 'deadline_exceeded' }); + _finishReason = FINISH_REASON_FINAL_TIMEOUT; + span.end(); + } + }, finalTimeout); + + return span; +} + +function _startIdleSpan(options: StartSpanOptions): Span | undefined { + const span = startInactiveSpan(options); + + // eslint-disable-next-line deprecation/deprecation + getCurrentScope().setSpan(span); + + if (span) { + DEBUG_BUILD && logger.log(`Setting idle span on scope. Span ID: ${span.spanContext().spanId}`); + } + + return span; +} diff --git a/packages/core/src/tracing/index.ts b/packages/core/src/tracing/index.ts index f6f65a59475d..8054e0d06aaa 100644 --- a/packages/core/src/tracing/index.ts +++ b/packages/core/src/tracing/index.ts @@ -18,3 +18,5 @@ export { } from './trace'; export { getDynamicSamplingContextFromClient, getDynamicSamplingContextFromSpan } from './dynamicSamplingContext'; export { setMeasurement } from './measurement'; + +export { startIdleSpan } from './idleSpan'; diff --git a/packages/core/src/tracing/utils.ts b/packages/core/src/tracing/utils.ts index 44224ac6a59a..c299281a6f95 100644 --- a/packages/core/src/tracing/utils.ts +++ b/packages/core/src/tracing/utils.ts @@ -48,6 +48,13 @@ export function addChildSpanToSpan(span: SpanWithPotentialChildren, childSpan: S } } +/** This is only used internally by Idle Spans. */ +export function removeChildSpanFromSpan(span: SpanWithPotentialChildren, childSpan: Span): void { + if (span[CHILD_SPANS_FIELD]) { + span[CHILD_SPANS_FIELD].delete(childSpan); + } +} + /** * Returns an array of the given span and all of its descendants. */ diff --git a/packages/core/test/lib/tracing/idleSpan.test.ts b/packages/core/test/lib/tracing/idleSpan.test.ts new file mode 100644 index 000000000000..ade484bbce4b --- /dev/null +++ b/packages/core/test/lib/tracing/idleSpan.test.ts @@ -0,0 +1,435 @@ +import { TestClient, getDefaultTestClientOptions } from '../../mocks/client'; + +import type { Event, Span } from '@sentry/types'; +import { + addTracingExtensions, + getActiveSpan, + getClient, + getCurrentScope, + getGlobalScope, + getIsolationScope, + setCurrentClient, + spanToJSON, + startInactiveSpan, + startSpan, + startSpanManual, +} from '../../../src'; +import { TRACING_DEFAULTS, startIdleSpan } from '../../../src/tracing/idleSpan'; + +const dsn = 'https://123@sentry.io/42'; + +describe('startIdleSpan', () => { + beforeEach(() => { + jest.useFakeTimers(); + addTracingExtensions(); + + getCurrentScope().clear(); + getIsolationScope().clear(); + getGlobalScope().clear(); + + const options = getDefaultTestClientOptions({ dsn, tracesSampleRate: 1 }); + const client = new TestClient(options); + setCurrentClient(client); + client.init(); + }); + + afterEach(() => { + jest.clearAllMocks(); + }); + + it('sets & unsets the idle span on the scope', () => { + const idleSpan = startIdleSpan({ name: 'foo' }); + expect(idleSpan).toBeDefined(); + + expect(getActiveSpan()).toBe(idleSpan); + + idleSpan!.end(); + jest.runAllTimers(); + + expect(getActiveSpan()).toBe(undefined); + }); + + it('does not finish idle span if there are still active activities', () => { + const idleSpan = startIdleSpan({ name: 'foo' })!; + expect(idleSpan).toBeDefined(); + + startSpanManual({ name: 'inner1' }, span => { + const childSpan = startInactiveSpan({ name: 'inner2' })!; + + span?.end(); + jest.advanceTimersByTime(TRACING_DEFAULTS.idleTimeout + 1); + + // Idle span is still recording + expect(idleSpan.isRecording()).toBe(true); + + childSpan?.end(); + jest.advanceTimersByTime(TRACING_DEFAULTS.idleTimeout + 1); + + // Now it is finished! + expect(idleSpan.isRecording()).toBe(false); + }); + }); + + it('calls beforeSpanEnd callback before finishing', () => { + const beforeSpanEnd = jest.fn(); + const idleSpan = startIdleSpan({ name: 'foo' }, { beforeSpanEnd })!; + expect(idleSpan).toBeDefined(); + + expect(beforeSpanEnd).not.toHaveBeenCalled(); + + startSpan({ name: 'inner' }, () => {}); + + jest.runOnlyPendingTimers(); + expect(beforeSpanEnd).toHaveBeenCalledTimes(1); + expect(beforeSpanEnd).toHaveBeenLastCalledWith(idleSpan); + }); + + it('allows to mutate idle span in beforeSpanEnd before it is sent', () => { + const transactions: Event[] = []; + const beforeSendTransaction = jest.fn(event => { + transactions.push(event); + return null; + }); + const options = getDefaultTestClientOptions({ + dsn, + tracesSampleRate: 1, + beforeSendTransaction, + }); + const client = new TestClient(options); + setCurrentClient(client); + client.init(); + + // We want to accomodate a bit of drift there, so we ensure this starts earlier... + const baseTimeInSeconds = Math.floor(Date.now() / 1000) - 9999; + + const beforeSpanEnd = jest.fn((span: Span) => { + span.setAttribute('foo', 'bar'); + // Try adding a child here - we do this in browser tracing... + const inner = startInactiveSpan({ name: 'from beforeSpanEnd', startTime: baseTimeInSeconds }); + inner?.end(baseTimeInSeconds); + }); + const idleSpan = startIdleSpan({ name: 'idle span 2', startTime: baseTimeInSeconds }, { beforeSpanEnd })!; + expect(idleSpan).toBeDefined(); + + expect(beforeSpanEnd).not.toHaveBeenCalled(); + + jest.advanceTimersByTime(TRACING_DEFAULTS.idleTimeout + 1); + jest.runOnlyPendingTimers(); + + expect(spanToJSON(idleSpan!).data).toEqual( + expect.objectContaining({ + foo: 'bar', + }), + ); + + expect(beforeSendTransaction).toHaveBeenCalledTimes(1); + const transaction = transactions[0]; + + expect(transaction.contexts?.trace?.data).toEqual( + expect.objectContaining({ + foo: 'bar', + }), + ); + expect(transaction.spans).toHaveLength(1); + expect(transaction.spans).toEqual([expect.objectContaining({ description: 'from beforeSpanEnd' })]); + }); + + it('filters spans on end', () => { + const transactions: Event[] = []; + const beforeSendTransaction = jest.fn(event => { + transactions.push(event); + return null; + }); + const options = getDefaultTestClientOptions({ + dsn, + tracesSampleRate: 1, + beforeSendTransaction, + }); + const client = new TestClient(options); + setCurrentClient(client); + client.init(); + + // We want to accomodate a bit of drift there, so we ensure this starts earlier... + const baseTimeInSeconds = Math.floor(Date.now() / 1000) - 9999; + + const idleSpan = startIdleSpan({ name: 'idle span', startTime: baseTimeInSeconds })!; + expect(idleSpan).toBeDefined(); + + // regular child - should be kept + const regularSpan = startInactiveSpan({ + name: 'regular span', + startTime: baseTimeInSeconds + 2, + })!; + + // discardedSpan - startTimestamp is too large + const discardedSpan = startInactiveSpan({ name: 'discarded span', startTime: baseTimeInSeconds + 99 })!; + // discardedSpan2 - endTime is too large + const discardedSpan2 = startInactiveSpan({ name: 'discarded span', startTime: baseTimeInSeconds + 3 })!; + discardedSpan2.end(baseTimeInSeconds + 99)!; + + // Should be cancelled - will not finish + const cancelledSpan = startInactiveSpan({ + name: 'cancelled span', + startTime: baseTimeInSeconds + 4, + })!; + + regularSpan.end(baseTimeInSeconds + 4); + idleSpan.end(baseTimeInSeconds + 10); + + jest.advanceTimersByTime(TRACING_DEFAULTS.idleTimeout + 1); + jest.runOnlyPendingTimers(); + + expect(regularSpan.isRecording()).toBe(false); + expect(idleSpan.isRecording()).toBe(false); + expect(discardedSpan.isRecording()).toBe(false); + expect(discardedSpan2.isRecording()).toBe(false); + expect(cancelledSpan.isRecording()).toBe(false); + + expect(beforeSendTransaction).toHaveBeenCalledTimes(1); + const transaction = transactions[0]; + + // End time is based on idle time etc. + const idleSpanEndTime = transaction.timestamp!; + expect(idleSpanEndTime).toEqual(expect.any(Number)); + + expect(transaction.spans).toHaveLength(2); + expect(transaction.spans).toEqual( + expect.arrayContaining([ + expect.objectContaining({ + description: 'regular span', + timestamp: baseTimeInSeconds + 4, + start_timestamp: baseTimeInSeconds + 2, + }), + ]), + ); + expect(transaction.spans).toEqual( + expect.arrayContaining([ + expect.objectContaining({ + description: 'cancelled span', + timestamp: idleSpanEndTime, + start_timestamp: baseTimeInSeconds + 4, + status: 'cancelled', + }), + ]), + ); + }); + + it('emits span hooks', () => { + const client = getClient()!; + + const hookSpans: { span: Span; hook: string }[] = []; + client.on('spanStart', span => { + hookSpans.push({ span, hook: 'spanStart' }); + }); + client.on('spanEnd', span => { + hookSpans.push({ span, hook: 'spanEnd' }); + }); + + const idleSpan = startIdleSpan({ name: 'idle span' })!; + expect(idleSpan).toBeDefined(); + + expect(hookSpans).toEqual([{ span: idleSpan, hook: 'spanStart' }]); + + jest.advanceTimersByTime(TRACING_DEFAULTS.idleTimeout); + expect(spanToJSON(idleSpan).timestamp).toBeDefined(); + + expect(hookSpans).toEqual([ + { span: idleSpan, hook: 'spanStart' }, + { span: idleSpan, hook: 'spanEnd' }, + ]); + }); + + it('should record dropped idle span', () => { + const options = getDefaultTestClientOptions({ + dsn, + tracesSampleRate: 0, + }); + const client = new TestClient(options); + setCurrentClient(client); + client.init(); + + const recordDroppedEventSpy = jest.spyOn(client, 'recordDroppedEvent'); + + const idleSpan = startIdleSpan({ name: 'idle span' })!; + expect(idleSpan).toBeDefined(); + + idleSpan?.end(); + + expect(recordDroppedEventSpy).toHaveBeenCalledWith('sample_rate', 'transaction'); + }); + + describe('idleTimeout', () => { + it('finishes if no activities are added to the idle span', () => { + const idleSpan = startIdleSpan({ name: 'idle span' })!; + expect(idleSpan).toBeDefined(); + + jest.advanceTimersByTime(TRACING_DEFAULTS.idleTimeout); + expect(spanToJSON(idleSpan).timestamp).toBeDefined(); + }); + + it('does not finish if a activity is started', () => { + const idleSpan = startIdleSpan({ name: 'idle span' })!; + expect(idleSpan).toBeDefined(); + + startInactiveSpan({ name: 'span' }); + + jest.advanceTimersByTime(TRACING_DEFAULTS.idleTimeout); + expect(spanToJSON(idleSpan).timestamp).toBeUndefined(); + }); + + it('does not finish when idleTimeout is not exceed after last activity finished', () => { + const idleTimeout = 10; + const idleSpan = startIdleSpan({ name: 'idle span' }, { idleTimeout })!; + expect(idleSpan).toBeDefined(); + + startSpan({ name: 'span1' }, () => {}); + + jest.advanceTimersByTime(2); + + startSpan({ name: 'span2' }, () => {}); + + jest.advanceTimersByTime(8); + + expect(spanToJSON(idleSpan).timestamp).toBeUndefined(); + }); + + it('finish when idleTimeout is exceeded after last activity finished', () => { + const idleTimeout = 10; + const idleSpan = startIdleSpan({ name: 'idle span', startTime: 1234 }, { idleTimeout })!; + expect(idleSpan).toBeDefined(); + + startSpan({ name: 'span1' }, () => {}); + + jest.advanceTimersByTime(2); + + startSpan({ name: 'span2' }, () => {}); + + jest.advanceTimersByTime(10); + + expect(spanToJSON(idleSpan).timestamp).toBeDefined(); + }); + }); + + describe('child span timeout', () => { + it('finishes when a child span exceed timeout', () => { + const idleSpan = startIdleSpan({ name: 'idle span' })!; + expect(idleSpan).toBeDefined(); + + // Start any span to cancel idle timeout + startInactiveSpan({ name: 'span' }); + + expect(spanToJSON(idleSpan).status).not.toEqual('deadline_exceeded'); + expect(spanToJSON(idleSpan).timestamp).toBeUndefined(); + + // Wait some time + jest.advanceTimersByTime(TRACING_DEFAULTS.childSpanTimeout - 1000); + expect(spanToJSON(idleSpan).status).not.toEqual('deadline_exceeded'); + expect(spanToJSON(idleSpan).timestamp).toBeUndefined(); + + // Wait for timeout to exceed + jest.advanceTimersByTime(1000); + expect(spanToJSON(idleSpan).status).not.toEqual('deadline_exceeded'); + expect(spanToJSON(idleSpan).timestamp).toBeDefined(); + }); + + it('resets after new activities are added', () => { + const idleSpan = startIdleSpan({ name: 'idle span' }, { finalTimeout: 99_999 })!; + expect(idleSpan).toBeDefined(); + + // Start any span to cancel idle timeout + startInactiveSpan({ name: 'span' }); + + expect(spanToJSON(idleSpan).status).not.toEqual('deadline_exceeded'); + expect(spanToJSON(idleSpan).timestamp).toBeUndefined(); + + // Wait some time + jest.advanceTimersByTime(TRACING_DEFAULTS.childSpanTimeout - 1000); + expect(spanToJSON(idleSpan).status).not.toEqual('deadline_exceeded'); + expect(spanToJSON(idleSpan).timestamp).toBeUndefined(); + + // New span resets the timeout + startInactiveSpan({ name: 'span' }); + + jest.advanceTimersByTime(TRACING_DEFAULTS.childSpanTimeout - 1000); + expect(spanToJSON(idleSpan).status).not.toEqual('deadline_exceeded'); + expect(spanToJSON(idleSpan).timestamp).toBeUndefined(); + + // New span resets the timeout + startInactiveSpan({ name: 'span' }); + + jest.advanceTimersByTime(TRACING_DEFAULTS.childSpanTimeout - 1000); + expect(spanToJSON(idleSpan).status).not.toEqual('deadline_exceeded'); + expect(spanToJSON(idleSpan).timestamp).toBeUndefined(); + + // Wait for timeout to exceed + jest.advanceTimersByTime(1000); + expect(spanToJSON(idleSpan).status).not.toEqual('deadline_exceeded'); + expect(spanToJSON(idleSpan).timestamp).toBeDefined(); + }); + }); + + describe('disableAutoFinish', () => { + it('skips idle timeout if disableAutoFinish=true', () => { + const idleSpan = startIdleSpan({ name: 'idle span' }, { disableAutoFinish: true })!; + expect(idleSpan).toBeDefined(); + + jest.advanceTimersByTime(TRACING_DEFAULTS.idleTimeout); + expect(spanToJSON(idleSpan).timestamp).toBeUndefined(); + + jest.advanceTimersByTime(TRACING_DEFAULTS.idleTimeout); + expect(spanToJSON(idleSpan).timestamp).toBeUndefined(); + + // Now emit a signal + getClient()!.emit('idleSpanEnableAutoFinish', idleSpan); + + jest.advanceTimersByTime(TRACING_DEFAULTS.idleTimeout); + expect(spanToJSON(idleSpan).timestamp).toBeDefined(); + }); + + it('skips span timeout if disableAutoFinish=true', () => { + const idleSpan = startIdleSpan({ name: 'idle span' }, { disableAutoFinish: true, finalTimeout: 99_999 })!; + expect(idleSpan).toBeDefined(); + + startInactiveSpan({ name: 'inner' }); + + jest.advanceTimersByTime(TRACING_DEFAULTS.childSpanTimeout); + expect(spanToJSON(idleSpan).timestamp).toBeUndefined(); + + jest.advanceTimersByTime(TRACING_DEFAULTS.childSpanTimeout); + expect(spanToJSON(idleSpan).timestamp).toBeUndefined(); + + // Now emit a signal + getClient()!.emit('idleSpanEnableAutoFinish', idleSpan); + + jest.advanceTimersByTime(TRACING_DEFAULTS.childSpanTimeout); + expect(spanToJSON(idleSpan).timestamp).toBeDefined(); + }); + + it('times out at final timeout if disableAutoFinish=true', () => { + const idleSpan = startIdleSpan({ name: 'idle span' }, { disableAutoFinish: true })!; + expect(idleSpan).toBeDefined(); + + jest.advanceTimersByTime(TRACING_DEFAULTS.finalTimeout); + expect(spanToJSON(idleSpan).timestamp).toBeDefined(); + }); + + it('ignores it if hook is emitted with other span', () => { + const span = startInactiveSpan({ name: 'other span' })!; + const idleSpan = startIdleSpan({ name: 'idle span' }, { disableAutoFinish: true })!; + expect(idleSpan).toBeDefined(); + + jest.advanceTimersByTime(TRACING_DEFAULTS.idleTimeout); + expect(spanToJSON(idleSpan).timestamp).toBeUndefined(); + + jest.advanceTimersByTime(TRACING_DEFAULTS.idleTimeout); + expect(spanToJSON(idleSpan).timestamp).toBeUndefined(); + + // Now emit a signal, but with a different span + getClient()!.emit('idleSpanEnableAutoFinish', span); + + // This doesn't affect us! + jest.advanceTimersByTime(TRACING_DEFAULTS.idleTimeout); + expect(spanToJSON(idleSpan).timestamp).toBeUndefined(); + }); + }); +}); diff --git a/packages/types/src/client.ts b/packages/types/src/client.ts index df36e21a46c5..23eede42d1e3 100644 --- a/packages/types/src/client.ts +++ b/packages/types/src/client.ts @@ -206,6 +206,11 @@ export interface Client { */ on(hook: 'spanEnd', callback: (span: Span) => void): void; + /** + * Register a callback for when an idle span is allowed to auto-finish. + */ + on(hook: 'idleSpanEnableAutoFinish', callback: (span: Span) => void): void; + /** * Register a callback for transaction start and finish. */ @@ -288,6 +293,11 @@ export interface Client { /** Fire a hook whener a span ends. */ emit(hook: 'spanEnd', span: Span): void; + /** + * Fire a hook indicating that an idle span is allowed to auto finish. + */ + emit(hook: 'idleSpanEnableAutoFinish', span: Span): void; + /* * Fire a hook event for envelope creation and sending. Expects to be given an envelope as the * second argument.