From 2647f181801937c330d3b9433d0f323578106711 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Thu, 9 Jul 2020 11:24:56 -0400 Subject: [PATCH 01/13] feat: errors --- .../tracing/src/browser/browsertracing.ts | 4 + packages/tracing/src/browser/errors.ts | 30 +++++++ packages/tracing/src/browser/utils.ts | 22 +++++ .../test/browser/browsertracing.test.ts | 27 ++---- packages/tracing/test/browser/errors.test.ts | 88 +++++++++++++++++++ yarn.lock | 35 +------- 6 files changed, 152 insertions(+), 54 deletions(-) create mode 100644 packages/tracing/src/browser/errors.ts create mode 100644 packages/tracing/src/browser/utils.ts create mode 100644 packages/tracing/test/browser/errors.test.ts diff --git a/packages/tracing/src/browser/browsertracing.ts b/packages/tracing/src/browser/browsertracing.ts index 1b07ebac3206..1b4234ed685b 100644 --- a/packages/tracing/src/browser/browsertracing.ts +++ b/packages/tracing/src/browser/browsertracing.ts @@ -6,6 +6,7 @@ import { startIdleTransaction } from '../hubextensions'; import { DEFAULT_IDLE_TIMEOUT } from '../idletransaction'; import { Span } from '../span'; +import { registerErrorInstrumentation } from './errors'; import { defaultBeforeNavigate, defaultRoutingInstrumentation } from './router'; /** Options for Browser Tracing integration */ @@ -103,6 +104,9 @@ export class BrowserTracing implements Integration { startTransactionOnPageLoad, startTransactionOnLocationChange, ); + + // TODO: Should this be default behaviour? + registerErrorInstrumentation(); } /** Create routing idle transaction. */ diff --git a/packages/tracing/src/browser/errors.ts b/packages/tracing/src/browser/errors.ts new file mode 100644 index 000000000000..5a8a97910647 --- /dev/null +++ b/packages/tracing/src/browser/errors.ts @@ -0,0 +1,30 @@ +import { addInstrumentationHandler, logger } from '@sentry/utils'; + +import { SpanStatus } from '../spanstatus'; + +import { getActiveTransaction } from './utils'; + +/** + * Configures global error listeners + */ +export function registerErrorInstrumentation(): void { + addInstrumentationHandler({ + callback: errorCallback, + type: 'error', + }); + addInstrumentationHandler({ + callback: errorCallback, + type: 'unhandledrejection', + }); +} + +/** + * If an error or unhandled promise occurs, we mark the active transaction as failed + */ +function errorCallback(): void { + const activeTransaction = getActiveTransaction(); + if (activeTransaction) { + logger.log(`[Tracing] Transaction: ${SpanStatus.InternalError} -> Global error occured`); + activeTransaction.setStatus(SpanStatus.InternalError); + } +} diff --git a/packages/tracing/src/browser/utils.ts b/packages/tracing/src/browser/utils.ts new file mode 100644 index 000000000000..a2686e2f7c0a --- /dev/null +++ b/packages/tracing/src/browser/utils.ts @@ -0,0 +1,22 @@ +import { getCurrentHub, Hub } from '@sentry/hub'; +import { Transaction } from '@sentry/types'; + +/** Grabs active transaction off scope */ +export function getActiveTransaction(hub: Hub = getCurrentHub()): T | undefined { + if (hub) { + const scope = hub.getScope(); + if (scope) { + return scope.getTransaction() as T | undefined; + } + } + + return undefined; +} + +/** + * Converts from milliseconds to seconds + * @param time time in ms + */ +export function msToSec(time: number): number { + return time / 1000; +} diff --git a/packages/tracing/test/browser/browsertracing.test.ts b/packages/tracing/test/browser/browsertracing.test.ts index effc6dcf8b5e..ff2a19411315 100644 --- a/packages/tracing/test/browser/browsertracing.test.ts +++ b/packages/tracing/test/browser/browsertracing.test.ts @@ -1,10 +1,11 @@ import { BrowserClient } from '@sentry/browser'; -import { Hub } from '@sentry/hub'; +import { Hub, makeMain } from '@sentry/hub'; // tslint:disable-next-line: no-implicit-dependencies import { JSDOM } from 'jsdom'; import { BrowserTracing, BrowserTracingOptions, getMetaContent } from '../../src/browser/browsertracing'; import { defaultRoutingInstrumentation } from '../../src/browser/router'; +import { getActiveTransaction } from '../../src/browser/utils'; import { DEFAULT_IDLE_TIMEOUT, IdleTransaction } from '../../src/idletransaction'; let mockChangeHistory: ({ to, from }: { to: string; from?: string }) => void = () => undefined; @@ -12,8 +13,10 @@ jest.mock('@sentry/utils', () => { const actual = jest.requireActual('@sentry/utils'); return { ...actual, - addInstrumentationHandler: ({ callback }: any): void => { - mockChangeHistory = callback; + addInstrumentationHandler: ({ callback, type }: any): void => { + if (type === 'history') { + mockChangeHistory = callback; + } }, }; }); @@ -33,16 +36,10 @@ describe('BrowserTracing', () => { beforeEach(() => { jest.useFakeTimers(); hub = new Hub(new BrowserClient({ tracesSampleRate: 1 })); + makeMain(hub); document.head.innerHTML = ''; }); - afterEach(() => { - const transaction = getActiveTransaction(hub); - if (transaction) { - transaction.finish(); - } - }); - // tslint:disable-next-line: completed-docs function createBrowserTracing(setup?: boolean, _options?: Partial): BrowserTracing { const inst = new BrowserTracing(_options); @@ -240,13 +237,3 @@ describe('getMeta', () => { expect(meta).toBe(null); }); }); - -/** Get active transaction from scope */ -function getActiveTransaction(hub: Hub): IdleTransaction | undefined { - const scope = hub.getScope(); - if (scope) { - return scope.getTransaction() as IdleTransaction; - } - - return undefined; -} diff --git a/packages/tracing/test/browser/errors.test.ts b/packages/tracing/test/browser/errors.test.ts new file mode 100644 index 000000000000..2a4b6a2a44cd --- /dev/null +++ b/packages/tracing/test/browser/errors.test.ts @@ -0,0 +1,88 @@ +import { BrowserClient } from '@sentry/browser'; +import { Hub, makeMain } from '@sentry/hub'; + +import { SpanStatus } from '../../src'; +import { registerErrorInstrumentation } from '../../src/browser/errors'; +import { addExtensionMethods } from '../../src/hubextensions'; + +const mockAddInstrumentationHandler = jest.fn(); +let mockErrorCallback: () => void = () => undefined; +let mockUnhandledRejectionCallback: () => void = () => undefined; +jest.mock('@sentry/utils', () => { + const actual = jest.requireActual('@sentry/utils'); + return { + ...actual, + addInstrumentationHandler: ({ callback, type }: any) => { + if (type === 'error') { + mockErrorCallback = callback; + } + if (type === 'unhandledrejection') { + mockUnhandledRejectionCallback = callback; + } + return mockAddInstrumentationHandler({ callback, type }); + }, + }; +}); + +beforeAll(() => { + addExtensionMethods(); +}); + +describe('registerErrorHandlers()', () => { + let hub: Hub; + beforeEach(() => { + mockAddInstrumentationHandler.mockClear(); + hub = new Hub(new BrowserClient({ tracesSampleRate: 1 })); + makeMain(hub); + }); + + afterEach(() => { + hub.configureScope(scope => scope.setSpan(undefined)); + }); + + it('registers error instrumentation', () => { + registerErrorInstrumentation(); + expect(mockAddInstrumentationHandler).toHaveBeenCalledTimes(2); + expect(mockAddInstrumentationHandler).toHaveBeenNthCalledWith(1, { callback: expect.any(Function), type: 'error' }); + expect(mockAddInstrumentationHandler).toHaveBeenNthCalledWith(2, { + callback: expect.any(Function), + type: 'unhandledrejection', + }); + }); + + it('does not set status if transaction is not on scope', () => { + registerErrorInstrumentation(); + const transaction = hub.startTransaction({ name: 'test' }); + expect(transaction.status).toBe(undefined); + + mockErrorCallback(); + expect(transaction.status).toBe(undefined); + + mockUnhandledRejectionCallback(); + expect(transaction.status).toBe(undefined); + transaction.finish(); + }); + + it('sets status for transaction on scope on error', () => { + registerErrorInstrumentation(); + const transaction = hub.startTransaction({ name: 'test' }); + hub.configureScope(scope => scope.setSpan(transaction)); + + mockErrorCallback(); + expect(transaction.status).toBe(SpanStatus.InternalError); + + // mockUnhandledRejectionCallback(); + // expect(transaction.status).toBe(undefined); + transaction.finish(); + }); + + it('sets status for transaction on scope on unhandledrejection', () => { + registerErrorInstrumentation(); + const transaction = hub.startTransaction({ name: 'test' }); + hub.configureScope(scope => scope.setSpan(transaction)); + + mockUnhandledRejectionCallback(); + expect(transaction.status).toBe(SpanStatus.InternalError); + transaction.finish(); + }); +}); diff --git a/yarn.lock b/yarn.lock index e5e78067be6f..9ba9790cf98d 100644 --- a/yarn.lock +++ b/yarn.lock @@ -1847,32 +1847,11 @@ after@0.8.2: version "0.8.2" resolved "https://registry.yarnpkg.com/after/-/after-0.8.2.tgz#fedb394f9f0e02aa9768e702bda23b505fae7e1f" -agent-base@4, agent-base@^4.3.0: - version "4.3.0" - resolved "https://registry.yarnpkg.com/agent-base/-/agent-base-4.3.0.tgz#8165f01c436009bccad0b1d122f05ed770efc6ee" - integrity sha512-salcGninV0nPrwpGNn4VTXBb1SOuXQBiqbrNXoeizJsHrsL6ERFM2Ne3JUSBWRE6aeNJI2ROP/WEEIDUiDe3cg== - dependencies: - es6-promisify "^5.0.0" - -agent-base@5: +agent-base@4, agent-base@5, agent-base@6, agent-base@^4.3.0, agent-base@~4.2.0: version "5.1.1" resolved "https://registry.yarnpkg.com/agent-base/-/agent-base-5.1.1.tgz#e8fb3f242959db44d63be665db7a8e739537a32c" integrity sha512-TMeqbNl2fMW0nMjTEPOwe3J/PRFP4vqeoNuQMG0HlMrtm5QxKqdvAkZ1pRBQ/ulIyDD5Yq0nJ7YbdD8ey0TO3g== -agent-base@6: - version "6.0.1" - resolved "https://registry.yarnpkg.com/agent-base/-/agent-base-6.0.1.tgz#808007e4e5867decb0ab6ab2f928fbdb5a596db4" - integrity sha512-01q25QQDwLSsyfhrKbn8yuur+JNw0H+0Y4JiGIKd3z9aYk/w/2kxD/Upc+t2ZBBSUNff50VjPsSW2YxM8QYKVg== - dependencies: - debug "4" - -agent-base@~4.2.0: - version "4.2.1" - resolved "https://registry.yarnpkg.com/agent-base/-/agent-base-4.2.1.tgz#d89e5999f797875674c07d87f260fc41e83e8ca9" - integrity sha512-JVwXMr9nHYTUXsBFKUqhJwvlcYU/blreOEUkhNR2eXZIvwd+c+o5V4MgDPKWnMS/56awN3TRzIP+KoPn+roQtg== - dependencies: - es6-promisify "^5.0.0" - agentkeepalive@^3.4.1: version "3.5.2" resolved "https://registry.yarnpkg.com/agentkeepalive/-/agentkeepalive-3.5.2.tgz#a113924dd3fa24a0bc3b78108c450c2abee00f67" @@ -4633,18 +4612,6 @@ es-to-primitive@^1.1.1, es-to-primitive@^1.2.0: is-date-object "^1.0.1" is-symbol "^1.0.2" -es6-promise@^4.0.3: - version "4.2.8" - resolved "https://registry.yarnpkg.com/es6-promise/-/es6-promise-4.2.8.tgz#4eb21594c972bc40553d276e510539143db53e0a" - integrity sha512-HJDGx5daxeIvxdBxvG2cb9g4tEvwIk3i8+nhX0yGrYmZUzbkdg8QbDevheDB8gd0//uPj4c1EQua8Q+MViT0/w== - -es6-promisify@^5.0.0: - version "5.0.0" - resolved "https://registry.yarnpkg.com/es6-promisify/-/es6-promisify-5.0.0.tgz#5109d62f3e56ea967c4b63505aef08291c8a5203" - integrity sha1-UQnWLz5W6pZ8S2NQWu8IKRyKUgM= - dependencies: - es6-promise "^4.0.3" - escape-html@~1.0.3: version "1.0.3" resolved "https://registry.yarnpkg.com/escape-html/-/escape-html-1.0.3.tgz#0258eae4d3d0c0974de1c169188ef0051d1d1988" From 64d1efcd1aa96392f229cb7c77124fd78cd6f2cc Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Thu, 9 Jul 2020 12:36:50 -0400 Subject: [PATCH 02/13] feat: Max Transaction Duration --- .../tracing/src/browser/browsertracing.ts | 35 +++- packages/tracing/src/browser/utils.ts | 8 + packages/tracing/src/idletransaction.ts | 4 +- .../test/browser/browsertracing.test.ts | 166 ++++++++++++------ 4 files changed, 155 insertions(+), 58 deletions(-) diff --git a/packages/tracing/src/browser/browsertracing.ts b/packages/tracing/src/browser/browsertracing.ts index 1b4234ed685b..a222f9fe3947 100644 --- a/packages/tracing/src/browser/browsertracing.ts +++ b/packages/tracing/src/browser/browsertracing.ts @@ -3,11 +3,15 @@ import { EventProcessor, Integration, Transaction as TransactionType, Transactio import { logger } from '@sentry/utils'; import { startIdleTransaction } from '../hubextensions'; -import { DEFAULT_IDLE_TIMEOUT } from '../idletransaction'; +import { BeforeFinishCallback, DEFAULT_IDLE_TIMEOUT, IdleTransaction } from '../idletransaction'; import { Span } from '../span'; +import { SpanStatus } from '../spanstatus'; import { registerErrorInstrumentation } from './errors'; import { defaultBeforeNavigate, defaultRoutingInstrumentation } from './router'; +import { secToMs } from './utils'; + +export const DEFAULT_MAX_TRANSACTION_DURATION__SECONDS = 600; /** Options for Browser Tracing integration */ export interface BrowserTracingOptions { @@ -51,6 +55,15 @@ export interface BrowserTracingOptions { startTransactionOnPageLoad?: boolean, startTransactionOnLocationChange?: boolean, ): void; + + /** + * 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; } /** @@ -70,6 +83,7 @@ export class BrowserTracing implements Integration { public options: BrowserTracingOptions = { beforeNavigate: defaultBeforeNavigate, idleTimeout: DEFAULT_IDLE_TIMEOUT, + maxTransactionDuration: DEFAULT_MAX_TRANSACTION_DURATION__SECONDS, routingInstrumentation: defaultRoutingInstrumentation, startTransactionOnLocationChange: true, startTransactionOnPageLoad: true, @@ -116,7 +130,7 @@ export class BrowserTracing implements Integration { return undefined; } - const { beforeNavigate, idleTimeout } = this.options; + const { beforeNavigate, idleTimeout, maxTransactionDuration } = this.options; // if beforeNavigate returns undefined, we should not start a transaction. const ctx = beforeNavigate({ @@ -131,7 +145,10 @@ export class BrowserTracing implements Integration { const hub = this._getCurrentHub(); logger.log(`[Tracing] starting ${ctx.op} idleTransaction on scope with context:`, ctx); - return startIdleTransaction(hub, ctx, idleTimeout, true) as TransactionType; + const idleTransaction = startIdleTransaction(hub, ctx, idleTimeout, true); + idleTransaction.registerBeforeFinishCallback(adjustTransactionDuration(secToMs(maxTransactionDuration))); + + return idleTransaction as TransactionType; } } @@ -159,3 +176,15 @@ export function getMetaContent(metaName: string): string | null { const el = document.querySelector(`meta[name=${metaName}]`); return el ? el.getAttribute('content') : null; } + +/** Adjusts transaction value based on max transaction duration */ +function adjustTransactionDuration(maxDuration: number): BeforeFinishCallback { + return (transaction: IdleTransaction, endTimestamp: number): void => { + const diff = endTimestamp - transaction.startTimestamp; + const isOutdatedTransaction = endTimestamp && (diff > maxDuration || diff < 0); + if (isOutdatedTransaction) { + transaction.setStatus(SpanStatus.Cancelled); + transaction.setTag('maxTransactionDurationExceeded', 'true'); + } + }; +} diff --git a/packages/tracing/src/browser/utils.ts b/packages/tracing/src/browser/utils.ts index a2686e2f7c0a..bda91de29c82 100644 --- a/packages/tracing/src/browser/utils.ts +++ b/packages/tracing/src/browser/utils.ts @@ -20,3 +20,11 @@ export function getActiveTransaction(hub: Hub = getCurren export function msToSec(time: number): number { return time / 1000; } + +/** + * Converts from seconds to milliseconds + * @param time time in seconds + */ +export function secToMs(time: number): number { + return time * 1000; +} diff --git a/packages/tracing/src/idletransaction.ts b/packages/tracing/src/idletransaction.ts index 2b24549ddefe..4fe761d3d0d6 100644 --- a/packages/tracing/src/idletransaction.ts +++ b/packages/tracing/src/idletransaction.ts @@ -45,7 +45,7 @@ export class IdleTransactionSpanRecorder extends SpanRecorder { } } -export type BeforeFinishCallback = (transactionSpan: IdleTransaction) => void; +export type BeforeFinishCallback = (transactionSpan: IdleTransaction, endTimestamp: number) => void; /** * An IdleTransaction is a transaction that automatically finishes. It does this by tracking child spans as activities. @@ -143,7 +143,7 @@ export class IdleTransaction extends Transaction { logger.log('[Tracing] finishing IdleTransaction', new Date(endTimestamp * 1000).toISOString(), this.op); for (const callback of this._beforeFinishCallbacks) { - callback(this); + callback(this, endTimestamp); } this.spanRecorder.spans = this.spanRecorder.spans.filter((span: Span) => { diff --git a/packages/tracing/test/browser/browsertracing.test.ts b/packages/tracing/test/browser/browsertracing.test.ts index ff2a19411315..323e39db77bd 100644 --- a/packages/tracing/test/browser/browsertracing.test.ts +++ b/packages/tracing/test/browser/browsertracing.test.ts @@ -3,9 +3,15 @@ import { Hub, makeMain } from '@sentry/hub'; // tslint:disable-next-line: no-implicit-dependencies import { JSDOM } from 'jsdom'; -import { BrowserTracing, BrowserTracingOptions, getMetaContent } from '../../src/browser/browsertracing'; +import { SpanStatus } from '../../src'; +import { + BrowserTracing, + BrowserTracingOptions, + DEFAULT_MAX_TRANSACTION_DURATION__SECONDS, + getMetaContent, +} from '../../src/browser/browsertracing'; import { defaultRoutingInstrumentation } from '../../src/browser/router'; -import { getActiveTransaction } from '../../src/browser/utils'; +import { getActiveTransaction, secToMs } from '../../src/browser/utils'; import { DEFAULT_IDLE_TIMEOUT, IdleTransaction } from '../../src/idletransaction'; let mockChangeHistory: ({ to, from }: { to: string; from?: string }) => void = () => undefined; @@ -40,6 +46,14 @@ describe('BrowserTracing', () => { document.head.innerHTML = ''; }); + afterEach(() => { + const activeTransaction = getActiveTransaction(); + if (activeTransaction) { + // Should unset off of scope. + activeTransaction.finish(); + } + }); + // tslint:disable-next-line: completed-docs function createBrowserTracing(setup?: boolean, _options?: Partial): BrowserTracing { const inst = new BrowserTracing(_options); @@ -59,12 +73,18 @@ describe('BrowserTracing', () => { expect(browserTracing.options).toEqual({ beforeNavigate: expect.any(Function), idleTimeout: DEFAULT_IDLE_TIMEOUT, + maxTransactionDuration: DEFAULT_MAX_TRANSACTION_DURATION__SECONDS, routingInstrumentation: defaultRoutingInstrumentation, startTransactionOnLocationChange: true, startTransactionOnPageLoad: true, }); }); + /** + * All of these tests under `describe('route transaction')` are tested with + * `browserTracing.options = { routingInstrumentation: customRoutingInstrumentation }`, + * so that we can show this functionality works independent of the default routing integration. + */ describe('route transaction', () => { const customRoutingInstrumentation = (startTransaction: Function) => { startTransaction({ name: 'a/path', op: 'pageload' }); @@ -81,44 +101,46 @@ describe('BrowserTracing', () => { expect(transaction.op).toBe('pageload'); }); - it('calls beforeNavigate on transaction creation', () => { - const mockBeforeNavigation = jest.fn().mockReturnValue({ name: 'here/is/my/path' }); - createBrowserTracing(true, { - beforeNavigate: mockBeforeNavigation, - routingInstrumentation: customRoutingInstrumentation, + describe('beforeNavigate', () => { + it('is called on transaction creation', () => { + const mockBeforeNavigation = jest.fn().mockReturnValue({ name: 'here/is/my/path' }); + createBrowserTracing(true, { + beforeNavigate: mockBeforeNavigation, + routingInstrumentation: customRoutingInstrumentation, + }); + const transaction = getActiveTransaction(hub) as IdleTransaction; + expect(transaction).toBeDefined(); + + expect(mockBeforeNavigation).toHaveBeenCalledTimes(1); }); - const transaction = getActiveTransaction(hub) as IdleTransaction; - expect(transaction).toBeDefined(); - expect(mockBeforeNavigation).toHaveBeenCalledTimes(1); - }); + it('does not create a transaction if it returns undefined', () => { + const mockBeforeNavigation = jest.fn().mockReturnValue(undefined); + createBrowserTracing(true, { + beforeNavigate: mockBeforeNavigation, + routingInstrumentation: customRoutingInstrumentation, + }); + const transaction = getActiveTransaction(hub) as IdleTransaction; + expect(transaction).not.toBeDefined(); - it('is not created if beforeNavigate returns undefined', () => { - const mockBeforeNavigation = jest.fn().mockReturnValue(undefined); - createBrowserTracing(true, { - beforeNavigate: mockBeforeNavigation, - routingInstrumentation: customRoutingInstrumentation, + expect(mockBeforeNavigation).toHaveBeenCalledTimes(1); }); - const transaction = getActiveTransaction(hub) as IdleTransaction; - expect(transaction).not.toBeDefined(); - expect(mockBeforeNavigation).toHaveBeenCalledTimes(1); - }); + it('can be a custom value', () => { + const mockBeforeNavigation = jest.fn(ctx => ({ + ...ctx, + op: 'something-else', + })); + createBrowserTracing(true, { + beforeNavigate: mockBeforeNavigation, + routingInstrumentation: customRoutingInstrumentation, + }); + const transaction = getActiveTransaction(hub) as IdleTransaction; + expect(transaction).toBeDefined(); + expect(transaction.op).toBe('something-else'); - it('can use a custom beforeNavigate', () => { - const mockBeforeNavigation = jest.fn(ctx => ({ - ...ctx, - op: 'something-else', - })); - createBrowserTracing(true, { - beforeNavigate: mockBeforeNavigation, - routingInstrumentation: customRoutingInstrumentation, + expect(mockBeforeNavigation).toHaveBeenCalledTimes(1); }); - const transaction = getActiveTransaction(hub) as IdleTransaction; - expect(transaction).toBeDefined(); - expect(transaction.op).toBe('something-else'); - - expect(mockBeforeNavigation).toHaveBeenCalledTimes(1); }); it('sets transaction context from sentry-trace header', () => { @@ -133,32 +155,70 @@ describe('BrowserTracing', () => { expect(transaction.sampled).toBe(true); }); - it('is created with a default idleTimeout', () => { - createBrowserTracing(true, { routingInstrumentation: customRoutingInstrumentation }); - const mockFinish = jest.fn(); - const transaction = getActiveTransaction(hub) as IdleTransaction; - transaction.finish = mockFinish; + describe('idleTimeout', () => { + it('is created by default', () => { + createBrowserTracing(true, { routingInstrumentation: customRoutingInstrumentation }); + const mockFinish = jest.fn(); + const transaction = getActiveTransaction(hub) as IdleTransaction; + transaction.finish = mockFinish; - const span = transaction.startChild(); // activities = 1 - span.finish(); // activities = 0 + const span = transaction.startChild(); // activities = 1 + span.finish(); // activities = 0 - expect(mockFinish).toHaveBeenCalledTimes(0); - jest.advanceTimersByTime(DEFAULT_IDLE_TIMEOUT); - expect(mockFinish).toHaveBeenCalledTimes(1); + expect(mockFinish).toHaveBeenCalledTimes(0); + jest.advanceTimersByTime(DEFAULT_IDLE_TIMEOUT); + expect(mockFinish).toHaveBeenCalledTimes(1); + }); + + it('can be a custom value', () => { + createBrowserTracing(true, { idleTimeout: 2000, routingInstrumentation: customRoutingInstrumentation }); + const mockFinish = jest.fn(); + const transaction = getActiveTransaction(hub) as IdleTransaction; + transaction.finish = mockFinish; + + const span = transaction.startChild(); // activities = 1 + span.finish(); // activities = 0 + + expect(mockFinish).toHaveBeenCalledTimes(0); + jest.advanceTimersByTime(2000); + expect(mockFinish).toHaveBeenCalledTimes(1); + }); }); - it('can be created with a custom idleTimeout', () => { - createBrowserTracing(true, { idleTimeout: 2000, routingInstrumentation: customRoutingInstrumentation }); - const mockFinish = jest.fn(); - const transaction = getActiveTransaction(hub) as IdleTransaction; - transaction.finish = mockFinish; + describe('maxTransactionDuration', () => { + it('cancels a transaction if exceeded', () => { + createBrowserTracing(true, { routingInstrumentation: customRoutingInstrumentation }); + const transaction = getActiveTransaction(hub) as IdleTransaction; + transaction.finish(transaction.startTimestamp + secToMs(DEFAULT_MAX_TRANSACTION_DURATION__SECONDS) + 1); + + expect(transaction.status).toBe(SpanStatus.Cancelled); + expect(transaction.tags.maxTransactionDurationExceeded).toBeDefined(); + }); - const span = transaction.startChild(); // activities = 1 - span.finish(); // activities = 0 + it('does not cancel a transaction if not exceeded', () => { + createBrowserTracing(true, { routingInstrumentation: customRoutingInstrumentation }); + const transaction = getActiveTransaction(hub) as IdleTransaction; + transaction.finish(transaction.startTimestamp + secToMs(DEFAULT_MAX_TRANSACTION_DURATION__SECONDS)); - expect(mockFinish).toHaveBeenCalledTimes(0); - jest.advanceTimersByTime(2000); - expect(mockFinish).toHaveBeenCalledTimes(1); + 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: customRoutingInstrumentation, + }); + const transaction = getActiveTransaction(hub) as IdleTransaction; + + transaction.finish(transaction.startTimestamp + secToMs(customMaxTransactionDuration)); + + expect(transaction.status).toBe(undefined); + expect(transaction.tags.maxTransactionDurationExceeded).not.toBeDefined(); + }); }); }); From 644fb7827c68973f683c897aad112e910c2d9a5f Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Thu, 9 Jul 2020 13:10:34 -0400 Subject: [PATCH 03/13] feat: Background tab detection --- packages/tracing/src/browser/backgroundtab.ts | 28 +++++++++ .../tracing/src/browser/browsertracing.ts | 23 +++++++- .../test/browser/backgroundtab.test.ts | 57 +++++++++++++++++++ 3 files changed, 107 insertions(+), 1 deletion(-) create mode 100644 packages/tracing/src/browser/backgroundtab.ts create mode 100644 packages/tracing/test/browser/backgroundtab.test.ts diff --git a/packages/tracing/src/browser/backgroundtab.ts b/packages/tracing/src/browser/backgroundtab.ts new file mode 100644 index 000000000000..d92ec1614fd1 --- /dev/null +++ b/packages/tracing/src/browser/backgroundtab.ts @@ -0,0 +1,28 @@ +import { getGlobalObject, logger } from '@sentry/utils'; + +import { IdleTransaction } from '../idletransaction'; +import { SpanStatus } from '../spanstatus'; + +import { getActiveTransaction } from './utils'; + +const global = getGlobalObject(); + +/** + * Add a listener that cancels and finishes a transaction when the global + * document is hidden. + */ +export function registerBackgroundTabDetection(): void { + if (global && global.document) { + global.document.addEventListener('visibilitychange', () => { + const activeTransaction = getActiveTransaction() as IdleTransaction; + if (global.document.hidden && activeTransaction) { + logger.log(`[Tracing] Transaction: ${SpanStatus.Cancelled} -> since tab moved to the background`); + activeTransaction.setStatus(SpanStatus.Cancelled); + activeTransaction.setTag('visibilitychange', 'document.hidden'); + activeTransaction.finish(); + } + }); + } else { + logger.warn('[Tracing] Could not set up background tab detection due to lack of global document'); + } +} diff --git a/packages/tracing/src/browser/browsertracing.ts b/packages/tracing/src/browser/browsertracing.ts index a222f9fe3947..002362185003 100644 --- a/packages/tracing/src/browser/browsertracing.ts +++ b/packages/tracing/src/browser/browsertracing.ts @@ -7,6 +7,7 @@ import { BeforeFinishCallback, DEFAULT_IDLE_TIMEOUT, IdleTransaction } from '../ import { Span } from '../span'; import { SpanStatus } from '../spanstatus'; +import { registerBackgroundTabDetection } from './backgroundtab'; import { registerErrorInstrumentation } from './errors'; import { defaultBeforeNavigate, defaultRoutingInstrumentation } from './router'; import { secToMs } from './utils'; @@ -64,6 +65,15 @@ export interface BrowserTracingOptions { * 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. Background transaction can mess up your + * statistics in non deterministic ways that's why we by default recommend leaving this opition enabled. + * + * Default: true + */ + markBackgroundTransactions: boolean; } /** @@ -83,6 +93,7 @@ export class BrowserTracing implements Integration { public options: BrowserTracingOptions = { beforeNavigate: defaultBeforeNavigate, idleTimeout: DEFAULT_IDLE_TIMEOUT, + markBackgroundTransactions: true, maxTransactionDuration: DEFAULT_MAX_TRANSACTION_DURATION__SECONDS, routingInstrumentation: defaultRoutingInstrumentation, startTransactionOnLocationChange: true, @@ -111,7 +122,12 @@ export class BrowserTracing implements Integration { public setupOnce(_: (callback: EventProcessor) => void, getCurrentHub: () => Hub): void { this._getCurrentHub = getCurrentHub; - const { routingInstrumentation, startTransactionOnLocationChange, startTransactionOnPageLoad } = this.options; + const { + routingInstrumentation, + startTransactionOnLocationChange, + startTransactionOnPageLoad, + markBackgroundTransactions, + } = this.options; routingInstrumentation( (context: TransactionContext) => this._createRouteTransaction(context), @@ -121,6 +137,11 @@ export class BrowserTracing implements Integration { // TODO: Should this be default behaviour? registerErrorInstrumentation(); + + // TODO: Should this be default behaviour? + if (markBackgroundTransactions) { + registerBackgroundTabDetection(); + } } /** Create routing idle transaction. */ diff --git a/packages/tracing/test/browser/backgroundtab.test.ts b/packages/tracing/test/browser/backgroundtab.test.ts new file mode 100644 index 000000000000..a85a93434bc2 --- /dev/null +++ b/packages/tracing/test/browser/backgroundtab.test.ts @@ -0,0 +1,57 @@ +import { BrowserClient } from '@sentry/browser'; +import { Hub, makeMain } from '@sentry/hub'; +// tslint:disable-next-line: no-implicit-dependencies +import { JSDOM } from 'jsdom'; + +import { SpanStatus } from '../../src'; +import { registerBackgroundTabDetection } from '../../src/browser/backgroundtab'; + +describe('registerBackgroundTabDetection', () => { + let events: Record = {}; + let hub: Hub; + beforeEach(() => { + const dom = new JSDOM(); + // @ts-ignore + global.document = dom.window.document; + + hub = new Hub(new BrowserClient({ tracesSampleRate: 1 })); + makeMain(hub); + + // @ts-ignore + global.document.addEventListener = jest.fn((event, callback) => { + events[event] = callback; + }); + }); + + afterEach(() => { + events = {}; + hub.configureScope(scope => scope.setSpan(undefined)); + }); + + it('does not creates an event listener if global document is undefined', () => { + // @ts-ignore; + global.document = undefined; + registerBackgroundTabDetection(); + expect(events).toMatchObject({}); + }); + + it('creates an event listener', () => { + registerBackgroundTabDetection(); + expect(events).toMatchObject({ visibilitychange: expect.any(Function) }); + }); + + it('finishes a transaction on visibility change', () => { + registerBackgroundTabDetection(); + const transaction = hub.startTransaction({ name: 'test' }); + hub.configureScope(scope => scope.setSpan(transaction)); + + // Simulate document visibility hidden event + // @ts-ignore + global.document.hidden = true; + events.visibilitychange(); + + expect(transaction.status).toBe(SpanStatus.Cancelled); + expect(transaction.tags.visibilitychange).toBe('document.hidden'); + expect(transaction.endTimestamp).toBeDefined(); + }); +}); From 51ec8569c572b8f1028ed27f012f0632dda68027 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Thu, 9 Jul 2020 14:17:43 -0400 Subject: [PATCH 04/13] feat: Request instrumentation --- .../tracing/src/browser/browsertracing.ts | 31 ++- packages/tracing/src/browser/request.ts | 235 ++++++++++++++++++ 2 files changed, 263 insertions(+), 3 deletions(-) create mode 100644 packages/tracing/src/browser/request.ts diff --git a/packages/tracing/src/browser/browsertracing.ts b/packages/tracing/src/browser/browsertracing.ts index 002362185003..40edb14af638 100644 --- a/packages/tracing/src/browser/browsertracing.ts +++ b/packages/tracing/src/browser/browsertracing.ts @@ -9,13 +9,18 @@ import { SpanStatus } from '../spanstatus'; import { registerBackgroundTabDetection } from './backgroundtab'; import { registerErrorInstrumentation } from './errors'; +import { + defaultRequestInstrumentionOptions, + registerRequestInstrumentation, + RequestInstrumentationOptions, +} from './request'; import { defaultBeforeNavigate, defaultRoutingInstrumentation } from './router'; import { secToMs } from './utils'; export const DEFAULT_MAX_TRANSACTION_DURATION__SECONDS = 600; /** Options for Browser Tracing integration */ -export interface BrowserTracingOptions { +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. @@ -98,6 +103,7 @@ export class BrowserTracing implements Integration { routingInstrumentation: defaultRoutingInstrumentation, startTransactionOnLocationChange: true, startTransactionOnPageLoad: true, + ...defaultRequestInstrumentionOptions, }; /** @@ -107,9 +113,14 @@ export class BrowserTracing implements Integration { private _getCurrentHub?: () => Hub; - // navigationTransactionInvoker() -> Uses history API NavigationTransaction[] + private readonly _emitOptionsWarning: boolean = false; public constructor(_options?: Partial) { + // NOTE: Logger doesn't work in contructors, as it's initialized after integrations instances + if (!_options || !Array.isArray(_options.tracingOrigins) || _options.tracingOrigins.length === 0) { + this._emitOptionsWarning = true; + } + this.options = { ...this.options, ..._options, @@ -122,11 +133,24 @@ export class BrowserTracing implements Integration { public setupOnce(_: (callback: EventProcessor) => void, getCurrentHub: () => Hub): void { this._getCurrentHub = getCurrentHub; + if (this._emitOptionsWarning) { + logger.warn( + '[Tracing] You need to define `tracingOrigins` in the options. Set an array of urls or patterns to trace.', + ); + logger.warn( + `[Tracing] We added a reasonable default for you: ${defaultRequestInstrumentionOptions.tracingOrigins}`, + ); + } + const { routingInstrumentation, startTransactionOnLocationChange, startTransactionOnPageLoad, markBackgroundTransactions, + traceFetch, + traceXHR, + tracingOrigins, + shouldCreateSpanForRequest, } = this.options; routingInstrumentation( @@ -138,10 +162,11 @@ export class BrowserTracing implements Integration { // TODO: Should this be default behaviour? registerErrorInstrumentation(); - // TODO: Should this be default behaviour? if (markBackgroundTransactions) { registerBackgroundTabDetection(); } + + registerRequestInstrumentation({ traceFetch, traceXHR, tracingOrigins, shouldCreateSpanForRequest }); } /** Create routing idle transaction. */ diff --git a/packages/tracing/src/browser/request.ts b/packages/tracing/src/browser/request.ts new file mode 100644 index 000000000000..d4499b70b11d --- /dev/null +++ b/packages/tracing/src/browser/request.ts @@ -0,0 +1,235 @@ +import { addInstrumentationHandler, isInstanceOf, isMatchingPattern } from '@sentry/utils'; + +import { Span } from '../span'; + +import { getActiveTransaction } from './utils'; + +export const DEFAULT_TRACING_ORIGINS = ['localhost', /^\//]; + +/** Options for Request Instrumentation */ +export interface RequestInstrumentationOptions { + /** + * List of strings / regex where the integration should create Spans out of. Additionally this will be used + * to define which outgoing requests the `sentry-trace` header will be attached to. + * + * Default: ['localhost', /^\//] {@see DEFAULT_TRACING_ORIGINS} + */ + tracingOrigins: Array; + + /** + * Flag to disable patching all together for fetch requests. + * + * Default: true + */ + traceFetch: boolean; + + /** + * Flag to disable patching all together for xhr requests. + * + * Default: true + */ + traceXHR: boolean; + + /** + * This function will be called before creating a span for a request with the given url. + * Return false if you don't want a span for the given url. + * + * By default it uses the `tracingOrigins` options as a url match. + */ + shouldCreateSpanForRequest?(url: string): boolean; +} + +/** Data returned from fetch callback */ +interface FetchData { + args: any[]; + fetchData: { + method: string; + url: string; + // span_id + __span?: string; + }; + startTimestamp: number; + endTimestamp?: number; +} + +/** Data returned from XHR request */ +interface XHRData { + xhr?: { + __sentry_xhr__?: { + method: string; + url: string; + status_code: number; + data: Record; + }; + __sentry_xhr_span_id__?: string; + __sentry_own_request__: boolean; + setRequestHeader?: Function; + }; + startTimestamp: number; + endTimestamp?: number; +} + +export const defaultRequestInstrumentionOptions: RequestInstrumentationOptions = { + traceFetch: true, + traceXHR: true, + tracingOrigins: DEFAULT_TRACING_ORIGINS, +}; + +/** Registers span creators for xhr and fetch requests */ +export function registerRequestInstrumentation(_options: Partial): void { + const { traceFetch, traceXHR, tracingOrigins, shouldCreateSpanForRequest } = { + ...defaultRequestInstrumentionOptions, + ..._options, + }; + + // We should cache url -> decision so that we don't have to compute + // regexp everytime we create a request. + const urlMap: Record = {}; + + const shouldCreateSpan = shouldCreateSpanForRequest + ? shouldCreateSpanForRequest + : (url: string) => { + if (urlMap[url]) { + return urlMap[url]; + } + const origins = tracingOrigins; + const decision = + origins.some((origin: string | RegExp) => isMatchingPattern(url, origin)) && + !isMatchingPattern(url, 'sentry_key'); + urlMap[url] = decision; + return urlMap[url]; + }; + + const spans: Record = {}; + + if (traceFetch) { + addInstrumentationHandler({ + callback: (handlerData: FetchData) => { + fetchCallback(handlerData, shouldCreateSpan, spans); + }, + type: 'fetch', + }); + } + + if (traceXHR) { + addInstrumentationHandler({ + callback: (handlerData: XHRData) => { + xhrCallback(handlerData, shouldCreateSpan, spans); + }, + type: 'xhr', + }); + } +} + +/** + * Create and track fetch request spans + */ +function fetchCallback( + handlerData: FetchData, + shouldCreateSpan: (url: string) => boolean, + spans: Record, +): void { + if (!shouldCreateSpan(handlerData.fetchData.url)) { + return; + } + + if (handlerData.endTimestamp && handlerData.fetchData.__span) { + const span = spans[handlerData.fetchData.__span]; + if (span) { + span.finish(); + } + return; + } + + const activeTransaction = getActiveTransaction(); + if (activeTransaction) { + const span = activeTransaction.startChild({ + data: { + ...handlerData.fetchData, + type: 'fetch', + }, + description: `${handlerData.fetchData.method} ${handlerData.fetchData.url}`, + op: 'http', + }); + + spans[span.spanId] = span; + + const request = (handlerData.args[0] = handlerData.args[0] as string | Request); + const options = (handlerData.args[1] = (handlerData.args[1] as { [key: string]: any }) || {}); + let headers = options.headers; + if (isInstanceOf(request, Request)) { + headers = (request as Request).headers; + } + if (headers) { + // tslint:disable-next-line: no-unsafe-any + if (typeof headers.append === 'function') { + // tslint:disable-next-line: no-unsafe-any + headers.append('sentry-trace', span.toTraceparent()); + } else if (Array.isArray(headers)) { + headers = [...headers, ['sentry-trace', span.toTraceparent()]]; + } else { + headers = { ...headers, 'sentry-trace': span.toTraceparent() }; + } + } else { + headers = { 'sentry-trace': span.toTraceparent() }; + } + options.headers = headers; + } +} + +/** + * Create and track xhr request spans + */ +function xhrCallback( + handlerData: XHRData, + shouldCreateSpan: (url: string) => boolean, + spans: Record, +): void { + if (!handlerData || !handlerData.xhr || !handlerData.xhr.__sentry_xhr__) { + return; + } + + const xhr = handlerData.xhr.__sentry_xhr__; + if (!shouldCreateSpan(xhr.url)) { + return; + } + + // We only capture complete, non-sentry requests + if (handlerData.xhr.__sentry_own_request__) { + return; + } + + if (handlerData.endTimestamp && handlerData.xhr.__sentry_xhr_span_id__) { + const span = spans[handlerData.xhr.__sentry_xhr_span_id__]; + if (span) { + span.setData('url', xhr.url); + span.setData('method', xhr.method); + span.setHttpStatus(xhr.status_code); + span.finish(); + } + return; + } + + const activeTransaction = getActiveTransaction(); + if (activeTransaction) { + const span = activeTransaction.startChild({ + data: { + ...xhr.data, + type: 'xhr', + }, + description: `${xhr.method} ${xhr.url}`, + op: 'http', + }); + + handlerData.xhr.__sentry_xhr_span_id__ = span.spanId; + spans[handlerData.xhr.__sentry_xhr_span_id__] = span; + + if (handlerData.xhr.setRequestHeader) { + try { + handlerData.xhr.setRequestHeader('sentry-trace', span.toTraceparent()); + } catch (_) { + // Error: InvalidStateError: Failed to execute 'setRequestHeader' on 'XMLHttpRequest': The object's state must be OPENED. + } + } + } +} From a9b91c5b9cb53eeb013ec36dae575e6201052228 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Thu, 9 Jul 2020 15:38:52 -0400 Subject: [PATCH 05/13] feat: metrics --- .../tracing/src/browser/browsertracing.ts | 6 + packages/tracing/src/browser/metrics.ts | 278 ++++++++++++++++++ 2 files changed, 284 insertions(+) create mode 100644 packages/tracing/src/browser/metrics.ts diff --git a/packages/tracing/src/browser/browsertracing.ts b/packages/tracing/src/browser/browsertracing.ts index 40edb14af638..ef03fa66c3f7 100644 --- a/packages/tracing/src/browser/browsertracing.ts +++ b/packages/tracing/src/browser/browsertracing.ts @@ -9,6 +9,7 @@ import { SpanStatus } from '../spanstatus'; import { registerBackgroundTabDetection } from './backgroundtab'; import { registerErrorInstrumentation } from './errors'; +import { MetricsInstrumentation } from './metrics'; import { defaultRequestInstrumentionOptions, registerRequestInstrumentation, @@ -113,6 +114,8 @@ export class BrowserTracing implements Integration { private _getCurrentHub?: () => Hub; + private readonly _metrics: MetricsInstrumentation = new MetricsInstrumentation(); + private readonly _emitOptionsWarning: boolean = false; public constructor(_options?: Partial) { @@ -193,6 +196,9 @@ export class BrowserTracing implements Integration { logger.log(`[Tracing] starting ${ctx.op} idleTransaction on scope with context:`, ctx); const idleTransaction = startIdleTransaction(hub, ctx, idleTimeout, true); idleTransaction.registerBeforeFinishCallback(adjustTransactionDuration(secToMs(maxTransactionDuration))); + idleTransaction.registerBeforeFinishCallback(transaction => { + this._metrics.addPerformanceEntires(transaction); + }); return idleTransaction as TransactionType; } diff --git a/packages/tracing/src/browser/metrics.ts b/packages/tracing/src/browser/metrics.ts new file mode 100644 index 000000000000..3032aead7d0b --- /dev/null +++ b/packages/tracing/src/browser/metrics.ts @@ -0,0 +1,278 @@ +import { getGlobalObject, logger } from '@sentry/utils'; + +import { Span } from '../span'; +import { Transaction } from '../transaction'; + +import { msToSec } from './utils'; + +const global = getGlobalObject(); + +/** Class tracking metrics */ +export class MetricsInstrumentation { + private _lcp: Record = {}; + + private _performanceCursor: number = 0; + + private _forceLCP = () => { + /* No-op, replaced later if LCP API is available. */ + return; + }; + + /** Starts tracking the Largest Contentful Paint on the current page. */ + private _trackLCP(): void { + // Based on reference implementation from https://web.dev/lcp/#measure-lcp-in-javascript. + // Use a try/catch instead of feature detecting `largest-contentful-paint` + // support, since some browsers throw when using the new `type` option. + // https://bugs.webkit.org/show_bug.cgi?id=209216 + try { + // Keep track of whether (and when) the page was first hidden, see: + // https://github.com/w3c/page-visibility/issues/29 + // NOTE: ideally this check would be performed in the document + // to avoid cases where the visibility state changes before this code runs. + let firstHiddenTime = document.visibilityState === 'hidden' ? 0 : Infinity; + document.addEventListener( + 'visibilitychange', + event => { + firstHiddenTime = Math.min(firstHiddenTime, event.timeStamp); + }, + { once: true }, + ); + + const updateLCP = (entry: PerformanceEntry) => { + // Only include an LCP entry if the page wasn't hidden prior to + // the entry being dispatched. This typically happens when a page is + // loaded in a background tab. + if (entry.startTime < firstHiddenTime) { + // NOTE: the `startTime` value is a getter that returns the entry's + // `renderTime` value, if available, or its `loadTime` value otherwise. + // The `renderTime` value may not be available if the element is an image + // that's loaded cross-origin without the `Timing-Allow-Origin` header. + this._lcp = { + // @ts-ignore + ...(entry.id && { elementId: entry.id }), + // @ts-ignore + ...(entry.size && { elementSize: entry.size }), + value: entry.startTime, + }; + } + }; + + // Create a PerformanceObserver that calls `updateLCP` for each entry. + const po = new PerformanceObserver(entryList => { + entryList.getEntries().forEach(updateLCP); + }); + + // Observe entries of type `largest-contentful-paint`, including buffered entries, + // i.e. entries that occurred before calling `observe()` below. + po.observe({ + buffered: true, + type: 'largest-contentful-paint', + }); + + this._forceLCP = () => { + po.takeRecords().forEach(updateLCP); + }; + } catch (e) { + // Do nothing if the browser doesn't support this API. + } + } + + public constructor() { + if (global && global.performance) { + if (global.performance.mark) { + global.performance.mark('sentry-tracing-init'); + } + + this._trackLCP(); + } + } + + /** Add performance related spans to a transaction */ + public addPerformanceEntires(transaction: Transaction): void { + if (!global || !global.performance || !global.performance.getEntries) { + // Gatekeeper if performance API not available + return; + } + + logger.log('[Tracing] Adding & adjusting spans using Performance API'); + + // TODO(fixme): depending on the 'op' directly is brittle. + if (transaction.op === 'pageload') { + // Force any pending records to be dispatched. + this._forceLCP(); + if (this._lcp) { + // Set the last observed LCP score. + transaction.setData('_sentry_web_vitals', { LCP: this._lcp }); + } + } + + const timeOrigin = msToSec(performance.timeOrigin); + let entryScriptSrc: string | undefined; + + if (global.document) { + // tslint:disable-next-line: prefer-for-of + for (let i = 0; i < document.scripts.length; i++) { + // We go through all scripts on the page and look for 'data-entry' + // We remember the name and measure the time between this script finished loading and + // our mark 'sentry-tracing-init' + if (document.scripts[i].dataset.entry === 'true') { + entryScriptSrc = document.scripts[i].src; + break; + } + } + } + + let entryScriptStartEndTime: number | undefined; + let tracingInitMarkStartTime: number | undefined; + + global.performance + .getEntries() + .slice(this._performanceCursor) + .forEach((entry: Record) => { + const startTime = msToSec(entry.startTime as number); + const duration = msToSec(entry.duration as number); + + if (transaction.op === 'navigation' && timeOrigin + startTime < transaction.startTimestamp) { + return; + } + + switch (entry.entryType) { + case 'navigation': + addNavigationSpans(transaction, entry, timeOrigin); + break; + case 'mark': + case 'paint': + case 'measure': + const startTimestamp = addMeasureSpans(transaction, entry, startTime, duration, timeOrigin); + if (tracingInitMarkStartTime === undefined && entry.name === 'sentry-tracing-init') { + tracingInitMarkStartTime = startTimestamp; + } + break; + case 'resource': + const resourceName = (entry.name as string).replace(window.location.origin, ''); + const endTimestamp = addResourceSpans(transaction, entry, resourceName, startTime, duration, timeOrigin); + // We remember the entry script end time to calculate the difference to the first init mark + if (entryScriptStartEndTime === undefined && (entryScriptSrc || '').indexOf(resourceName) > -1) { + entryScriptStartEndTime = endTimestamp; + } + break; + default: + // Ignore other entry types. + } + }); + if (entryScriptStartEndTime !== undefined && tracingInitMarkStartTime !== undefined) { + transaction.startChild({ + description: 'evaluation', + endTimestamp: tracingInitMarkStartTime, + op: `script`, + startTimestamp: entryScriptStartEndTime, + }); + } + + this._performanceCursor = Math.max(performance.getEntries().length - 1, 0); + } +} + +/** Instrument navigation entries */ +function addNavigationSpans(transaction: Transaction, entry: Record, timeOrigin: number): void { + addPerformanceNavigationTiming(transaction, entry, 'unloadEvent', timeOrigin); + addPerformanceNavigationTiming(transaction, entry, 'domContentLoadedEvent', timeOrigin); + addPerformanceNavigationTiming(transaction, entry, 'loadEvent', timeOrigin); + addPerformanceNavigationTiming(transaction, entry, 'connect', timeOrigin); + addPerformanceNavigationTiming(transaction, entry, 'domainLookup', timeOrigin); + addRequest(transaction, entry, timeOrigin); +} + +/** Create measure related spans */ +function addMeasureSpans( + transaction: Transaction, + entry: Record, + startTime: number, + duration: number, + timeOrigin: number, +): number { + const measureStartTimestamp = timeOrigin + startTime; + const measureEndTimestamp = measureStartTimestamp + duration; + + transaction.startChild({ + description: entry.name as string, + endTimestamp: measureEndTimestamp, + op: entry.entryType as string, + startTimestamp: measureStartTimestamp, + }); + + return measureStartTimestamp; +} + +/** Create resource related spans */ +function addResourceSpans( + transaction: Transaction, + entry: Record, + resourceName: string, + startTime: number, + duration: number, + timeOrigin: number, +): number | undefined { + if (entry.initiatorType === 'xmlhttprequest' || entry.initiatorType === 'fetch') { + // We need to update existing spans with new timing info + if (transaction.spanRecorder) { + transaction.spanRecorder.spans.map((finishedSpan: Span) => { + if (finishedSpan.description && finishedSpan.description.indexOf(resourceName) !== -1) { + finishedSpan.startTimestamp = timeOrigin + startTime; + finishedSpan.endTimestamp = finishedSpan.startTimestamp + duration; + } + }); + } + } else { + const startTimestamp = timeOrigin + startTime; + const endTimestamp = startTimestamp + duration; + + transaction.startChild({ + description: `${entry.initiatorType} ${resourceName}`, + endTimestamp, + op: `resource`, + startTimestamp, + }); + + return endTimestamp; + } + + return undefined; +} + +/** Create performance navigation related spans */ +function addPerformanceNavigationTiming( + transaction: Transaction, + entry: Record, + event: string, + timeOrigin: number, +): void { + const end = entry[`${event}End`] as number | undefined; + const start = entry[`${event}Start`] as number | undefined; + if (!start || !end) { + return; + } + transaction.startChild({ + description: event, + endTimestamp: end + timeOrigin, + op: 'browser', + startTimestamp: start + timeOrigin, + }); +} + +/** Create request and response related spans */ +function addRequest(transaction: Transaction, entry: Record, timeOrigin: number): void { + transaction.startChild({ + description: 'request', + endTimestamp: timeOrigin + msToSec(entry.responseEnd as number), + op: 'browser', + startTimestamp: timeOrigin + msToSec(entry.requestStart as number), + }); + + transaction.startChild({ + description: 'response', + endTimestamp: timeOrigin + msToSec(entry.responseEnd as number), + op: 'browser', + startTimestamp: timeOrigin + msToSec(entry.responseStart as number), + }); +} From bede8694e03a2a2d2b4608c7480f652c0893ea75 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Thu, 9 Jul 2020 16:22:37 -0400 Subject: [PATCH 06/13] add more logging --- packages/tracing/src/browser/backgroundtab.ts | 6 +++++- packages/tracing/src/browser/metrics.ts | 5 +++-- packages/tracing/src/browser/router.ts | 1 + packages/tracing/src/idletransaction.ts | 9 ++++++--- 4 files changed, 15 insertions(+), 6 deletions(-) diff --git a/packages/tracing/src/browser/backgroundtab.ts b/packages/tracing/src/browser/backgroundtab.ts index d92ec1614fd1..9deea870841b 100644 --- a/packages/tracing/src/browser/backgroundtab.ts +++ b/packages/tracing/src/browser/backgroundtab.ts @@ -16,7 +16,11 @@ export function registerBackgroundTabDetection(): void { global.document.addEventListener('visibilitychange', () => { const activeTransaction = getActiveTransaction() as IdleTransaction; if (global.document.hidden && activeTransaction) { - logger.log(`[Tracing] Transaction: ${SpanStatus.Cancelled} -> since tab moved to the background`); + logger.log( + `[Tracing] Transaction: ${SpanStatus.Cancelled} -> since tab moved to the background, op: ${ + activeTransaction.op + }`, + ); activeTransaction.setStatus(SpanStatus.Cancelled); activeTransaction.setTag('visibilitychange', 'document.hidden'); activeTransaction.finish(); diff --git a/packages/tracing/src/browser/metrics.ts b/packages/tracing/src/browser/metrics.ts index 3032aead7d0b..6571371d49b2 100644 --- a/packages/tracing/src/browser/metrics.ts +++ b/packages/tracing/src/browser/metrics.ts @@ -66,6 +66,7 @@ export class MetricsInstrumentation { // i.e. entries that occurred before calling `observe()` below. po.observe({ buffered: true, + // @ts-ignore type: 'largest-contentful-paint', }); @@ -164,7 +165,7 @@ export class MetricsInstrumentation { transaction.startChild({ description: 'evaluation', endTimestamp: tracingInitMarkStartTime, - op: `script`, + op: 'script', startTimestamp: entryScriptStartEndTime, }); } @@ -230,7 +231,7 @@ function addResourceSpans( transaction.startChild({ description: `${entry.initiatorType} ${resourceName}`, endTimestamp, - op: `resource`, + op: 'resource', startTimestamp, }); diff --git a/packages/tracing/src/browser/router.ts b/packages/tracing/src/browser/router.ts index 6ce36eef5bd5..b7d0565ecad6 100644 --- a/packages/tracing/src/browser/router.ts +++ b/packages/tracing/src/browser/router.ts @@ -43,6 +43,7 @@ export function defaultRoutingInstrumentation( if (from !== to) { startingUrl = undefined; if (activeTransaction) { + logger.log(`[Tracing] finishing current idleTransaction with op: ${activeTransaction.op}`); // We want to finish all current ongoing idle transactions as we // are navigating to a new page. activeTransaction.finish(); diff --git a/packages/tracing/src/idletransaction.ts b/packages/tracing/src/idletransaction.ts index 4fe761d3d0d6..5d45dd50958d 100644 --- a/packages/tracing/src/idletransaction.ts +++ b/packages/tracing/src/idletransaction.ts @@ -139,6 +139,9 @@ export class IdleTransaction extends Transaction { /** {@inheritDoc} */ public finish(endTimestamp: number = timestampWithMs()): string | undefined { + this._finished = true; + this.activities = {}; + if (this.spanRecorder) { logger.log('[Tracing] finishing IdleTransaction', new Date(endTimestamp * 1000).toISOString(), this.op); @@ -169,8 +172,6 @@ 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); @@ -213,7 +214,9 @@ export class IdleTransaction extends Transaction { const end = timestampWithMs() + timeout / 1000; setTimeout(() => { - this.finish(end); + if (!this._finished) { + this.finish(end); + } }, timeout); } } From a55c8be9f3c1c78359ca7119e966d9a5e1cf0866 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Thu, 9 Jul 2020 18:28:48 -0400 Subject: [PATCH 07/13] trim transactions --- packages/tracing/src/browser/browsertracing.ts | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/packages/tracing/src/browser/browsertracing.ts b/packages/tracing/src/browser/browsertracing.ts index ef03fa66c3f7..dea9e1fac643 100644 --- a/packages/tracing/src/browser/browsertracing.ts +++ b/packages/tracing/src/browser/browsertracing.ts @@ -185,6 +185,7 @@ export class BrowserTracing implements Integration { const ctx = beforeNavigate({ ...context, ...getHeaderContext(), + trimEnd: true, }); if (ctx === undefined) { @@ -193,7 +194,7 @@ export class BrowserTracing implements Integration { } const hub = this._getCurrentHub(); - logger.log(`[Tracing] starting ${ctx.op} idleTransaction on scope with context:`, ctx); + logger.log(`[Tracing] starting ${ctx.op} idleTransaction on scope`); const idleTransaction = startIdleTransaction(hub, ctx, idleTimeout, true); idleTransaction.registerBeforeFinishCallback(adjustTransactionDuration(secToMs(maxTransactionDuration))); idleTransaction.registerBeforeFinishCallback(transaction => { From ea0686eb01b8e146c846e3618fe68bb3e753b213 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Fri, 10 Jul 2020 12:28:41 -0400 Subject: [PATCH 08/13] test for request --- packages/tracing/src/browser/request.ts | 4 +- .../test/browser/browsertracing.test.ts | 18 +++++++ packages/tracing/test/browser/metrics.test.ts | 1 + packages/tracing/test/browser/request.test.ts | 49 +++++++++++++++++++ 4 files changed, 71 insertions(+), 1 deletion(-) create mode 100644 packages/tracing/test/browser/metrics.test.ts create mode 100644 packages/tracing/test/browser/request.test.ts diff --git a/packages/tracing/src/browser/request.ts b/packages/tracing/src/browser/request.ts index d4499b70b11d..1f0bc17f10ba 100644 --- a/packages/tracing/src/browser/request.ts +++ b/packages/tracing/src/browser/request.ts @@ -76,7 +76,7 @@ export const defaultRequestInstrumentionOptions: RequestInstrumentationOptions = }; /** Registers span creators for xhr and fetch requests */ -export function registerRequestInstrumentation(_options: Partial): void { +export function registerRequestInstrumentation(_options?: Partial): void { const { traceFetch, traceXHR, tracingOrigins, shouldCreateSpanForRequest } = { ...defaultRequestInstrumentionOptions, ..._options, @@ -199,6 +199,8 @@ function xhrCallback( return; } + // logger.log('XHR', JSON.stringify(handlerData)); + if (handlerData.endTimestamp && handlerData.xhr.__sentry_xhr_span_id__) { const span = spans[handlerData.xhr.__sentry_xhr_span_id__]; if (span) { diff --git a/packages/tracing/test/browser/browsertracing.test.ts b/packages/tracing/test/browser/browsertracing.test.ts index 323e39db77bd..7524faeaf745 100644 --- a/packages/tracing/test/browser/browsertracing.test.ts +++ b/packages/tracing/test/browser/browsertracing.test.ts @@ -10,6 +10,7 @@ import { DEFAULT_MAX_TRANSACTION_DURATION__SECONDS, getMetaContent, } from '../../src/browser/browsertracing'; +import { defaultRequestInstrumentionOptions } from '../../src/browser/request'; import { defaultRoutingInstrumentation } from '../../src/browser/router'; import { getActiveTransaction, secToMs } from '../../src/browser/utils'; import { DEFAULT_IDLE_TIMEOUT, IdleTransaction } from '../../src/idletransaction'; @@ -73,10 +74,12 @@ describe('BrowserTracing', () => { expect(browserTracing.options).toEqual({ beforeNavigate: expect.any(Function), idleTimeout: DEFAULT_IDLE_TIMEOUT, + markBackgroundTransactions: true, maxTransactionDuration: DEFAULT_MAX_TRANSACTION_DURATION__SECONDS, routingInstrumentation: defaultRoutingInstrumentation, startTransactionOnLocationChange: true, startTransactionOnPageLoad: true, + ...defaultRequestInstrumentionOptions, }); }); @@ -101,6 +104,21 @@ describe('BrowserTracing', () => { expect(transaction.op).toBe('pageload'); }); + it('trims all transactions', () => { + createBrowserTracing(true, { + routingInstrumentation: customRoutingInstrumentation, + }); + + const transaction = getActiveTransaction(hub) as IdleTransaction; + const span = transaction.startChild(); + span.finish(); + + if (span.endTimestamp) { + transaction.finish(span.endTimestamp + 12345); + } + expect(transaction.endTimestamp).toBe(span.endTimestamp); + }); + describe('beforeNavigate', () => { it('is called on transaction creation', () => { const mockBeforeNavigation = jest.fn().mockReturnValue({ name: 'here/is/my/path' }); diff --git a/packages/tracing/test/browser/metrics.test.ts b/packages/tracing/test/browser/metrics.test.ts new file mode 100644 index 000000000000..b88991dbcc3a --- /dev/null +++ b/packages/tracing/test/browser/metrics.test.ts @@ -0,0 +1 @@ +import { performance } from 'perf_hooks'; diff --git a/packages/tracing/test/browser/request.test.ts b/packages/tracing/test/browser/request.test.ts new file mode 100644 index 000000000000..a9daece7516c --- /dev/null +++ b/packages/tracing/test/browser/request.test.ts @@ -0,0 +1,49 @@ +import { registerRequestInstrumentation } from '../../src/browser/request'; + +const mockAddInstrumentationHandler = jest.fn(); +let mockFetchCallback = jest.fn(); +let mockXHRCallback = jest.fn(); +jest.mock('@sentry/utils', () => { + const actual = jest.requireActual('@sentry/utils'); + return { + ...actual, + addInstrumentationHandler: ({ callback, type }: any) => { + if (type === 'fetch') { + mockFetchCallback = jest.fn(callback); + } + if (type === 'xhr') { + mockXHRCallback = jest.fn(callback); + } + return mockAddInstrumentationHandler({ callback, type }); + }, + }; +}); + +describe('registerRequestInstrumentation', () => { + beforeEach(() => { + mockFetchCallback.mockClear(); + mockXHRCallback.mockClear(); + mockAddInstrumentationHandler.mockClear(); + }); + + it('tracks fetch and xhr requests', () => { + registerRequestInstrumentation(); + expect(mockAddInstrumentationHandler).toHaveBeenCalledTimes(2); + // fetch + expect(mockAddInstrumentationHandler).toHaveBeenNthCalledWith(1, { callback: expect.any(Function), type: 'fetch' }); + // xhr + expect(mockAddInstrumentationHandler).toHaveBeenNthCalledWith(2, { callback: expect.any(Function), type: 'xhr' }); + }); + + it('does not add fetch requests spans if traceFetch is false', () => { + registerRequestInstrumentation({ traceFetch: false }); + expect(mockAddInstrumentationHandler).toHaveBeenCalledTimes(1); + expect(mockFetchCallback()).toBe(undefined); + }); + + it('does not add xhr requests spans if traceXHR is false', () => { + registerRequestInstrumentation({ traceXHR: false }); + expect(mockAddInstrumentationHandler).toHaveBeenCalledTimes(1); + expect(mockXHRCallback()).toBe(undefined); + }); +}); From 3e55bf61a505f08888790704cfe357e8456e25ab Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Fri, 10 Jul 2020 12:37:42 -0400 Subject: [PATCH 09/13] remove comment --- packages/tracing/test/browser/errors.test.ts | 2 -- 1 file changed, 2 deletions(-) diff --git a/packages/tracing/test/browser/errors.test.ts b/packages/tracing/test/browser/errors.test.ts index 2a4b6a2a44cd..07b43ad6252f 100644 --- a/packages/tracing/test/browser/errors.test.ts +++ b/packages/tracing/test/browser/errors.test.ts @@ -71,8 +71,6 @@ describe('registerErrorHandlers()', () => { mockErrorCallback(); expect(transaction.status).toBe(SpanStatus.InternalError); - // mockUnhandledRejectionCallback(); - // expect(transaction.status).toBe(undefined); transaction.finish(); }); From 0a5e72a33ac0f430a7d9c4427f9364785e0fa0fe Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Mon, 13 Jul 2020 07:56:21 -0400 Subject: [PATCH 10/13] ref: Make sure tracingOrigins is set properly --- .../tracing/src/browser/browsertracing.ts | 17 +++++-- .../test/browser/browsertracing.test.ts | 47 +++++++++++++++++++ 2 files changed, 60 insertions(+), 4 deletions(-) diff --git a/packages/tracing/src/browser/browsertracing.ts b/packages/tracing/src/browser/browsertracing.ts index dea9e1fac643..4d0f0115d76a 100644 --- a/packages/tracing/src/browser/browsertracing.ts +++ b/packages/tracing/src/browser/browsertracing.ts @@ -74,8 +74,8 @@ export interface BrowserTracingOptions extends RequestInstrumentationOptions { /** * Flag Transactions where tabs moved to background with "cancelled". Browser background tab timing is - * not suited towards doing precise measurements of operations. Background transaction can mess up your - * statistics in non deterministic ways that's why we by default recommend leaving this opition enabled. + * not suited towards doing precise measurements of operations. By default, we recommend that this option + * be enabled as background transactions can mess up your statistics in nondeterministic ways. * * Default: true */ @@ -119,14 +119,23 @@ export class BrowserTracing implements Integration { private readonly _emitOptionsWarning: boolean = false; public constructor(_options?: Partial) { - // NOTE: Logger doesn't work in contructors, as it's initialized after integrations instances - if (!_options || !Array.isArray(_options.tracingOrigins) || _options.tracingOrigins.length === 0) { + let tracingOrigins = defaultRequestInstrumentionOptions.tracingOrigins; + // NOTE: Logger doesn't work in constructors, as it's initialized after integrations instances + if ( + _options && + _options.tracingOrigins && + Array.isArray(_options.tracingOrigins) && + _options.tracingOrigins.length !== 0 + ) { + tracingOrigins = _options.tracingOrigins; + } else { this._emitOptionsWarning = true; } this.options = { ...this.options, ..._options, + tracingOrigins, }; } diff --git a/packages/tracing/test/browser/browsertracing.test.ts b/packages/tracing/test/browser/browsertracing.test.ts index 7524faeaf745..3b6485843ef4 100644 --- a/packages/tracing/test/browser/browsertracing.test.ts +++ b/packages/tracing/test/browser/browsertracing.test.ts @@ -16,6 +16,7 @@ import { getActiveTransaction, secToMs } from '../../src/browser/utils'; import { DEFAULT_IDLE_TIMEOUT, IdleTransaction } from '../../src/idletransaction'; let mockChangeHistory: ({ to, from }: { to: string; from?: string }) => void = () => undefined; + jest.mock('@sentry/utils', () => { const actual = jest.requireActual('@sentry/utils'); return { @@ -28,6 +29,9 @@ jest.mock('@sentry/utils', () => { }; }); +const { logger } = jest.requireActual('@sentry/utils'); +const warnSpy = jest.spyOn(logger, 'warn'); + beforeAll(() => { const dom = new JSDOM(); // @ts-ignore @@ -45,6 +49,8 @@ describe('BrowserTracing', () => { hub = new Hub(new BrowserClient({ tracesSampleRate: 1 })); makeMain(hub); document.head.innerHTML = ''; + + warnSpy.mockClear(); }); afterEach(() => { @@ -119,6 +125,47 @@ describe('BrowserTracing', () => { expect(transaction.endTimestamp).toBe(span.endTimestamp); }); + describe('tracingOrigins', () => { + it('warns and uses default tracing origins if non are provided', () => { + const inst = createBrowserTracing(true, { + routingInstrumentation: customRoutingInstrumentation, + }); + + expect(warnSpy).toHaveBeenCalledTimes(2); + expect(inst.options.tracingOrigins).toEqual(defaultRequestInstrumentionOptions.tracingOrigins); + }); + + it('warns and uses default tracing origins if array not given', () => { + const inst = createBrowserTracing(true, { + routingInstrumentation: customRoutingInstrumentation, + tracingOrigins: [], + }); + + expect(warnSpy).toHaveBeenCalledTimes(2); + expect(inst.options.tracingOrigins).toEqual(defaultRequestInstrumentionOptions.tracingOrigins); + }); + + it('warns and uses default tracing origins if tracing origins are not defined', () => { + const inst = createBrowserTracing(true, { + routingInstrumentation: customRoutingInstrumentation, + tracingOrigins: undefined, + }); + + expect(warnSpy).toHaveBeenCalledTimes(2); + expect(inst.options.tracingOrigins).toEqual(defaultRequestInstrumentionOptions.tracingOrigins); + }); + + it('sets tracing origins if provided and does not warn', () => { + const inst = createBrowserTracing(true, { + routingInstrumentation: customRoutingInstrumentation, + tracingOrigins: ['something'], + }); + + expect(warnSpy).toHaveBeenCalledTimes(0); + expect(inst.options.tracingOrigins).toEqual(['something']); + }); + }); + describe('beforeNavigate', () => { it('is called on transaction creation', () => { const mockBeforeNavigation = jest.fn().mockReturnValue({ name: 'here/is/my/path' }); From ee5b4c4c549e9b81f7b450cbc84ff56d7d9ca8d9 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Mon, 13 Jul 2020 08:19:08 -0400 Subject: [PATCH 11/13] ref: Address PR review --- .../tracing/src/browser/browsertracing.ts | 22 +++++++-------- packages/tracing/src/browser/metrics.ts | 1 + packages/tracing/src/browser/request.ts | 27 +++++++++---------- .../test/browser/browsertracing.test.ts | 2 +- 4 files changed, 24 insertions(+), 28 deletions(-) diff --git a/packages/tracing/src/browser/browsertracing.ts b/packages/tracing/src/browser/browsertracing.ts index 4d0f0115d76a..506914cd6cf2 100644 --- a/packages/tracing/src/browser/browsertracing.ts +++ b/packages/tracing/src/browser/browsertracing.ts @@ -3,7 +3,7 @@ import { EventProcessor, Integration, Transaction as TransactionType, Transactio import { logger } from '@sentry/utils'; import { startIdleTransaction } from '../hubextensions'; -import { BeforeFinishCallback, DEFAULT_IDLE_TIMEOUT, IdleTransaction } from '../idletransaction'; +import { DEFAULT_IDLE_TIMEOUT, IdleTransaction } from '../idletransaction'; import { Span } from '../span'; import { SpanStatus } from '../spanstatus'; @@ -205,9 +205,9 @@ export class BrowserTracing implements Integration { const hub = this._getCurrentHub(); logger.log(`[Tracing] starting ${ctx.op} idleTransaction on scope`); const idleTransaction = startIdleTransaction(hub, ctx, idleTimeout, true); - idleTransaction.registerBeforeFinishCallback(adjustTransactionDuration(secToMs(maxTransactionDuration))); - idleTransaction.registerBeforeFinishCallback(transaction => { + idleTransaction.registerBeforeFinishCallback((transaction, endTimestamp) => { this._metrics.addPerformanceEntires(transaction); + adjustTransactionDuration(secToMs(maxTransactionDuration), transaction, endTimestamp); }); return idleTransaction as TransactionType; @@ -240,13 +240,11 @@ export function getMetaContent(metaName: string): string | null { } /** Adjusts transaction value based on max transaction duration */ -function adjustTransactionDuration(maxDuration: number): BeforeFinishCallback { - return (transaction: IdleTransaction, endTimestamp: number): void => { - const diff = endTimestamp - transaction.startTimestamp; - const isOutdatedTransaction = endTimestamp && (diff > maxDuration || diff < 0); - if (isOutdatedTransaction) { - transaction.setStatus(SpanStatus.Cancelled); - transaction.setTag('maxTransactionDurationExceeded', 'true'); - } - }; +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(SpanStatus.DeadlineExceeded); + transaction.setTag('maxTransactionDurationExceeded', 'true'); + } } diff --git a/packages/tracing/src/browser/metrics.ts b/packages/tracing/src/browser/metrics.ts index 6571371d49b2..d5f59c7956cd 100644 --- a/packages/tracing/src/browser/metrics.ts +++ b/packages/tracing/src/browser/metrics.ts @@ -161,6 +161,7 @@ export class MetricsInstrumentation { // Ignore other entry types. } }); + if (entryScriptStartEndTime !== undefined && tracingInitMarkStartTime !== undefined) { transaction.startChild({ description: 'evaluation', diff --git a/packages/tracing/src/browser/request.ts b/packages/tracing/src/browser/request.ts index 1f0bc17f10ba..7cd5d2c8188c 100644 --- a/packages/tracing/src/browser/request.ts +++ b/packages/tracing/src/browser/request.ts @@ -86,19 +86,18 @@ export function registerRequestInstrumentation(_options?: Partial = {}; - const shouldCreateSpan = shouldCreateSpanForRequest - ? shouldCreateSpanForRequest - : (url: string) => { - if (urlMap[url]) { - return urlMap[url]; - } - const origins = tracingOrigins; - const decision = - origins.some((origin: string | RegExp) => isMatchingPattern(url, origin)) && - !isMatchingPattern(url, 'sentry_key'); - urlMap[url] = decision; - return urlMap[url]; - }; + const defaultShouldCreateSpan = (url: string): boolean => { + if (urlMap[url]) { + return urlMap[url]; + } + const origins = tracingOrigins; + urlMap[url] = + origins.some((origin: string | RegExp) => isMatchingPattern(url, origin)) && + !isMatchingPattern(url, 'sentry_key'); + return urlMap[url]; + }; + + const shouldCreateSpan = shouldCreateSpanForRequest || defaultShouldCreateSpan; const spans: Record = {}; @@ -199,8 +198,6 @@ function xhrCallback( return; } - // logger.log('XHR', JSON.stringify(handlerData)); - if (handlerData.endTimestamp && handlerData.xhr.__sentry_xhr_span_id__) { const span = spans[handlerData.xhr.__sentry_xhr_span_id__]; if (span) { diff --git a/packages/tracing/test/browser/browsertracing.test.ts b/packages/tracing/test/browser/browsertracing.test.ts index 3b6485843ef4..e0b88e845933 100644 --- a/packages/tracing/test/browser/browsertracing.test.ts +++ b/packages/tracing/test/browser/browsertracing.test.ts @@ -256,7 +256,7 @@ describe('BrowserTracing', () => { const transaction = getActiveTransaction(hub) as IdleTransaction; transaction.finish(transaction.startTimestamp + secToMs(DEFAULT_MAX_TRANSACTION_DURATION__SECONDS) + 1); - expect(transaction.status).toBe(SpanStatus.Cancelled); + expect(transaction.status).toBe(SpanStatus.DeadlineExceeded); expect(transaction.tags.maxTransactionDurationExceeded).toBeDefined(); }); From e8c5d008b11215f7d2a2c184b8fda37f12849339 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Mon, 13 Jul 2020 09:44:15 -0400 Subject: [PATCH 12/13] address PR review 2 --- packages/tracing/src/browser/browsertracing.ts | 4 ++-- packages/tracing/src/browser/request.ts | 14 ++++++++++---- .../tracing/test/browser/browsertracing.test.ts | 10 +++++----- packages/tracing/test/browser/metrics.test.ts | 1 - packages/tracing/test/browser/request.test.ts | 6 +++--- packages/tracing/test/idletransaction.test.ts | 4 ++-- 6 files changed, 22 insertions(+), 17 deletions(-) delete mode 100644 packages/tracing/test/browser/metrics.test.ts diff --git a/packages/tracing/src/browser/browsertracing.ts b/packages/tracing/src/browser/browsertracing.ts index 506914cd6cf2..244f87c35de4 100644 --- a/packages/tracing/src/browser/browsertracing.ts +++ b/packages/tracing/src/browser/browsertracing.ts @@ -18,7 +18,7 @@ import { import { defaultBeforeNavigate, defaultRoutingInstrumentation } from './router'; import { secToMs } from './utils'; -export const DEFAULT_MAX_TRANSACTION_DURATION__SECONDS = 600; +export const DEFAULT_MAX_TRANSACTION_DURATION_SECONDS = 600; /** Options for Browser Tracing integration */ export interface BrowserTracingOptions extends RequestInstrumentationOptions { @@ -100,7 +100,7 @@ export class BrowserTracing implements Integration { beforeNavigate: defaultBeforeNavigate, idleTimeout: DEFAULT_IDLE_TIMEOUT, markBackgroundTransactions: true, - maxTransactionDuration: DEFAULT_MAX_TRANSACTION_DURATION__SECONDS, + maxTransactionDuration: DEFAULT_MAX_TRANSACTION_DURATION_SECONDS, routingInstrumentation: defaultRoutingInstrumentation, startTransactionOnLocationChange: true, startTransactionOnPageLoad: true, diff --git a/packages/tracing/src/browser/request.ts b/packages/tracing/src/browser/request.ts index 7cd5d2c8188c..e66dc97606d2 100644 --- a/packages/tracing/src/browser/request.ts +++ b/packages/tracing/src/browser/request.ts @@ -99,7 +99,7 @@ export function registerRequestInstrumentation(_options?: Partial = {}; + const spans: Record = {}; if (traceFetch) { addInstrumentationHandler({ @@ -126,9 +126,9 @@ export function registerRequestInstrumentation(_options?: Partial boolean, - spans: Record, + spans: Record, ): void { - if (!shouldCreateSpan(handlerData.fetchData.url)) { + if (!shouldCreateSpan(handlerData.fetchData.url) || !handlerData.fetchData) { return; } @@ -136,6 +136,9 @@ function fetchCallback( const span = spans[handlerData.fetchData.__span]; if (span) { span.finish(); + + // tslint:disable-next-line: no-dynamic-delete + delete spans[handlerData.fetchData.__span]; } return; } @@ -182,7 +185,7 @@ function fetchCallback( function xhrCallback( handlerData: XHRData, shouldCreateSpan: (url: string) => boolean, - spans: Record, + spans: Record, ): void { if (!handlerData || !handlerData.xhr || !handlerData.xhr.__sentry_xhr__) { return; @@ -205,6 +208,9 @@ function xhrCallback( span.setData('method', xhr.method); span.setHttpStatus(xhr.status_code); span.finish(); + + // tslint:disable-next-line: no-dynamic-delete + delete spans[handlerData.xhr.__sentry_xhr_span_id__]; } return; } diff --git a/packages/tracing/test/browser/browsertracing.test.ts b/packages/tracing/test/browser/browsertracing.test.ts index e0b88e845933..5e7f695aed86 100644 --- a/packages/tracing/test/browser/browsertracing.test.ts +++ b/packages/tracing/test/browser/browsertracing.test.ts @@ -7,7 +7,7 @@ import { SpanStatus } from '../../src'; import { BrowserTracing, BrowserTracingOptions, - DEFAULT_MAX_TRANSACTION_DURATION__SECONDS, + DEFAULT_MAX_TRANSACTION_DURATION_SECONDS, getMetaContent, } from '../../src/browser/browsertracing'; import { defaultRequestInstrumentionOptions } from '../../src/browser/request'; @@ -81,7 +81,7 @@ describe('BrowserTracing', () => { beforeNavigate: expect.any(Function), idleTimeout: DEFAULT_IDLE_TIMEOUT, markBackgroundTransactions: true, - maxTransactionDuration: DEFAULT_MAX_TRANSACTION_DURATION__SECONDS, + maxTransactionDuration: DEFAULT_MAX_TRANSACTION_DURATION_SECONDS, routingInstrumentation: defaultRoutingInstrumentation, startTransactionOnLocationChange: true, startTransactionOnPageLoad: true, @@ -254,7 +254,7 @@ describe('BrowserTracing', () => { it('cancels a transaction if exceeded', () => { createBrowserTracing(true, { routingInstrumentation: customRoutingInstrumentation }); const transaction = getActiveTransaction(hub) as IdleTransaction; - transaction.finish(transaction.startTimestamp + secToMs(DEFAULT_MAX_TRANSACTION_DURATION__SECONDS) + 1); + transaction.finish(transaction.startTimestamp + secToMs(DEFAULT_MAX_TRANSACTION_DURATION_SECONDS) + 1); expect(transaction.status).toBe(SpanStatus.DeadlineExceeded); expect(transaction.tags.maxTransactionDurationExceeded).toBeDefined(); @@ -263,7 +263,7 @@ describe('BrowserTracing', () => { it('does not cancel a transaction if not exceeded', () => { createBrowserTracing(true, { routingInstrumentation: customRoutingInstrumentation }); const transaction = getActiveTransaction(hub) as IdleTransaction; - transaction.finish(transaction.startTimestamp + secToMs(DEFAULT_MAX_TRANSACTION_DURATION__SECONDS)); + transaction.finish(transaction.startTimestamp + secToMs(DEFAULT_MAX_TRANSACTION_DURATION_SECONDS)); expect(transaction.status).toBe(undefined); expect(transaction.tags.maxTransactionDurationExceeded).not.toBeDefined(); @@ -272,7 +272,7 @@ describe('BrowserTracing', () => { 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); + expect(DEFAULT_MAX_TRANSACTION_DURATION_SECONDS < customMaxTransactionDuration).toBe(true); createBrowserTracing(true, { maxTransactionDuration: customMaxTransactionDuration, routingInstrumentation: customRoutingInstrumentation, diff --git a/packages/tracing/test/browser/metrics.test.ts b/packages/tracing/test/browser/metrics.test.ts deleted file mode 100644 index b88991dbcc3a..000000000000 --- a/packages/tracing/test/browser/metrics.test.ts +++ /dev/null @@ -1 +0,0 @@ -import { performance } from 'perf_hooks'; diff --git a/packages/tracing/test/browser/request.test.ts b/packages/tracing/test/browser/request.test.ts index a9daece7516c..5e22c6985db7 100644 --- a/packages/tracing/test/browser/request.test.ts +++ b/packages/tracing/test/browser/request.test.ts @@ -21,9 +21,9 @@ jest.mock('@sentry/utils', () => { describe('registerRequestInstrumentation', () => { beforeEach(() => { - mockFetchCallback.mockClear(); - mockXHRCallback.mockClear(); - mockAddInstrumentationHandler.mockClear(); + mockFetchCallback.mockReset(); + mockXHRCallback.mockReset(); + mockAddInstrumentationHandler.mockReset(); }); it('tracks fetch and xhr requests', () => { diff --git a/packages/tracing/test/idletransaction.test.ts b/packages/tracing/test/idletransaction.test.ts index 563cfbd0a1b8..44c00b8e3945 100644 --- a/packages/tracing/test/idletransaction.test.ts +++ b/packages/tracing/test/idletransaction.test.ts @@ -107,9 +107,9 @@ describe('IdleTransaction', () => { jest.runOnlyPendingTimers(); expect(mockCallback1).toHaveBeenCalledTimes(1); - expect(mockCallback1).toHaveBeenLastCalledWith(transaction); + expect(mockCallback1).toHaveBeenLastCalledWith(transaction, expect.any(Number)); expect(mockCallback2).toHaveBeenCalledTimes(1); - expect(mockCallback2).toHaveBeenLastCalledWith(transaction); + expect(mockCallback2).toHaveBeenLastCalledWith(transaction, expect.any(Number)); }); it('filters spans on finish', () => { From da4b39acc25e5266be70b4d4b8c06f881b768551 Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Mon, 13 Jul 2020 09:50:27 -0400 Subject: [PATCH 13/13] entryScriptStartTimestamp --- packages/tracing/src/browser/metrics.ts | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/packages/tracing/src/browser/metrics.ts b/packages/tracing/src/browser/metrics.ts index d5f59c7956cd..8bd0722618e4 100644 --- a/packages/tracing/src/browser/metrics.ts +++ b/packages/tracing/src/browser/metrics.ts @@ -123,7 +123,7 @@ export class MetricsInstrumentation { } } - let entryScriptStartEndTime: number | undefined; + let entryScriptStartTimestamp: number | undefined; let tracingInitMarkStartTime: number | undefined; global.performance @@ -153,8 +153,8 @@ export class MetricsInstrumentation { const resourceName = (entry.name as string).replace(window.location.origin, ''); const endTimestamp = addResourceSpans(transaction, entry, resourceName, startTime, duration, timeOrigin); // We remember the entry script end time to calculate the difference to the first init mark - if (entryScriptStartEndTime === undefined && (entryScriptSrc || '').indexOf(resourceName) > -1) { - entryScriptStartEndTime = endTimestamp; + if (entryScriptStartTimestamp === undefined && (entryScriptSrc || '').indexOf(resourceName) > -1) { + entryScriptStartTimestamp = endTimestamp; } break; default: @@ -162,12 +162,12 @@ export class MetricsInstrumentation { } }); - if (entryScriptStartEndTime !== undefined && tracingInitMarkStartTime !== undefined) { + if (entryScriptStartTimestamp !== undefined && tracingInitMarkStartTime !== undefined) { transaction.startChild({ description: 'evaluation', endTimestamp: tracingInitMarkStartTime, op: 'script', - startTimestamp: entryScriptStartEndTime, + startTimestamp: entryScriptStartTimestamp, }); }