diff --git a/packages/tracing/src/hubextensions.ts b/packages/tracing/src/hubextensions.ts index 8480ffbf1bde..313ee8c81119 100644 --- a/packages/tracing/src/hubextensions.ts +++ b/packages/tracing/src/hubextensions.ts @@ -1,8 +1,7 @@ import { getMainCarrier, Hub } from '@sentry/hub'; -import { SpanContext, TransactionContext } from '@sentry/types'; -import { logger } from '@sentry/utils'; +import { TransactionContext } from '@sentry/types'; -import { Span } from './span'; +import { IdleTransaction } from './idletransaction'; import { Transaction } from './transaction'; /** Returns all trace headers that are currently on the top scope. */ @@ -20,13 +19,10 @@ function traceHeaders(this: Hub): { [key: string]: string } { } /** - * {@see Hub.startTransaction} + * Use RNG to generate sampling decision, which all child spans inherit. */ -function startTransaction(this: Hub, context: TransactionContext): Transaction { - const transaction = new Transaction(context, this); - - const client = this.getClient(); - // Roll the dice for sampling transaction, all child spans inherit the sampling decision. +function sample(hub: Hub, transaction: T): T { + const client = hub.getClient(); if (transaction.sampled === undefined) { const sampleRate = (client && client.getOptions().tracesSampleRate) || 0; // if true = we want to have the transaction @@ -46,41 +42,24 @@ function startTransaction(this: Hub, context: TransactionContext): Transaction { } /** - * {@see Hub.startSpan} + * {@see Hub.startTransaction} */ -function startSpan(this: Hub, context: SpanContext): Transaction | Span { - /** - * @deprecated - * TODO: consider removing this in a future release. - * - * This is for backwards compatibility with releases before startTransaction - * existed, to allow for a smoother transition. - */ - { - // The `TransactionContext.name` field used to be called `transaction`. - const transactionContext = context as Partial; - if (transactionContext.transaction !== undefined) { - transactionContext.name = transactionContext.transaction; - } - // Check for not undefined since we defined it's ok to start a transaction - // with an empty name. - if (transactionContext.name !== undefined) { - logger.warn('Deprecated: Use startTransaction to start transactions and Transaction.startChild to start spans.'); - return this.startTransaction(transactionContext as TransactionContext); - } - } - - const scope = this.getScope(); - if (scope) { - // If there is a Span on the Scope we start a child and return that instead - const parentSpan = scope.getSpan(); - if (parentSpan) { - return parentSpan.startChild(context); - } - } +function startTransaction(this: Hub, context: TransactionContext): Transaction { + const transaction = new Transaction(context, this); + return sample(this, transaction); +} - // Otherwise we return a new Span - return new Span(context); +/** + * Create new idle transaction. + */ +export function startIdleTransaction( + this: Hub, + context: TransactionContext, + idleTimeout?: number, + onScope?: boolean, +): IdleTransaction { + const transaction = new IdleTransaction(context, this, idleTimeout, onScope); + return sample(this, transaction); } /** @@ -93,9 +72,6 @@ export function addExtensionMethods(): void { if (!carrier.__SENTRY__.extensions.startTransaction) { carrier.__SENTRY__.extensions.startTransaction = startTransaction; } - if (!carrier.__SENTRY__.extensions.startSpan) { - carrier.__SENTRY__.extensions.startSpan = startSpan; - } if (!carrier.__SENTRY__.extensions.traceHeaders) { carrier.__SENTRY__.extensions.traceHeaders = traceHeaders; } diff --git a/packages/tracing/src/idletransaction.ts b/packages/tracing/src/idletransaction.ts new file mode 100644 index 000000000000..5ba230f5a12d --- /dev/null +++ b/packages/tracing/src/idletransaction.ts @@ -0,0 +1,265 @@ +// tslint:disable: max-classes-per-file +import { Hub } from '@sentry/hub'; +import { TransactionContext } from '@sentry/types'; +import { logger, timestampWithMs } from '@sentry/utils'; + +import { Span } from './span'; +import { SpanStatus } from './spanstatus'; +import { SpanRecorder, Transaction } from './transaction'; + +const DEFAULT_IDLE_TIMEOUT = 1000; + +/** + * @inheritDoc + */ +export class IdleTransactionSpanRecorder extends SpanRecorder { + public constructor( + private readonly _pushActivity: (id: string) => void, + private readonly _popActivity: (id: string) => void, + public transactionSpanId: string = '', + maxlen?: number, + ) { + super(maxlen); + } + + /** + * @inheritDoc + */ + public add(span: Span): void { + // We should make sure we do not push and pop activities for + // the transaction that this span recorder belongs to. + if (span.spanId !== this.transactionSpanId) { + // We patch span.finish() to pop an activity after setting an endTimestamp. + span.finish = (endTimestamp?: number) => { + span.endTimestamp = typeof endTimestamp === 'number' ? endTimestamp : timestampWithMs(); + this._popActivity(span.spanId); + }; + + // We should only push new activities if the span does not have an end timestamp. + if (span.endTimestamp === undefined) { + this._pushActivity(span.spanId); + } + } + + super.add(span); + } +} + +/** + * An IdleTransaction is a transaction that automatically finishes. It does this by tracking child spans as activities. + * You can have multiple IdleTransactions active, but if the `onScope` option is specified, the idle transaction will + * put itself on the scope on creation. + */ +export class IdleTransaction extends Transaction { + // Activities store a list of active spans + public activities: Record = {}; + + // Stores reference to the timeout that calls _beat(). + private _heartbeatTimer: number = 0; + + // Track state of activities in previous heartbeat + private _prevHeartbeatString: string | undefined; + + // Amount of times heartbeat has counted. Will cause transaction to finish after 3 beats. + private _heartbeatCounter: number = 1; + + // We should not use heartbeat if we finished a transaction + private _finished: boolean = false; + + private _finishCallback?: (transactionSpan: IdleTransaction) => void; + + public constructor( + transactionContext: TransactionContext, + 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, + // If an idle transaction should be put itself on and off the scope automatically. + private readonly _onScope: boolean = false, + ) { + super(transactionContext, _idleHub); + + if (_idleHub && _onScope) { + // There should only be one active transaction on the scope + clearActiveTransaction(_idleHub); + + // We set the transaction here on the scope so error events pick up the trace + // context and attach it to the error. + logger.log(`Setting idle transaction on scope. Span ID: ${this.spanId}`); + _idleHub.configureScope(scope => scope.setSpan(this)); + } + } + + /** + * Checks when entries of this.activities are not changing for 3 beats. + * If this occurs we finish the transaction. + */ + private _beat(): void { + clearTimeout(this._heartbeatTimer); + // We should not be running heartbeat if the idle transaction is finished. + if (this._finished) { + return; + } + + const keys = Object.keys(this.activities); + const heartbeatString = keys.length ? keys.reduce((prev: string, current: string) => prev + current) : ''; + + if (heartbeatString === this._prevHeartbeatString) { + this._heartbeatCounter++; + } else { + this._heartbeatCounter = 1; + } + + this._prevHeartbeatString = heartbeatString; + + if (this._heartbeatCounter >= 3) { + logger.log( + `[Tracing] Transaction: ${ + SpanStatus.Cancelled + } -> Heartbeat safeguard kicked in since content hasn't changed for 3 beats`, + ); + this.setStatus(SpanStatus.DeadlineExceeded); + this.setTag('heartbeat', 'failed'); + this.finishIdleTransaction(timestampWithMs()); + } else { + this._pingHeartbeat(); + } + } + + /** + * Pings the heartbeat + */ + private _pingHeartbeat(): void { + logger.log(`pinging Heartbeat -> current counter: ${this._heartbeatCounter}`); + this._heartbeatTimer = (setTimeout(() => { + this._beat(); + }, 5000) as any) as number; + } + + /** + * Finish the current active idle transaction + */ + public finishIdleTransaction(endTimestamp: number): void { + if (this.spanRecorder) { + logger.log('[Tracing] finishing IdleTransaction', new Date(endTimestamp * 1000).toISOString(), this.op); + + if (this._finishCallback) { + this._finishCallback(this); + } + + this.spanRecorder.spans = this.spanRecorder.spans.filter((span: Span) => { + // If we are dealing with the transaction itself, we just return it + if (span.spanId === this.spanId) { + return true; + } + + // We cancel all pending spans with status "cancelled" to indicate the idle transaction was finished early + if (!span.endTimestamp) { + span.endTimestamp = endTimestamp; + span.setStatus(SpanStatus.Cancelled); + logger.log('[Tracing] cancelling span since transaction ended early', JSON.stringify(span, undefined, 2)); + } + + const keepSpan = span.startTimestamp < endTimestamp; + if (!keepSpan) { + logger.log( + '[Tracing] discarding Span since it happened after Transaction was finished', + JSON.stringify(span, undefined, 2), + ); + } + return keepSpan; + }); + + this._finished = true; + this.activities = {}; + // this._onScope is true if the transaction was previously on the scope. + if (this._onScope) { + clearActiveTransaction(this._idleHub); + } + + logger.log('[Tracing] flushing IdleTransaction'); + this.finish(endTimestamp); + } else { + logger.log('[Tracing] No active IdleTransaction'); + } + } + + /** + * Start tracking a specific activity. + * @param spanId The span id that represents the activity + */ + private _pushActivity(spanId: string): void { + logger.log(`[Tracing] pushActivity: ${spanId}`); + this.activities[spanId] = true; + logger.log('[Tracing] new activities count', Object.keys(this.activities).length); + } + + /** + * Remove an activity from usage + * @param spanId The span id that represents the activity + */ + private _popActivity(spanId: string): void { + if (this.activities[spanId]) { + logger.log(`[Tracing] popActivity ${spanId}`); + // tslint:disable-next-line: no-dynamic-delete + delete this.activities[spanId]; + logger.log('[Tracing] new activities count', Object.keys(this.activities).length); + } + + 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(() => { + this.finishIdleTransaction(end); + }, timeout); + } + } + + /** + * Register a callback function that gets excecuted before the transaction finishes. + * Useful for cleanup or if you want to add any additional spans based on current context. + * + * This is exposed because users have no other way of running something before an idle transaction + * finishes. + */ + public beforeFinish(callback: (transactionSpan: IdleTransaction) => void): void { + this._finishCallback = callback; + } + + /** + * @inheritDoc + */ + public initSpanRecorder(maxlen?: number): void { + if (!this.spanRecorder) { + const pushActivity = (id: string) => { + this._pushActivity(id); + }; + const popActivity = (id: string) => { + this._popActivity(id); + }; + this.spanRecorder = new IdleTransactionSpanRecorder(pushActivity, popActivity, this.spanId, maxlen); + + // Start heartbeat so that transactions do not run forever. + logger.log('Starting heartbeat'); + this._pingHeartbeat(); + } + this.spanRecorder.add(this); + } +} + +/** + * Reset active transaction on scope + */ +function clearActiveTransaction(hub?: Hub): void { + if (hub) { + const scope = hub.getScope(); + if (scope) { + const transaction = scope.getTransaction(); + if (transaction) { + scope.setSpan(undefined); + } + } + } +} diff --git a/packages/tracing/test/idletransaction.test.ts b/packages/tracing/test/idletransaction.test.ts new file mode 100644 index 000000000000..72b2418b7f29 --- /dev/null +++ b/packages/tracing/test/idletransaction.test.ts @@ -0,0 +1,287 @@ +import { BrowserClient } from '@sentry/browser'; +import { Hub } from '@sentry/hub'; + +import { IdleTransaction, IdleTransactionSpanRecorder } from '../src/idletransaction'; +import { Span } from '../src/span'; +import { SpanStatus } from '../src/spanstatus'; + +let hub: Hub; +beforeEach(() => { + hub = new Hub(new BrowserClient({ tracesSampleRate: 1 })); +}); + +describe('IdleTransaction', () => { + describe('onScope', () => { + it('sets the transaction on the scope on creation if onScope is true', () => { + const transaction = new IdleTransaction({ name: 'foo' }, hub, 1000, true); + transaction.initSpanRecorder(10); + + hub.configureScope(s => { + expect(s.getTransaction()).toBe(transaction); + }); + }); + + it('does not set the transaction on the scope on creation if onScope is falsey', () => { + const transaction = new IdleTransaction({ name: 'foo' }, hub, 1000); + transaction.initSpanRecorder(10); + + hub.configureScope(s => { + expect(s.getTransaction()).toBe(undefined); + }); + }); + + it('removes transaction from scope on finish if onScope is true', () => { + const transaction = new IdleTransaction({ name: 'foo' }, hub, 1000, true); + transaction.initSpanRecorder(10); + + transaction.finish(); + jest.runAllTimers(); + + hub.configureScope(s => { + expect(s.getTransaction()).toBe(undefined); + }); + }); + }); + + beforeEach(() => { + jest.useFakeTimers(); + }); + + it('push and pops activities', () => { + const mockFinish = jest.fn(); + const transaction = new IdleTransaction({ name: 'foo' }, hub, 1000); + transaction.finishIdleTransaction = mockFinish; + transaction.initSpanRecorder(10); + expect(transaction.activities).toMatchObject({}); + + const span = transaction.startChild(); + expect(transaction.activities).toMatchObject({ [span.spanId]: true }); + + expect(mockFinish).toHaveBeenCalledTimes(0); + + span.finish(); + expect(transaction.activities).toMatchObject({}); + + jest.runOnlyPendingTimers(); + expect(mockFinish).toHaveBeenCalledTimes(1); + }); + + it('does not push activities if a span already has an end timestamp', () => { + const transaction = new IdleTransaction({ name: 'foo' }, hub, 1000); + transaction.initSpanRecorder(10); + expect(transaction.activities).toMatchObject({}); + + transaction.startChild({ startTimestamp: 1234, endTimestamp: 5678 }); + expect(transaction.activities).toMatchObject({}); + }); + + it('does not finish if there are still active activities', () => { + const mockFinish = jest.fn(); + const transaction = new IdleTransaction({ name: 'foo' }, hub, 1000); + + transaction.finish = mockFinish; + transaction.initSpanRecorder(10); + expect(transaction.activities).toMatchObject({}); + + const span = transaction.startChild(); + const childSpan = span.startChild(); + + expect(transaction.activities).toMatchObject({ [span.spanId]: true, [childSpan.spanId]: true }); + span.finish(); + jest.runOnlyPendingTimers(); + + expect(mockFinish).toHaveBeenCalledTimes(0); + expect(transaction.activities).toMatchObject({ [childSpan.spanId]: true }); + }); + + it('calls beforeFinish callback before finishing', () => { + const mockCallback = jest.fn(); + const transaction = new IdleTransaction({ name: 'foo' }, hub, 1000); + transaction.initSpanRecorder(10); + transaction.beforeFinish(mockCallback); + + expect(mockCallback).toHaveBeenCalledTimes(0); + + const span = transaction.startChild(); + span.finish(); + + jest.runOnlyPendingTimers(); + expect(mockCallback).toHaveBeenCalledTimes(1); + expect(mockCallback).toHaveBeenLastCalledWith(transaction); + }); + + it('filters spans on finish', () => { + const transaction = new IdleTransaction({ name: 'foo', startTimestamp: 1234 }, hub, 1000); + transaction.initSpanRecorder(10); + + // regular child - should be kept + const regularSpan = transaction.startChild({ startTimestamp: transaction.startTimestamp + 2 }); + + // discardedSpan - startTimestamp is too large + transaction.startChild({ startTimestamp: 645345234 }); + + // Should be cancelled - will not finish + const cancelledSpan = transaction.startChild({ startTimestamp: transaction.startTimestamp + 4 }); + + regularSpan.finish(regularSpan.startTimestamp + 4); + transaction.finishIdleTransaction(transaction.startTimestamp + 10); + + expect(transaction.spanRecorder).toBeDefined(); + if (transaction.spanRecorder) { + const spans = transaction.spanRecorder.spans; + expect(spans).toHaveLength(3); + expect(spans[0].spanId).toBe(transaction.spanId); + + // Regular Span - should not modified + expect(spans[1].spanId).toBe(regularSpan.spanId); + expect(spans[1].endTimestamp).not.toBe(transaction.endTimestamp); + + // Cancelled Span - has endtimestamp of transaction + expect(spans[2].spanId).toBe(cancelledSpan.spanId); + expect(spans[2].status).toBe(SpanStatus.Cancelled); + expect(spans[2].endTimestamp).toBe(transaction.endTimestamp); + } + }); + + describe('heartbeat', () => { + it('does not start heartbeat if there is no span recorder', () => { + const mockFinish = jest.fn(); + const transaction = new IdleTransaction({ name: 'foo' }, hub, 1000); + transaction.finish = mockFinish; + + expect(mockFinish).toHaveBeenCalledTimes(0); + + // Beat 1 + jest.runOnlyPendingTimers(); + expect(mockFinish).toHaveBeenCalledTimes(0); + + // Beat 2 + jest.runOnlyPendingTimers(); + expect(mockFinish).toHaveBeenCalledTimes(0); + + // Beat 3 + jest.runOnlyPendingTimers(); + expect(mockFinish).toHaveBeenCalledTimes(0); + }); + it('finishes a transaction after 3 beats', () => { + const mockFinish = jest.fn(); + const transaction = new IdleTransaction({ name: 'foo' }, hub, 1000); + transaction.finish = mockFinish; + transaction.initSpanRecorder(10); + + expect(mockFinish).toHaveBeenCalledTimes(0); + + // Beat 1 + jest.runOnlyPendingTimers(); + expect(mockFinish).toHaveBeenCalledTimes(0); + + // Beat 2 + jest.runOnlyPendingTimers(); + expect(mockFinish).toHaveBeenCalledTimes(0); + + // Beat 3 + jest.runOnlyPendingTimers(); + expect(mockFinish).toHaveBeenCalledTimes(1); + }); + + it('resets after new activities are added', () => { + const mockFinish = jest.fn(); + const transaction = new IdleTransaction({ name: 'foo' }, hub, 1000); + transaction.finish = mockFinish; + transaction.initSpanRecorder(10); + + expect(mockFinish).toHaveBeenCalledTimes(0); + + // Beat 1 + jest.runOnlyPendingTimers(); + expect(mockFinish).toHaveBeenCalledTimes(0); + + const span = transaction.startChild(); // push activity + + // Beat 1 + jest.runOnlyPendingTimers(); + expect(mockFinish).toHaveBeenCalledTimes(0); + + // Beat 2 + jest.runOnlyPendingTimers(); + expect(mockFinish).toHaveBeenCalledTimes(0); + + transaction.startChild(); // push activity + transaction.startChild(); // push activity + + // Beat 1 + jest.runOnlyPendingTimers(); + expect(mockFinish).toHaveBeenCalledTimes(0); + + // Beat 2 + jest.runOnlyPendingTimers(); + expect(mockFinish).toHaveBeenCalledTimes(0); + + span.finish(); // pop activity + + // Beat 1 + jest.runOnlyPendingTimers(); + expect(mockFinish).toHaveBeenCalledTimes(0); + + // Beat 2 + jest.runOnlyPendingTimers(); + expect(mockFinish).toHaveBeenCalledTimes(0); + + // Beat 3 + jest.runOnlyPendingTimers(); + expect(mockFinish).toHaveBeenCalledTimes(1); + + // Heartbeat does not keep going after finish has been called + jest.runAllTimers(); + expect(mockFinish).toHaveBeenCalledTimes(1); + }); + }); +}); + +describe('IdleTransactionSpanRecorder', () => { + it('pushes and pops activities', () => { + const mockPushActivity = jest.fn(); + const mockPopActivity = jest.fn(); + const spanRecorder = new IdleTransactionSpanRecorder(mockPushActivity, mockPopActivity, undefined, 10); + expect(mockPushActivity).toHaveBeenCalledTimes(0); + expect(mockPopActivity).toHaveBeenCalledTimes(0); + + const span = new Span({ sampled: true }); + + expect(spanRecorder.spans).toHaveLength(0); + spanRecorder.add(span); + expect(spanRecorder.spans).toHaveLength(1); + + expect(mockPushActivity).toHaveBeenCalledTimes(1); + expect(mockPushActivity).toHaveBeenLastCalledWith(span.spanId); + expect(mockPopActivity).toHaveBeenCalledTimes(0); + + span.finish(); + expect(mockPushActivity).toHaveBeenCalledTimes(1); + expect(mockPopActivity).toHaveBeenCalledTimes(1); + expect(mockPushActivity).toHaveBeenLastCalledWith(span.spanId); + }); + + 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 span = new Span({ sampled: true, startTimestamp: 765, endTimestamp: 345 }); + spanRecorder.add(span); + + expect(mockPushActivity).toHaveBeenCalledTimes(0); + }); + + it('does not push or pop transaction spans', () => { + const mockPushActivity = jest.fn(); + const mockPopActivity = jest.fn(); + + const transaction = new IdleTransaction({ name: 'foo' }, hub, 1000); + const spanRecorder = new IdleTransactionSpanRecorder(mockPushActivity, mockPopActivity, transaction.spanId, 10); + + spanRecorder.add(transaction); + expect(mockPushActivity).toHaveBeenCalledTimes(0); + expect(mockPopActivity).toHaveBeenCalledTimes(0); + }); +});