fix: Make sure fetch requests are being timed correctly (#2772)

Author: AbhiPrasad

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
 

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`,

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();
       }

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 */

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<RequestInstrum
   if (traceFetch) {
     addInstrumentationHandler({
       callback: (handlerData: FetchData) => {
-        fetchCallback(handlerData, shouldCreateSpan, spans);
+        _fetchCallback(handlerData, shouldCreateSpan, spans);
       },
       type: 'fetch',
     });
@@ -123,12 +123,12 @@ export function registerRequestInstrumentation(_options?: Partial<RequestInstrum
 /**
  * Create and track fetch request spans
  */
-function fetchCallback(
+export function _fetchCallback(
   handlerData: FetchData,
   shouldCreateSpan: (url: string) => boolean,
   spans: Record<string, Span>,
 ): 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);

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();

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<string, Span> = {};
+
+    // 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');
+    }
+  });
+});