fix(sveltekit): Ensure sub requests are recorded as child spans of parent request (#11130)

Lms24 · c298lee · commit f6149d8f0715 · 2024-03-22T17:36:54.000-04:00
When switching the SvelteKit server side SDK to `@sentry/node` powered by Otel, the semantics behind `continueTrace` changed as outlined in #11199. TLDR: We previously called `continueTrace` in a nested way when dealing with sub-requests`*` in SvelteKit. In our old Node SDK, this did nothing; in the new SDK, this currently causes a new root span/transaction to be created for the sub request. This patch now ensures that we continue to send sub request spans as child spans of the top-level/parent request.
diff --git a/dev-packages/e2e-tests/test-applications/sveltekit-2/src/routes/+page.svelte b/dev-packages/e2e-tests/test-applications/sveltekit-2/src/routes/+page.svelte
@@ -26,4 +26,7 @@
   <li>
     <a id="redirectLink" href="/redirect1">Redirect</a>
   </li>
+  <li>
+    <a href="/server-load-fetch">Route with nested fetch in server load</a>
+  </li>
 </ul>
diff --git a/dev-packages/e2e-tests/test-applications/sveltekit-2/src/routes/server-load-fetch/+page.server.ts b/dev-packages/e2e-tests/test-applications/sveltekit-2/src/routes/server-load-fetch/+page.server.ts
@@ -0,0 +1,5 @@
+export const load = async ({ fetch }) => {
+  const res = await fetch('/api/users');
+  const data = await res.json();
+  return { data };
+};
diff --git a/dev-packages/e2e-tests/test-applications/sveltekit-2/src/routes/server-load-fetch/+page.svelte b/dev-packages/e2e-tests/test-applications/sveltekit-2/src/routes/server-load-fetch/+page.svelte
@@ -0,0 +1,8 @@
+<script lang="ts">
+  export let data;
+</script>
+
+<main>
+  <h1>Server Load Fetch</h1>
+  <p>{JSON.stringify(data, null, 2)}</p>
+</main>
diff --git a/dev-packages/e2e-tests/test-applications/sveltekit-2/test/performance.server.test.ts b/dev-packages/e2e-tests/test-applications/sveltekit-2/test/performance.server.test.ts
@@ -0,0 +1,35 @@
+import { expect, test } from '@playwright/test';
+import { waitForTransaction } from '../event-proxy-server';
+
+test('server pageload request span has nested request span for sub request', async ({ page }) => {
+  const serverTxnEventPromise = waitForTransaction('sveltekit-2', txnEvent => {
+    return txnEvent?.transaction === 'GET /server-load-fetch';
+  });
+
+  await page.goto('/server-load-fetch');
+
+  const serverTxnEvent = await serverTxnEventPromise;
+  const spans = serverTxnEvent.spans;
+
+  expect(serverTxnEvent).toMatchObject({
+    transaction: 'GET /server-load-fetch',
+    tags: { runtime: 'node' },
+    transaction_info: { source: 'route' },
+    type: 'transaction',
+    contexts: {
+      trace: {
+        op: 'http.server',
+        origin: 'auto.http.sveltekit',
+      },
+    },
+  });
+
+  expect(spans).toEqual(
+    expect.arrayContaining([
+      // load span where the server load function initiates the sub request:
+      expect.objectContaining({ op: 'function.sveltekit.server.load', description: '/server-load-fetch' }),
+      // sub request span:
+      expect.objectContaining({ op: 'http.server', description: 'GET /api/users' }),
+    ]),
+  );
+});
diff --git a/dev-packages/e2e-tests/test-applications/sveltekit/package.json b/dev-packages/e2e-tests/test-applications/sveltekit/package.json
@@ -22,7 +22,7 @@
     "@sentry/utils": "latest || *",
     "@sveltejs/adapter-auto": "^2.0.0",
     "@sveltejs/adapter-node": "^1.2.4",
-    "@sveltejs/kit": "^1.30.3",
+    "@sveltejs/kit": "1.20.5",
     "svelte": "^3.54.0",
     "svelte-check": "^3.0.1",
     "ts-node": "10.9.1",
diff --git a/dev-packages/e2e-tests/test-applications/sveltekit/src/routes/+page.svelte b/dev-packages/e2e-tests/test-applications/sveltekit/src/routes/+page.svelte
@@ -23,4 +23,7 @@
   <li>
     <a href="/universal-load-fetch">Route with fetch in universal load</a>
   </li>
+  <li>
+    <a href="/server-load-fetch">Route with nested fetch in server load</a>
+  </li>
 </ul>
diff --git a/dev-packages/e2e-tests/test-applications/sveltekit/src/routes/server-load-fetch/+page.server.ts b/dev-packages/e2e-tests/test-applications/sveltekit/src/routes/server-load-fetch/+page.server.ts
@@ -0,0 +1,5 @@
+export const load = async ({ fetch }) => {
+  const res = await fetch('/api/users');
+  const data = await res.json();
+  return { data };
+};
diff --git a/dev-packages/e2e-tests/test-applications/sveltekit/src/routes/server-load-fetch/+page.svelte b/dev-packages/e2e-tests/test-applications/sveltekit/src/routes/server-load-fetch/+page.svelte
@@ -0,0 +1,8 @@
+<script lang="ts">
+  export let data;
+</script>
+
+<main>
+  <h1>Server Load Fetch</h1>
+  <p>{JSON.stringify(data, null, 2)}</p>
+</main>
diff --git a/dev-packages/e2e-tests/test-applications/sveltekit/test/performance.server.test.ts b/dev-packages/e2e-tests/test-applications/sveltekit/test/performance.server.test.ts
@@ -0,0 +1,35 @@
+import { expect, test } from '@playwright/test';
+import { waitForTransaction } from '../event-proxy-server';
+
+test('server pageload request span has nested request span for sub request', async ({ page }) => {
+  const serverTxnEventPromise = waitForTransaction('sveltekit', txnEvent => {
+    return txnEvent?.transaction === 'GET /server-load-fetch';
+  });
+
+  await page.goto('/server-load-fetch');
+
+  const serverTxnEvent = await serverTxnEventPromise;
+  const spans = serverTxnEvent.spans;
+
+  expect(serverTxnEvent).toMatchObject({
+    transaction: 'GET /server-load-fetch',
+    tags: { runtime: 'node' },
+    transaction_info: { source: 'route' },
+    type: 'transaction',
+    contexts: {
+      trace: {
+        op: 'http.server',
+        origin: 'auto.http.sveltekit',
+      },
+    },
+  });
+
+  expect(spans).toEqual(
+    expect.arrayContaining([
+      // load span where the server load function initiates the sub request:
+      expect.objectContaining({ op: 'function.sveltekit.server.load', description: '/server-load-fetch' }),
+      // sub request span:
+      expect.objectContaining({ op: 'http.server', description: 'GET /api/users' }),
+    ]),
+  );
+});
diff --git a/packages/sveltekit/src/server/handle.ts b/packages/sveltekit/src/server/handle.ts
@@ -149,15 +149,26 @@ export function sentryHandle(handlerOptions?: SentryHandleOptions): Handle {
   };
 
   const sentryRequestHandler: Handle = input => {
-    // if there is an active span, we know that this handle call is nested and hence
-    // we don't create a new execution context for it.
-    // If we created one, nested server calls would create new root span instead
-    // of adding a child span to the currently active span.
-    if (getActiveSpan()) {
+    // event.isSubRequest was added in SvelteKit 1.21.0 and we can use it to check
+    // if we should create a new execution context or not.
+    // In case of a same-origin `fetch` call within a server`load` function,
+    // SvelteKit will actually just re-enter the `handle` function and set `isSubRequest`
+    // to `true` so that no additional network call is made.
+    // We want the `http.server` span of that nested call to be a child span of the
+    // currently active span instead of a new root span to correctly reflect this
+    // behavior.
+    // As a fallback for Kit < 1.21.0, we check if there is an active span only if there's none,
+    // we create a new execution context.
+    const isSubRequest = typeof input.event.isSubRequest === 'boolean' ? input.event.isSubRequest : !!getActiveSpan();
+
+    if (isSubRequest) {
       return instrumentHandle(input, options);
     }
+
     return withIsolationScope(() => {
-      return instrumentHandle(input, options);
+      // We only call continueTrace in the initial top level request to avoid
+      // creating a new root span for the sub request.
+      return continueTrace(getTracePropagationData(input.event), () => instrumentHandle(input, options));
     });
   };
 
@@ -172,36 +183,32 @@ async function instrumentHandle(
     return resolve(event);
   }
 
-  const { sentryTrace, baggage } = getTracePropagationData(event);
-
-  return continueTrace({ sentryTrace, baggage }, async () => {
-    try {
-      const resolveResult = await startSpan(
-        {
-          op: 'http.server',
-          attributes: {
-            [SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN]: 'auto.http.sveltekit',
-            [SEMANTIC_ATTRIBUTE_SENTRY_SOURCE]: event.route?.id ? 'route' : 'url',
-            'http.method': event.request.method,
-          },
-          name: `${event.request.method} ${event.route?.id || event.url.pathname}`,
-        },
-        async (span?: Span) => {
-          const res = await resolve(event, {
-            transformPageChunk: addSentryCodeToPage(options),
-          });
-          if (span) {
-            setHttpStatus(span, res.status);
-          }
-          return res;
+  try {
+    const resolveResult = await startSpan(
+      {
+        op: 'http.server',
+        attributes: {
+          [SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN]: 'auto.http.sveltekit',
+          [SEMANTIC_ATTRIBUTE_SENTRY_SOURCE]: event.route?.id ? 'route' : 'url',
+          'http.method': event.request.method,
         },
-      );
-      return resolveResult;
-    } catch (e: unknown) {
-      sendErrorToSentry(e);
-      throw e;
-    } finally {
-      await flushIfServerless();
-    }
-  });
+        name: `${event.request.method} ${event.route?.id || event.url.pathname}`,
+      },
+      async (span?: Span) => {
+        const res = await resolve(event, {
+          transformPageChunk: addSentryCodeToPage(options),
+        });
+        if (span) {
+          setHttpStatus(span, res.status);
+        }
+        return res;
+      },
+    );
+    return resolveResult;
+  } catch (e: unknown) {
+    sendErrorToSentry(e);
+    throw e;
+  } finally {
+    await flushIfServerless();
+  }
 }
diff --git a/packages/sveltekit/src/server/load.ts b/packages/sveltekit/src/server/load.ts
@@ -2,15 +2,14 @@ import {
   SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN,
   SEMANTIC_ATTRIBUTE_SENTRY_SOURCE,
   captureException,
-  continueTrace,
   startSpan,
 } from '@sentry/node';
 import { addNonEnumerableProperty, objectify } from '@sentry/utils';
 import type { LoadEvent, ServerLoadEvent } from '@sveltejs/kit';
 
 import type { SentryWrappedFlag } from '../common/utils';
 import { isHttpError, isRedirect } from '../common/utils';
-import { flushIfServerless, getTracePropagationData } from './utils';
+import { flushIfServerless } from './utils';
 
 type PatchedLoadEvent = LoadEvent & SentryWrappedFlag;
 type PatchedServerLoadEvent = ServerLoadEvent & SentryWrappedFlag;
@@ -132,30 +131,26 @@ export function wrapServerLoadWithSentry<T extends (...args: any) => any>(origSe
       // https://github.com/sveltejs/kit/blob/e133aba479fa9ba0e7f9e71512f5f937f0247e2c/packages/kit/src/runtime/server/page/load_data.js#L111C3-L124
       const routeId = event.route && (Object.getOwnPropertyDescriptor(event.route, 'id')?.value as string | undefined);
 
-      const { sentryTrace, baggage } = getTracePropagationData(event);
-
-      return continueTrace({ sentryTrace, baggage }, async () => {
-        try {
-          // We need to await before returning, otherwise we won't catch any errors thrown by the load function
-          return await startSpan(
-            {
-              op: 'function.sveltekit.server.load',
-              attributes: {
-                [SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN]: 'auto.function.sveltekit',
-                [SEMANTIC_ATTRIBUTE_SENTRY_SOURCE]: routeId ? 'route' : 'url',
-                'http.method': event.request.method,
-              },
-              name: routeId ? routeId : event.url.pathname,
+      try {
+        // We need to await before returning, otherwise we won't catch any errors thrown by the load function
+        return await startSpan(
+          {
+            op: 'function.sveltekit.server.load',
+            attributes: {
+              [SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN]: 'auto.function.sveltekit',
+              [SEMANTIC_ATTRIBUTE_SENTRY_SOURCE]: routeId ? 'route' : 'url',
+              'http.method': event.request.method,
             },
-            () => wrappingTarget.apply(thisArg, args),
-          );
-        } catch (e: unknown) {
-          sendErrorToSentry(e);
-          throw e;
-        } finally {
-          await flushIfServerless();
-        }
-      });
+            name: routeId ? routeId : event.url.pathname,
+          },
+          () => wrappingTarget.apply(thisArg, args),
+        );
+      } catch (e: unknown) {
+        sendErrorToSentry(e);
+        throw e;
+      } finally {
+        await flushIfServerless();
+      }
     },
   });
 }
diff --git a/packages/sveltekit/test/server/handle.test.ts b/packages/sveltekit/test/server/handle.test.ts
@@ -43,7 +43,6 @@ function mockEvent(override: Record<string, unknown> = {}): Parameters<Handle>[0
     isDataRequest: false,
 
     ...override,
-    isSubRequest: false,
   };
 
   return event;
@@ -118,7 +117,6 @@ describe('sentryHandle', () => {
         response = await sentryHandle()({ event: mockEvent(), resolve: resolve(type, isError) });
       } catch (e) {
         expect(e).toBeInstanceOf(Error);
-        // @ts-expect-error - this is fine
         expect(e.message).toEqual(type);
       }
 
@@ -152,6 +150,53 @@ describe('sentryHandle', () => {
       expect(spans).toHaveLength(1);
     });
 
+    it('[kit>=1.21.0] creates a child span for nested server calls (i.e. if there is an active span)', async () => {
+      let _span: Span | undefined = undefined;
+      let txnCount = 0;
+      client.on('spanEnd', span => {
+        if (span === getRootSpan(span)) {
+          _span = span;
+          ++txnCount;
+        }
+      });
+
+      try {
+        await sentryHandle()({
+          event: mockEvent(),
+          resolve: async _ => {
+            // simulateing a nested load call:
+            await sentryHandle()({
+              event: mockEvent({ route: { id: 'api/users/details/[id]', isSubRequest: true } }),
+              resolve: resolve(type, isError),
+            });
+            return mockResponse;
+          },
+        });
+      } catch (e) {
+        //
+      }
+
+      expect(txnCount).toEqual(1);
+      expect(_span!).toBeDefined();
+
+      expect(spanToJSON(_span!).description).toEqual('GET /users/[id]');
+      expect(spanToJSON(_span!).op).toEqual('http.server');
+      expect(spanToJSON(_span!).status).toEqual(isError ? 'internal_error' : 'ok');
+      expect(spanToJSON(_span!).data?.[SEMANTIC_ATTRIBUTE_SENTRY_SOURCE]).toEqual('route');
+
+      expect(spanToJSON(_span!).timestamp).toBeDefined();
+
+      const spans = getSpanDescendants(_span!).map(spanToJSON);
+
+      expect(spans).toHaveLength(2);
+      expect(spans).toEqual(
+        expect.arrayContaining([
+          expect.objectContaining({ op: 'http.server', description: 'GET /users/[id]' }),
+          expect.objectContaining({ op: 'http.server', description: 'GET api/users/details/[id]' }),
+        ]),
+      );
+    });
+
     it('creates a child span for nested server calls (i.e. if there is an active span)', async () => {
       let _span: Span | undefined = undefined;
       let txnCount = 0;
diff --git a/packages/sveltekit/test/server/load.test.ts b/packages/sveltekit/test/server/load.test.ts
