From c6c54a1bbeccd832ea0309139b9d70732ae734fb Mon Sep 17 00:00:00 2001 From: Abhijeet Prasad Date: Fri, 24 Jul 2020 10:04:02 -0400 Subject: [PATCH] fix: Make sure fetch requests are being timed correctly (#2772) --- CHANGELOG.md | 1 + packages/apm/src/integrations/tracing.ts | 14 +-- packages/tracing/src/browser/backgroundtab.ts | 6 +- packages/tracing/src/browser/metrics.ts | 37 +++--- packages/tracing/src/browser/request.ts | 11 +- packages/tracing/src/idletransaction.ts | 6 +- packages/tracing/test/browser/request.test.ts | 111 +++++++++++++++++- 7 files changed, 141 insertions(+), 45 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0b9af336bd93..5f0e6d729c1e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,7 @@ - "You miss 100 percent of the chances you don't take. — Wayne Gretzky" — Michael Scott - [react] feat: Add instrumentation for React Router v3 (#2759) +- [apm/tracing] fix: Make sure fetch requests are being timed correctly (#2772) ## 5.20.0 diff --git a/packages/apm/src/integrations/tracing.ts b/packages/apm/src/integrations/tracing.ts index d7cbd77ab4a8..d5a7849d4f1a 100644 --- a/packages/apm/src/integrations/tracing.ts +++ b/packages/apm/src/integrations/tracing.ts @@ -660,17 +660,9 @@ export class Tracing implements Integration { break; case 'resource': const resourceName = entry.name.replace(window.location.origin, ''); - if (entry.initiatorType === 'xmlhttprequest' || entry.initiatorType === 'fetch') { - // We need to update existing spans with new timing info - if (transactionSpan.spanRecorder) { - transactionSpan.spanRecorder.spans.map((finishedSpan: Span) => { - if (finishedSpan.description && finishedSpan.description.indexOf(resourceName) !== -1) { - finishedSpan.startTimestamp = timeOrigin + startTime; - finishedSpan.endTimestamp = finishedSpan.startTimestamp + duration; - } - }); - } - } else { + // we already instrument based on fetch and xhr, so we don't need to + // duplicate spans here. + if (entry.initiatorType !== 'xmlhttprequest' && entry.initiatorType !== 'fetch') { const resource = transactionSpan.startChild({ description: `${entry.initiatorType} ${resourceName}`, op: `resource`, diff --git a/packages/tracing/src/browser/backgroundtab.ts b/packages/tracing/src/browser/backgroundtab.ts index b0065662d5e4..71d16c4f3ebd 100644 --- a/packages/tracing/src/browser/backgroundtab.ts +++ b/packages/tracing/src/browser/backgroundtab.ts @@ -19,7 +19,11 @@ export function registerBackgroundTabDetection(): void { logger.log( `[Tracing] Transaction: ${SpanStatus.Cancelled} -> since tab moved to the background, op: ${activeTransaction.op}`, ); - activeTransaction.setStatus(SpanStatus.Cancelled); + // We should not set status if it is already set, this prevent important statuses like + // error or data loss from being overwritten on transaction. + if (!activeTransaction.status) { + 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 606e703bfacb..b8e126323f8d 100644 --- a/packages/tracing/src/browser/metrics.ts +++ b/packages/tracing/src/browser/metrics.ts @@ -1,6 +1,5 @@ import { getGlobalObject, logger } from '@sentry/utils'; -import { Span } from '../span'; import { Transaction } from '../transaction'; import { msToSec } from './utils'; @@ -215,31 +214,23 @@ function addResourceSpans( duration: number, timeOrigin: number, ): number | undefined { + // we already instrument based on fetch and xhr, so we don't need to + // duplicate spans here. 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; } - return undefined; + const startTimestamp = timeOrigin + startTime; + const endTimestamp = startTimestamp + duration; + + transaction.startChild({ + description: `${entry.initiatorType} ${resourceName}`, + endTimestamp, + op: 'resource', + startTimestamp, + }); + + return endTimestamp; } /** Create performance navigation related spans */ diff --git a/packages/tracing/src/browser/request.ts b/packages/tracing/src/browser/request.ts index e66dc97606d2..9bc952d91a86 100644 --- a/packages/tracing/src/browser/request.ts +++ b/packages/tracing/src/browser/request.ts @@ -40,9 +40,9 @@ export interface RequestInstrumentationOptions { } /** Data returned from fetch callback */ -interface FetchData { +export interface FetchData { args: any[]; - fetchData: { + fetchData?: { method: string; url: string; // span_id @@ -104,7 +104,7 @@ export function registerRequestInstrumentation(_options?: Partial { - fetchCallback(handlerData, shouldCreateSpan, spans); + _fetchCallback(handlerData, shouldCreateSpan, spans); }, type: 'fetch', }); @@ -123,12 +123,12 @@ export function registerRequestInstrumentation(_options?: Partial boolean, spans: Record, ): void { - if (!shouldCreateSpan(handlerData.fetchData.url) || !handlerData.fetchData) { + if (!handlerData.fetchData || !shouldCreateSpan(handlerData.fetchData.url)) { return; } @@ -154,6 +154,7 @@ function fetchCallback( op: 'http', }); + handlerData.fetchData.__span = span.spanId; spans[span.spanId] = span; const request = (handlerData.args[0] = handlerData.args[0] as string | Request); diff --git a/packages/tracing/src/idletransaction.ts b/packages/tracing/src/idletransaction.ts index 2e0b6cde45ad..c63a24881b85 100644 --- a/packages/tracing/src/idletransaction.ts +++ b/packages/tracing/src/idletransaction.ts @@ -63,7 +63,7 @@ export class IdleTransaction extends Transaction { private _prevHeartbeatString: string | undefined; // Amount of times heartbeat has counted. Will cause transaction to finish after 3 beats. - private _heartbeatCounter: number = 1; + private _heartbeatCounter: number = 0; // We should not use heartbeat if we finished a transaction private _finished: boolean = false; @@ -118,9 +118,7 @@ export class IdleTransaction extends Transaction { 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`, - ); + logger.log(`[Tracing] Transaction finished because of no change for 3 heart beats`); this.setStatus(SpanStatus.DeadlineExceeded); this.setTag('heartbeat', 'failed'); this.finish(); diff --git a/packages/tracing/test/browser/request.test.ts b/packages/tracing/test/browser/request.test.ts index 5e22c6985db7..de6841e83aac 100644 --- a/packages/tracing/test/browser/request.test.ts +++ b/packages/tracing/test/browser/request.test.ts @@ -1,4 +1,25 @@ -import { registerRequestInstrumentation } from '../../src/browser/request'; +import { BrowserClient } from '@sentry/browser'; +import { Hub, makeMain } from '@sentry/hub'; + +import { Span, Transaction } from '../../src'; +import { _fetchCallback, FetchData, registerRequestInstrumentation } from '../../src/browser/request'; +import { addExtensionMethods } from '../../src/hubextensions'; + +declare global { + namespace NodeJS { + // tslint:disable-next-line: completed-docs + interface Global { + // Have to mock out Request because it is not defined in jest environment + Request: Request; + } + } +} + +beforeAll(() => { + addExtensionMethods(); + // @ts-ignore + global.Request = {}; +}); const mockAddInstrumentationHandler = jest.fn(); let mockFetchCallback = jest.fn(); @@ -47,3 +68,91 @@ describe('registerRequestInstrumentation', () => { expect(mockXHRCallback()).toBe(undefined); }); }); + +describe('_fetchCallback()', () => { + let hub: Hub; + let transaction: Transaction; + beforeAll(() => { + hub = new Hub(new BrowserClient({ tracesSampleRate: 1 })); + makeMain(hub); + }); + + beforeEach(() => { + transaction = hub.startTransaction({ name: 'organizations/users/:userid', op: 'pageload' }) as Transaction; + hub.configureScope(scope => scope.setSpan(transaction)); + }); + + it('does not create span if it should not be created', () => { + const shouldCreateSpan = (url: string): boolean => url === '/organizations'; + const data: FetchData = { + args: ['/users'], + fetchData: { + method: 'GET', + url: '/users', + }, + startTimestamp: 1595509730275, + }; + const spans = {}; + + _fetchCallback(data, shouldCreateSpan, spans); + expect(spans).toEqual({}); + }); + + it('does not create span if there is no fetch data', () => { + const shouldCreateSpan = (_: string): boolean => true; + const data: FetchData = { + args: [], + startTimestamp: 1595509730275, + }; + const spans = {}; + + _fetchCallback(data, shouldCreateSpan, spans); + expect(spans).toEqual({}); + }); + + it('creates and finishes fetch span on active transaction', () => { + const shouldCreateSpan = (_: string): boolean => true; + const data: FetchData = { + args: ['/users'], + fetchData: { + method: 'GET', + url: '/users', + }, + startTimestamp: 1595509730275, + }; + const spans: Record = {}; + + // Start fetch request + _fetchCallback(data, shouldCreateSpan, spans); + const spanKey = Object.keys(spans)[0]; + + const fetchSpan = spans[spanKey]; + expect(fetchSpan).toBeInstanceOf(Span); + expect(fetchSpan.data).toEqual({ + method: 'GET', + type: 'fetch', + url: '/users', + }); + expect(fetchSpan.description).toBe('GET /users'); + expect(fetchSpan.op).toBe('http'); + if (data.fetchData) { + expect(data.fetchData.__span).toBeDefined(); + } else { + fail('Fetch data does not exist'); + } + + const newData = { + ...data, + endTimestamp: data.startTimestamp + 12343234, + }; + + // End fetch request + _fetchCallback(newData, shouldCreateSpan, spans); + expect(spans).toEqual({}); + if (transaction.spanRecorder) { + expect(transaction.spanRecorder.spans[1].endTimestamp).toBeDefined(); + } else { + fail('Transaction does not have span recorder'); + } + }); +});