From 03257e09cf959a79ecc0a142e2946ebec53e760e Mon Sep 17 00:00:00 2001 From: Charly Gomez Date: Mon, 29 Jul 2024 16:12:23 +0200 Subject: [PATCH] feat(core): Adapt spans for client-side fetch to streaming responses (#12723) --- .size-limit.js | 6 +- .../react-router-6/package.json | 8 +- .../react-router-6/server/app.js | 47 ++++++ .../react-router-6/src/index.tsx | 2 + .../react-router-6/src/pages/SSE.tsx | 49 ++++++ .../react-router-6/tests/sse.test.ts | 69 +++++++++ .../src/tracing/browserTracingIntegration.ts | 2 +- packages/browser/src/tracing/request.ts | 37 ++++- .../browser/test/unit/tracing/request.test.ts | 18 ++- .../client/browserTracingIntegration.test.ts | 2 +- packages/utils/src/instrument/fetch.ts | 141 ++++++++++++++---- packages/utils/src/instrument/handlers.ts | 10 +- packages/utils/src/instrument/index.ts | 3 +- 13 files changed, 349 insertions(+), 45 deletions(-) create mode 100644 dev-packages/e2e-tests/test-applications/react-router-6/server/app.js create mode 100644 dev-packages/e2e-tests/test-applications/react-router-6/src/pages/SSE.tsx create mode 100644 dev-packages/e2e-tests/test-applications/react-router-6/tests/sse.test.ts diff --git a/.size-limit.js b/.size-limit.js index 97a8376b65da..dc85fffe40af 100644 --- a/.size-limit.js +++ b/.size-limit.js @@ -15,7 +15,7 @@ module.exports = [ path: 'packages/browser/build/npm/esm/index.js', import: createImport('init', 'browserTracingIntegration'), gzip: true, - limit: '35 KB', + limit: '36 KB', }, { name: '@sentry/browser (incl. Tracing, Replay)', @@ -29,7 +29,7 @@ module.exports = [ path: 'packages/browser/build/npm/esm/index.js', import: createImport('init', 'browserTracingIntegration', 'replayIntegration'), gzip: true, - limit: '65 KB', + limit: '66 KB', modifyWebpackConfig: function (config) { const webpack = require('webpack'); config.plugins.push( @@ -107,7 +107,7 @@ module.exports = [ import: createImport('init', 'ErrorBoundary', 'reactRouterV6BrowserTracingIntegration'), ignore: ['react/jsx-runtime'], gzip: true, - limit: '38 KB', + limit: '39 KB', }, // Vue SDK (ESM) { diff --git a/dev-packages/e2e-tests/test-applications/react-router-6/package.json b/dev-packages/e2e-tests/test-applications/react-router-6/package.json index 3053b0a7c137..5171a89eadb3 100644 --- a/dev-packages/e2e-tests/test-applications/react-router-6/package.json +++ b/dev-packages/e2e-tests/test-applications/react-router-6/package.json @@ -6,6 +6,7 @@ "@sentry/react": "latest || *", "@types/react": "18.0.0", "@types/react-dom": "18.0.0", + "express": "4.19.2", "react": "18.2.0", "react-dom": "18.2.0", "react-router-dom": "^6.4.1", @@ -14,7 +15,9 @@ }, "scripts": { "build": "react-scripts build", - "start": "serve -s build", + "start": "run-p start:client start:server", + "start:client": "node server/app.js", + "start:server": "serve -s build", "test": "playwright test", "clean": "npx rimraf node_modules pnpm-lock.yaml", "test:build": "pnpm install && npx playwright install && pnpm build", @@ -43,7 +46,8 @@ "devDependencies": { "@playwright/test": "^1.44.1", "@sentry-internal/test-utils": "link:../../../test-utils", - "serve": "14.0.1" + "serve": "14.0.1", + "npm-run-all2": "^6.2.0" }, "volta": { "extends": "../../package.json" diff --git a/dev-packages/e2e-tests/test-applications/react-router-6/server/app.js b/dev-packages/e2e-tests/test-applications/react-router-6/server/app.js new file mode 100644 index 000000000000..5a8cdb3929a1 --- /dev/null +++ b/dev-packages/e2e-tests/test-applications/react-router-6/server/app.js @@ -0,0 +1,47 @@ +const express = require('express'); + +const app = express(); +const PORT = 8080; + +const wait = time => { + return new Promise(resolve => { + setTimeout(() => { + resolve(); + }, time); + }); +}; + +async function sseHandler(request, response, timeout = false) { + response.headers = { + 'Content-Type': 'text/event-stream', + Connection: 'keep-alive', + 'Cache-Control': 'no-cache', + 'Access-Control-Allow-Origin': '*', + }; + + response.setHeader('Cache-Control', 'no-cache'); + response.setHeader('Content-Type', 'text/event-stream'); + response.setHeader('Access-Control-Allow-Origin', '*'); + response.setHeader('Connection', 'keep-alive'); + + response.flushHeaders(); + + await wait(2000); + + for (let index = 0; index < 10; index++) { + response.write(`data: ${new Date().toISOString()}\n\n`); + if (timeout) { + await wait(10000); + } + } + + response.end(); +} + +app.get('/sse', (req, res) => sseHandler(req, res)); + +app.get('/sse-timeout', (req, res) => sseHandler(req, res, true)); + +app.listen(PORT, () => { + console.log(`SSE service listening at http://localhost:${PORT}`); +}); diff --git a/dev-packages/e2e-tests/test-applications/react-router-6/src/index.tsx b/dev-packages/e2e-tests/test-applications/react-router-6/src/index.tsx index 601ac10a084b..434c1677bf88 100644 --- a/dev-packages/e2e-tests/test-applications/react-router-6/src/index.tsx +++ b/dev-packages/e2e-tests/test-applications/react-router-6/src/index.tsx @@ -11,6 +11,7 @@ import { useNavigationType, } from 'react-router-dom'; import Index from './pages/Index'; +import SSE from './pages/SSE'; import User from './pages/User'; const replay = Sentry.replayIntegration(); @@ -48,6 +49,7 @@ root.render( } /> } /> + } /> , ); diff --git a/dev-packages/e2e-tests/test-applications/react-router-6/src/pages/SSE.tsx b/dev-packages/e2e-tests/test-applications/react-router-6/src/pages/SSE.tsx new file mode 100644 index 000000000000..49e53b09cfa2 --- /dev/null +++ b/dev-packages/e2e-tests/test-applications/react-router-6/src/pages/SSE.tsx @@ -0,0 +1,49 @@ +import * as Sentry from '@sentry/react'; +// biome-ignore lint/nursery/noUnusedImports: Need React import for JSX +import * as React from 'react'; + +const fetchSSE = async ({ timeout }: { timeout: boolean }) => { + Sentry.startSpanManual({ name: 'sse stream using fetch' }, async span => { + const res = await Sentry.startSpan({ name: 'sse fetch call' }, async () => { + const endpoint = `http://localhost:8080/${timeout ? 'sse-timeout' : 'sse'}`; + return await fetch(endpoint); + }); + + const stream = res.body; + const reader = stream?.getReader(); + + const readChunk = async () => { + const readRes = await reader?.read(); + if (readRes?.done) { + return; + } + + new TextDecoder().decode(readRes?.value); + + await readChunk(); + }; + + try { + await readChunk(); + } catch (error) { + console.error('Could not fetch sse', error); + } + + span.end(); + }); +}; + +const SSE = () => { + return ( + <> + + + + ); +}; + +export default SSE; diff --git a/dev-packages/e2e-tests/test-applications/react-router-6/tests/sse.test.ts b/dev-packages/e2e-tests/test-applications/react-router-6/tests/sse.test.ts new file mode 100644 index 000000000000..5d4533726e36 --- /dev/null +++ b/dev-packages/e2e-tests/test-applications/react-router-6/tests/sse.test.ts @@ -0,0 +1,69 @@ +import { expect, test } from '@playwright/test'; +import { waitForTransaction } from '@sentry-internal/test-utils'; +import { SpanJSON } from '@sentry/types'; + +test('Waits for sse streaming when creating spans', async ({ page }) => { + await page.goto('/sse'); + + const transactionPromise = waitForTransaction('react-router-6', async transactionEvent => { + return !!transactionEvent?.transaction && transactionEvent.contexts?.trace?.op === 'pageload'; + }); + + const fetchButton = page.locator('id=fetch-button'); + await fetchButton.click(); + + const rootSpan = await transactionPromise; + const sseFetchCall = rootSpan.spans?.filter(span => span.description === 'sse fetch call')[0] as SpanJSON; + const httpGet = rootSpan.spans?.filter(span => span.description === 'GET http://localhost:8080/sse')[0] as SpanJSON; + + expect(sseFetchCall).toBeDefined(); + expect(httpGet).toBeDefined(); + + expect(sseFetchCall?.timestamp).toBeDefined(); + expect(sseFetchCall?.start_timestamp).toBeDefined(); + expect(httpGet?.timestamp).toBeDefined(); + expect(httpGet?.start_timestamp).toBeDefined(); + + // http headers get sent instantly from the server + const resolveDuration = Math.round((sseFetchCall.timestamp as number) - sseFetchCall.start_timestamp); + + // body streams after 2s + const resolveBodyDuration = Math.round((httpGet.timestamp as number) - httpGet.start_timestamp); + + expect(resolveDuration).toBe(0); + expect(resolveBodyDuration).toBe(2); +}); + +test('Aborts when stream takes longer than 5s', async ({ page }) => { + await page.goto('/sse'); + + const transactionPromise = waitForTransaction('react-router-6', async transactionEvent => { + return !!transactionEvent?.transaction && transactionEvent.contexts?.trace?.op === 'pageload'; + }); + + const fetchButton = page.locator('id=fetch-timeout-button'); + await fetchButton.click(); + + const rootSpan = await transactionPromise; + const sseFetchCall = rootSpan.spans?.filter(span => span.description === 'sse fetch call')[0] as SpanJSON; + const httpGet = rootSpan.spans?.filter( + span => span.description === 'GET http://localhost:8080/sse-timeout', + )[0] as SpanJSON; + + expect(sseFetchCall).toBeDefined(); + expect(httpGet).toBeDefined(); + + expect(sseFetchCall?.timestamp).toBeDefined(); + expect(sseFetchCall?.start_timestamp).toBeDefined(); + expect(httpGet?.timestamp).toBeDefined(); + expect(httpGet?.start_timestamp).toBeDefined(); + + // http headers get sent instantly from the server + const resolveDuration = Math.round((sseFetchCall.timestamp as number) - sseFetchCall.start_timestamp); + + // body streams after 10s but client should abort reading after 5s + const resolveBodyDuration = Math.round((httpGet.timestamp as number) - httpGet.start_timestamp); + + expect(resolveDuration).toBe(0); + expect(resolveBodyDuration).toBe(7); +}); diff --git a/packages/browser/src/tracing/browserTracingIntegration.ts b/packages/browser/src/tracing/browserTracingIntegration.ts index 9d5421f697cd..d8f6796b5b1b 100644 --- a/packages/browser/src/tracing/browserTracingIntegration.ts +++ b/packages/browser/src/tracing/browserTracingIntegration.ts @@ -398,7 +398,7 @@ export const browserTracingIntegration = ((_options: Partial(); +const spanIdToEndTimestamp = new Map(); + export const defaultRequestInstrumentationOptions: RequestInstrumentationOptions = { traceFetch: true, traceXHR: true, @@ -100,7 +104,7 @@ export const defaultRequestInstrumentationOptions: RequestInstrumentationOptions }; /** Registers span creators for xhr and fetch requests */ -export function instrumentOutgoingRequests(_options?: Partial): void { +export function instrumentOutgoingRequests(client: Client, _options?: Partial): void { const { traceFetch, traceXHR, shouldCreateSpanForRequest, enableHTTPTimings, tracePropagationTargets } = { traceFetch: defaultRequestInstrumentationOptions.traceFetch, traceXHR: defaultRequestInstrumentationOptions.traceXHR, @@ -115,8 +119,39 @@ export function instrumentOutgoingRequests(_options?: Partial = {}; if (traceFetch) { + // Keeping track of http requests, whose body payloads resolved later than the intial resolved request + // e.g. streaming using server sent events (SSE) + client.addEventProcessor(event => { + if (event.type === 'transaction' && event.spans) { + event.spans.forEach(span => { + if (span.op === 'http.client') { + const updatedTimestamp = spanIdToEndTimestamp.get(span.span_id); + if (updatedTimestamp) { + span.timestamp = updatedTimestamp / 1000; + spanIdToEndTimestamp.delete(span.span_id); + } + } + }); + } + return event; + }); + + addFetchEndInstrumentationHandler(handlerData => { + if (handlerData.response) { + const span = responseToSpanId.get(handlerData.response); + if (span && handlerData.endTimestamp) { + spanIdToEndTimestamp.set(span, handlerData.endTimestamp); + } + } + }); + addFetchInstrumentationHandler(handlerData => { const createdSpan = instrumentFetchRequest(handlerData, shouldCreateSpan, shouldAttachHeadersWithTargets, spans); + + if (handlerData.response && handlerData.fetchData.__span) { + responseToSpanId.set(handlerData.response, handlerData.fetchData.__span); + } + // We cannot use `window.location` in the generic fetch instrumentation, // but we need it for reliable `server.address` attribute. // so we extend this in here diff --git a/packages/browser/test/unit/tracing/request.test.ts b/packages/browser/test/unit/tracing/request.test.ts index 47174c7d9016..384d62bf52e2 100644 --- a/packages/browser/test/unit/tracing/request.test.ts +++ b/packages/browser/test/unit/tracing/request.test.ts @@ -1,4 +1,5 @@ import * as browserUtils from '@sentry-internal/browser-utils'; +import type { Client } from '@sentry/types'; import * as utils from '@sentry/utils'; import { WINDOW } from '../../../src/helpers'; @@ -10,16 +11,27 @@ beforeAll(() => { global.Request = {}; }); +class MockClient implements Partial { + public addEventProcessor: () => void; + constructor() { + // Mock addEventProcessor function + this.addEventProcessor = jest.fn(); + } +} + describe('instrumentOutgoingRequests', () => { + let client: Client; + beforeEach(() => { jest.clearAllMocks(); + client = new MockClient() as unknown as Client; }); it('instruments fetch and xhr requests', () => { const addFetchSpy = jest.spyOn(utils, 'addFetchInstrumentationHandler'); const addXhrSpy = jest.spyOn(browserUtils, 'addXhrInstrumentationHandler'); - instrumentOutgoingRequests(); + instrumentOutgoingRequests(client); expect(addFetchSpy).toHaveBeenCalledWith(expect.any(Function)); expect(addXhrSpy).toHaveBeenCalledWith(expect.any(Function)); @@ -28,7 +40,7 @@ describe('instrumentOutgoingRequests', () => { it('does not instrument fetch requests if traceFetch is false', () => { const addFetchSpy = jest.spyOn(utils, 'addFetchInstrumentationHandler'); - instrumentOutgoingRequests({ traceFetch: false }); + instrumentOutgoingRequests(client, { traceFetch: false }); expect(addFetchSpy).not.toHaveBeenCalled(); }); @@ -36,7 +48,7 @@ describe('instrumentOutgoingRequests', () => { it('does not instrument xhr requests if traceXHR is false', () => { const addXhrSpy = jest.spyOn(browserUtils, 'addXhrInstrumentationHandler'); - instrumentOutgoingRequests({ traceXHR: false }); + instrumentOutgoingRequests(client, { traceXHR: false }); expect(addXhrSpy).not.toHaveBeenCalled(); }); diff --git a/packages/sveltekit/test/client/browserTracingIntegration.test.ts b/packages/sveltekit/test/client/browserTracingIntegration.test.ts index a8fbaa815af2..6d052cc77b50 100644 --- a/packages/sveltekit/test/client/browserTracingIntegration.test.ts +++ b/packages/sveltekit/test/client/browserTracingIntegration.test.ts @@ -60,7 +60,7 @@ describe('browserTracingIntegration', () => { return createdRootSpan as Span; }); - const fakeClient = { getOptions: () => ({}), on: () => {} }; + const fakeClient = { getOptions: () => ({}), on: () => {}, addEventProcessor: () => {} }; const mockedRoutingSpan = { end: () => {}, diff --git a/packages/utils/src/instrument/fetch.ts b/packages/utils/src/instrument/fetch.ts index 24c435fdf07c..a4df9bd6f807 100644 --- a/packages/utils/src/instrument/fetch.ts +++ b/packages/utils/src/instrument/fetch.ts @@ -21,10 +21,24 @@ type FetchResource = string | { toString(): string } | { url: string }; export function addFetchInstrumentationHandler(handler: (data: HandlerDataFetch) => void): void { const type = 'fetch'; addHandler(type, handler); - maybeInstrument(type, instrumentFetch); + maybeInstrument(type, () => instrumentFetch()); } -function instrumentFetch(): void { +/** + * Add an instrumentation handler for long-lived fetch requests, like consuming server-sent events (SSE) via fetch. + * The handler will resolve the request body and emit the actual `endTimestamp`, so that the + * span can be updated accordingly. + * + * Only used internally + * @hidden + */ +export function addFetchEndInstrumentationHandler(handler: (data: HandlerDataFetch) => void): void { + const type = 'fetch-body-resolved'; + addHandler(type, handler); + maybeInstrument(type, () => instrumentFetch(streamHandler)); +} + +function instrumentFetch(onFetchResolved?: (response: Response) => void): void { if (!supportsNativeFetch()) { return; } @@ -32,7 +46,6 @@ function instrumentFetch(): void { fill(GLOBAL_OBJ, 'fetch', function (originalFetch: () => void): () => void { return function (...args: any[]): void { const { method, url } = parseFetchArgs(args); - const handlerData: HandlerDataFetch = { args, fetchData: { @@ -42,9 +55,12 @@ function instrumentFetch(): void { startTimestamp: timestampInSeconds() * 1000, }; - triggerHandlers('fetch', { - ...handlerData, - }); + // if there is no callback, fetch is instrumented directly + if (!onFetchResolved) { + triggerHandlers('fetch', { + ...handlerData, + }); + } // We capture the stack right here and not in the Promise error callback because Safari (and probably other // browsers too) will wipe the stack trace up to this point, only leaving us with this file which is useless. @@ -57,44 +73,105 @@ function instrumentFetch(): void { // eslint-disable-next-line @typescript-eslint/no-unsafe-member-access return originalFetch.apply(GLOBAL_OBJ, args).then( - (response: Response) => { - const finishedHandlerData: HandlerDataFetch = { - ...handlerData, - endTimestamp: timestampInSeconds() * 1000, - response, - }; - - triggerHandlers('fetch', finishedHandlerData); + async (response: Response) => { + if (onFetchResolved) { + onFetchResolved(response); + } else { + const finishedHandlerData: HandlerDataFetch = { + ...handlerData, + endTimestamp: timestampInSeconds() * 1000, + response, + }; + triggerHandlers('fetch', finishedHandlerData); + } + return response; }, (error: Error) => { - const erroredHandlerData: HandlerDataFetch = { - ...handlerData, - endTimestamp: timestampInSeconds() * 1000, - error, - }; + if (!onFetchResolved) { + const erroredHandlerData: HandlerDataFetch = { + ...handlerData, + endTimestamp: timestampInSeconds() * 1000, + error, + }; + + triggerHandlers('fetch', erroredHandlerData); + + if (isError(error) && error.stack === undefined) { + // NOTE: If you are a Sentry user, and you are seeing this stack frame, + // it means the error, that was caused by your fetch call did not + // have a stack trace, so the SDK backfilled the stack trace so + // you can see which fetch call failed. + error.stack = virtualStackTrace; + addNonEnumerableProperty(error, 'framesToPop', 1); + } - triggerHandlers('fetch', erroredHandlerData); - - if (isError(error) && error.stack === undefined) { // NOTE: If you are a Sentry user, and you are seeing this stack frame, - // it means the error, that was caused by your fetch call did not - // have a stack trace, so the SDK backfilled the stack trace so - // you can see which fetch call failed. - error.stack = virtualStackTrace; - addNonEnumerableProperty(error, 'framesToPop', 1); + // it means the sentry.javascript SDK caught an error invoking your application code. + // This is expected behavior and NOT indicative of a bug with sentry.javascript. + throw error; } - - // NOTE: If you are a Sentry user, and you are seeing this stack frame, - // it means the sentry.javascript SDK caught an error invoking your application code. - // This is expected behavior and NOT indicative of a bug with sentry.javascript. - throw error; }, ); }; }); } +function resolveResponse(res: Response | undefined, onFinishedResolving: () => void): void { + if (res && res.body) { + const responseReader = res.body.getReader(); + + // eslint-disable-next-line no-inner-declarations + async function consumeChunks({ done }: { done: boolean }): Promise { + if (!done) { + try { + // abort reading if read op takes more than 5s + const result = await Promise.race([ + responseReader.read(), + new Promise<{ done: boolean }>(res => { + setTimeout(() => { + res({ done: true }); + }, 5000); + }), + ]); + await consumeChunks(result); + } catch (error) { + // handle error if needed + } + } else { + return Promise.resolve(); + } + } + + responseReader + .read() + .then(consumeChunks) + .then(() => { + onFinishedResolving(); + }) + .catch(() => { + // noop + }); + } +} + +async function streamHandler(response: Response): Promise { + // clone response for awaiting stream + let clonedResponseForResolving: Response | undefined; + try { + clonedResponseForResolving = response.clone(); + } catch (e) { + // noop + } + + await resolveResponse(clonedResponseForResolving, () => { + triggerHandlers('fetch-body-resolved', { + endTimestamp: timestampInSeconds() * 1000, + response, + }); + }); +} + function hasProp(obj: unknown, prop: T): obj is Record { return !!obj && typeof obj === 'object' && !!(obj as Record)[prop]; } diff --git a/packages/utils/src/instrument/handlers.ts b/packages/utils/src/instrument/handlers.ts index 520d258ae1ac..b22f01318b0a 100644 --- a/packages/utils/src/instrument/handlers.ts +++ b/packages/utils/src/instrument/handlers.ts @@ -2,7 +2,15 @@ import { DEBUG_BUILD } from '../debug-build'; import { logger } from '../logger'; import { getFunctionName } from '../stacktrace'; -export type InstrumentHandlerType = 'console' | 'dom' | 'fetch' | 'history' | 'xhr' | 'error' | 'unhandledrejection'; +export type InstrumentHandlerType = + | 'console' + | 'dom' + | 'fetch' + | 'fetch-body-resolved' + | 'history' + | 'xhr' + | 'error' + | 'unhandledrejection'; // eslint-disable-next-line @typescript-eslint/no-explicit-any export type InstrumentHandlerCallback = (data: any) => void; diff --git a/packages/utils/src/instrument/index.ts b/packages/utils/src/instrument/index.ts index ee84f1375522..8a83959c636b 100644 --- a/packages/utils/src/instrument/index.ts +++ b/packages/utils/src/instrument/index.ts @@ -1,5 +1,5 @@ import { addConsoleInstrumentationHandler } from './console'; -import { addFetchInstrumentationHandler } from './fetch'; +import { addFetchEndInstrumentationHandler, addFetchInstrumentationHandler } from './fetch'; import { addGlobalErrorInstrumentationHandler } from './globalError'; import { addGlobalUnhandledRejectionInstrumentationHandler } from './globalUnhandledRejection'; import { addHandler, maybeInstrument, resetInstrumentationHandlers, triggerHandlers } from './handlers'; @@ -14,4 +14,5 @@ export { triggerHandlers, // Only exported for tests resetInstrumentationHandlers, + addFetchEndInstrumentationHandler, };