From f57a02787676b57193a02b3002ed2401236a92f4 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Fri, 3 Jul 2020 15:03:21 -0400 Subject: [PATCH 1/6] feat: Adjust hub for idle transaction --- packages/tracing/src/hubextensions.ts | 57 +++++++----------------- packages/tracing/src/idletransaction.ts | 58 +++++++++++++++++++++++++ 2 files changed, 73 insertions(+), 42 deletions(-) create mode 100644 packages/tracing/src/idletransaction.ts diff --git a/packages/tracing/src/hubextensions.ts b/packages/tracing/src/hubextensions.ts index 8480ffbf1bde..96f0b0e89c29 100644 --- a/packages/tracing/src/hubextensions.ts +++ b/packages/tracing/src/hubextensions.ts @@ -4,6 +4,7 @@ import { logger } from '@sentry/utils'; import { Span } from './span'; import { Transaction } from './transaction'; +import { IdleTransaction } from './idletransaction'; /** Returns all trace headers that are currently on the top scope. */ function traceHeaders(this: Hub): { [key: string]: string } { @@ -20,13 +21,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 +44,19 @@ 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): IdleTransaction { + const transaction = new IdleTransaction(context, this, idleTimeout); + return sample(this, transaction); } /** @@ -93,9 +69,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..b57350ad1160 --- /dev/null +++ b/packages/tracing/src/idletransaction.ts @@ -0,0 +1,58 @@ +import { Hub } from '@sentry/hub'; +import { TransactionContext } from '@sentry/types'; +import { logger } from '@sentry/utils'; + +import { Transaction } from './transaction'; + +const DEFAULT_IDLE_TIMEOUT = 500; + +/** + * An IdleTransaction is a transaction that automatically finishes. + * It tracks child spans as activities to decide when to finish. + */ +export class IdleTransaction extends Transaction { + /** + * Activities store a list of active spans + * + * TODO: Can we use `Set()` here? + */ + public activities: Record = {}; + + private readonly _idleTimeout: number = DEFAULT_IDLE_TIMEOUT; + private readonly _idleHub?: Hub; + + public constructor(transactionContext: TransactionContext, hub?: Hub, idleTimeout: number = DEFAULT_IDLE_TIMEOUT) { + super(transactionContext, hub); + this._idleTimeout = idleTimeout; + this._idleHub = hub; + + if (hub) { + // There should only be one active transaction on the scope + clearActiveTransaction(hub); + + // 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}`); + hub.configureScope(scope => scope.setSpan(this)); + } + + // Start heartbeat so that transactions do not run forever. + logger.log('Starting heartbeat'); + // this._pingHeartbeat(); + } +} + +/** + * 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); + } + } + } +} From 60ae9c128da5a727781a34fea451b3f4cea19aa2 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Fri, 3 Jul 2020 15:53:24 -0400 Subject: [PATCH 2/6] feat: Add IdleTransaction class --- packages/tracing/src/hubextensions.ts | 15 +- packages/tracing/src/idletransaction.ts | 262 +++++++++++++++++- packages/tracing/test/idletransaction.test.ts | 0 3 files changed, 259 insertions(+), 18 deletions(-) create mode 100644 packages/tracing/test/idletransaction.test.ts diff --git a/packages/tracing/src/hubextensions.ts b/packages/tracing/src/hubextensions.ts index 96f0b0e89c29..313ee8c81119 100644 --- a/packages/tracing/src/hubextensions.ts +++ b/packages/tracing/src/hubextensions.ts @@ -1,10 +1,8 @@ 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 { Transaction } from './transaction'; import { IdleTransaction } from './idletransaction'; +import { Transaction } from './transaction'; /** Returns all trace headers that are currently on the top scope. */ function traceHeaders(this: Hub): { [key: string]: string } { @@ -54,8 +52,13 @@ function startTransaction(this: Hub, context: TransactionContext): Transaction { /** * Create new idle transaction. */ -export function startIdleTransaction(this: Hub, context: TransactionContext, idleTimeout?: number): IdleTransaction { - const transaction = new IdleTransaction(context, this, idleTimeout); +export function startIdleTransaction( + this: Hub, + context: TransactionContext, + idleTimeout?: number, + onScope?: boolean, +): IdleTransaction { + const transaction = new IdleTransaction(context, this, idleTimeout, onScope); return sample(this, transaction); } diff --git a/packages/tracing/src/idletransaction.ts b/packages/tracing/src/idletransaction.ts index b57350ad1160..c1347cba1a1f 100644 --- a/packages/tracing/src/idletransaction.ts +++ b/packages/tracing/src/idletransaction.ts @@ -1,32 +1,103 @@ +// tslint:disable: max-classes-per-file import { Hub } from '@sentry/hub'; import { TransactionContext } from '@sentry/types'; -import { logger } from '@sentry/utils'; +import { logger, timestampWithMs } from '@sentry/utils'; -import { Transaction } from './transaction'; +import { Span } from './span'; +import { SpanStatus } from './spanstatus'; +import { SpanRecorder, Transaction } from './transaction'; -const DEFAULT_IDLE_TIMEOUT = 500; +const DEFAULT_IDLE_TIMEOUT = 1000; /** - * An IdleTransaction is a transaction that automatically finishes. - * It tracks child spans as activities to decide when to finish. + * @inheritDoc */ -export class IdleTransaction extends Transaction { +export class IdleTransactionSpanRecorder extends SpanRecorder { + private readonly _pushActivity: (id: string) => void; + private readonly _popActivity: (id: string) => void; + public transactionSpanId: string = ''; + + public constructor( + pushActivity: (id: string) => void, + popActivity: (id: string) => void, + transactionSpanId: string = '', + maxlen?: number, + ) { + super(maxlen); + this._pushActivity = pushActivity; + this._popActivity = popActivity; + this.transactionSpanId = transactionSpanId; + } + /** - * Activities store a list of active spans - * - * TODO: Can we use `Set()` here? + * @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 + // TODO: Can we use `Set()` here? public activities: Record = {}; + // Stores reference to the timeout that calls _beat(). + private _heartbeatTimer: number = 0; + + // Track state of activities in previous heartbeat + // TODO: If we use sets, this can just be a set, then we can do + private _prevHeartbeatString: string | undefined; + + // Amount of times heartbeat has counted. Will cause transaction to finish after 3 beats. + private _heartbeatCounter: number = 1; + + // 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; + private readonly _idleHub?: Hub; - public constructor(transactionContext: TransactionContext, hub?: Hub, idleTimeout: number = DEFAULT_IDLE_TIMEOUT) { + // We should not use heartbeat if we finished a transaction + private _finished: boolean = false; + + private _finishCallback?: (transactionSpan: IdleTransaction) => void; + + public constructor( + transactionContext: TransactionContext, + hub?: Hub, + idleTimeout: number = DEFAULT_IDLE_TIMEOUT, + onScope: boolean = false, + ) { super(transactionContext, hub); + this._idleTimeout = idleTimeout; this._idleHub = hub; + this._onScope = onScope; - if (hub) { + if (hub && onScope) { // There should only be one active transaction on the scope clearActiveTransaction(hub); @@ -38,7 +109,174 @@ export class IdleTransaction extends Transaction { // Start heartbeat so that transactions do not run forever. logger.log('Starting heartbeat'); - // this._pingHeartbeat(); + this._pingHeartbeat(); + } + + /** + * 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(`ping 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; + }); + + logger.log('[Tracing] flushing IdleTransaction'); + this.finish(endTimestamp); + } else { + logger.log('[Tracing] No active IdleTransaction'); + } + } + + /** + * @inheritDoc + */ + public finish(endTimestamp?: number): string | undefined { + this._finished = true; + this.activities = {}; + // this._onScope is true if the transaction was previously on the scope. + if (this._onScope) { + clearActiveTransaction(this._idleHub); + } + return super.finish(endTimestamp); + } + + /** + * 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(() => { + if (!this._finished) { + 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) => { + if (id !== this.spanId) { + this._pushActivity(id); + } + }; + const popActivity = (id: string) => { + if (id !== this.spanId) { + this._popActivity(id); + } + }; + this.spanRecorder = new IdleTransactionSpanRecorder(pushActivity, popActivity, this.spanId, maxlen); + } + this.spanRecorder.add(this); } } diff --git a/packages/tracing/test/idletransaction.test.ts b/packages/tracing/test/idletransaction.test.ts new file mode 100644 index 000000000000..e69de29bb2d1 From bed839a3debef34c28acbe3ebaf2214383e6b609 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Fri, 3 Jul 2020 16:38:47 -0400 Subject: [PATCH 3/6] test: IdleTransaction --- packages/tracing/src/idletransaction.ts | 14 +- packages/tracing/test/idletransaction.test.ts | 287 ++++++++++++++++++ 2 files changed, 293 insertions(+), 8 deletions(-) diff --git a/packages/tracing/src/idletransaction.ts b/packages/tracing/src/idletransaction.ts index c1347cba1a1f..369ccb1c3c41 100644 --- a/packages/tracing/src/idletransaction.ts +++ b/packages/tracing/src/idletransaction.ts @@ -106,10 +106,6 @@ export class IdleTransaction extends Transaction { logger.log(`Setting idle transaction on scope. Span ID: ${this.spanId}`); hub.configureScope(scope => scope.setSpan(this)); } - - // Start heartbeat so that transactions do not run forever. - logger.log('Starting heartbeat'); - this._pingHeartbeat(); } /** @@ -152,7 +148,7 @@ export class IdleTransaction extends Transaction { * Pings the heartbeat */ private _pingHeartbeat(): void { - logger.log(`ping Heartbeat -> current counter: ${this._heartbeatCounter}`); + logger.log(`pinging Heartbeat -> current counter: ${this._heartbeatCounter}`); this._heartbeatTimer = (setTimeout(() => { this._beat(); }, 5000) as any) as number; @@ -241,9 +237,7 @@ export class IdleTransaction extends Transaction { const end = timestampWithMs() + timeout / 1000; setTimeout(() => { - if (!this._finished) { - this.finishIdleTransaction(end); - } + this.finishIdleTransaction(end); }, timeout); } } @@ -275,6 +269,10 @@ export class IdleTransaction extends Transaction { } }; 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); } diff --git a/packages/tracing/test/idletransaction.test.ts b/packages/tracing/test/idletransaction.test.ts index e69de29bb2d1..72b2418b7f29 100644 --- a/packages/tracing/test/idletransaction.test.ts +++ 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); + }); +}); From 93284fae36512cabb3c1c0f1284d5829fcce1d92 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Fri, 3 Jul 2020 16:56:45 -0400 Subject: [PATCH 4/6] ref: Some uneeded code --- packages/tracing/src/idletransaction.ts | 28 ++++++++----------------- 1 file changed, 9 insertions(+), 19 deletions(-) diff --git a/packages/tracing/src/idletransaction.ts b/packages/tracing/src/idletransaction.ts index 369ccb1c3c41..f442a52d67b4 100644 --- a/packages/tracing/src/idletransaction.ts +++ b/packages/tracing/src/idletransaction.ts @@ -188,6 +188,13 @@ export class IdleTransaction extends Transaction { 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 { @@ -195,19 +202,6 @@ export class IdleTransaction extends Transaction { } } - /** - * @inheritDoc - */ - public finish(endTimestamp?: number): string | undefined { - this._finished = true; - this.activities = {}; - // this._onScope is true if the transaction was previously on the scope. - if (this._onScope) { - clearActiveTransaction(this._idleHub); - } - return super.finish(endTimestamp); - } - /** * Start tracking a specific activity. * @param spanId The span id that represents the activity @@ -259,14 +253,10 @@ export class IdleTransaction extends Transaction { public initSpanRecorder(maxlen?: number): void { if (!this.spanRecorder) { const pushActivity = (id: string) => { - if (id !== this.spanId) { - this._pushActivity(id); - } + this._pushActivity(id); }; const popActivity = (id: string) => { - if (id !== this.spanId) { - this._popActivity(id); - } + this._popActivity(id); }; this.spanRecorder = new IdleTransactionSpanRecorder(pushActivity, popActivity, this.spanId, maxlen); From e4a54335922f831582b45ccfc1c5c6570727f3a4 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Mon, 6 Jul 2020 07:52:08 -0400 Subject: [PATCH 5/6] ref: Declare class variables in constructor --- packages/tracing/src/idletransaction.ts | 41 ++++++++----------------- 1 file changed, 12 insertions(+), 29 deletions(-) diff --git a/packages/tracing/src/idletransaction.ts b/packages/tracing/src/idletransaction.ts index f442a52d67b4..68f737719340 100644 --- a/packages/tracing/src/idletransaction.ts +++ b/packages/tracing/src/idletransaction.ts @@ -13,20 +13,13 @@ const DEFAULT_IDLE_TIMEOUT = 1000; * @inheritDoc */ export class IdleTransactionSpanRecorder extends SpanRecorder { - private readonly _pushActivity: (id: string) => void; - private readonly _popActivity: (id: string) => void; - public transactionSpanId: string = ''; - public constructor( - pushActivity: (id: string) => void, - popActivity: (id: string) => void, - transactionSpanId: string = '', + private readonly _pushActivity: (id: string) => void, + private readonly _popActivity: (id: string) => void, + public transactionSpanId: string = '', maxlen?: number, ) { super(maxlen); - this._pushActivity = pushActivity; - this._popActivity = popActivity; - this.transactionSpanId = transactionSpanId; } /** @@ -72,14 +65,6 @@ export class IdleTransaction extends Transaction { // Amount of times heartbeat has counted. Will cause transaction to finish after 3 beats. private _heartbeatCounter: number = 1; - // 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; - - private readonly _idleHub?: Hub; - // We should not use heartbeat if we finished a transaction private _finished: boolean = false; @@ -87,24 +72,22 @@ export class IdleTransaction extends Transaction { public constructor( transactionContext: TransactionContext, - hub?: Hub, - idleTimeout: number = DEFAULT_IDLE_TIMEOUT, - onScope: boolean = false, + 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, hub); - - this._idleTimeout = idleTimeout; - this._idleHub = hub; - this._onScope = onScope; + super(transactionContext, _idleHub); - if (hub && onScope) { + if (_idleHub && _onScope) { // There should only be one active transaction on the scope - clearActiveTransaction(hub); + 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}`); - hub.configureScope(scope => scope.setSpan(this)); + _idleHub.configureScope(scope => scope.setSpan(this)); } } From 4a8081b2a951dd43b7406d695207324c7c8adbce Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Mon, 6 Jul 2020 08:13:36 -0400 Subject: [PATCH 6/6] chore: Cleanup set() comments --- packages/tracing/src/idletransaction.ts | 2 -- 1 file changed, 2 deletions(-) diff --git a/packages/tracing/src/idletransaction.ts b/packages/tracing/src/idletransaction.ts index 68f737719340..5ba230f5a12d 100644 --- a/packages/tracing/src/idletransaction.ts +++ b/packages/tracing/src/idletransaction.ts @@ -52,14 +52,12 @@ export class IdleTransactionSpanRecorder extends SpanRecorder { */ export class IdleTransaction extends Transaction { // Activities store a list of active spans - // TODO: Can we use `Set()` here? public activities: Record = {}; // Stores reference to the timeout that calls _beat(). private _heartbeatTimer: number = 0; // Track state of activities in previous heartbeat - // TODO: If we use sets, this can just be a set, then we can do private _prevHeartbeatString: string | undefined; // Amount of times heartbeat has counted. Will cause transaction to finish after 3 beats.