Skip to content

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 11 commits into from
Mar 22, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Original file line number Diff line number Diff line change
@@ -0,0 +1,5 @@
export const load = async ({ fetch }) => {
const res = await fetch('/api/users');
const data = await res.json();
return { data };
};
Original file line number Diff line number Diff line change
@@ -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>
Original file line number Diff line number Diff line change
@@ -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' }),
]),
);
});
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Original file line number Diff line number Diff line change
@@ -0,0 +1,5 @@
export const load = async ({ fetch }) => {
const res = await fetch('/api/users');
const data = await res.json();
return { data };
};
Original file line number Diff line number Diff line change
@@ -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>
Original file line number Diff line number Diff line change
@@ -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' }),
]),
);
});
81 changes: 44 additions & 37 deletions packages/sveltekit/src/server/handle.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am worried about sveltekit 1 here because shouldn't there always be a span with the OTEL http instrumentation? Or was it that the http integration doesn't work in sveltekit?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The http integration doesn't seem to do anything in Kit :(
But you're raising a good point. I'll check what getActiveSpan now returns going forward. i.e. if it returns something like a NonRecordingSpan if there previously was no span. In that case, we need to rework the check a bit.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I checked for Kit < 1.21.0 and we still return undefined in this case. So the logic works correctly here. To make sure we cover this correctly in the future, I downgraded to kit 1.20.5 in our Kit 1.x E2E test version.

// we create a new execution context.
const isSubRequest = typeof input.event.isSubRequest === 'boolean' ? input.event.isSubRequest : !!getActiveSpan();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yo this is surprisingly convenient 😂

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah I was really happy when I found sveltejs/kit#10170 😅


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

Expand All @@ -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();
}
}
45 changes: 20 additions & 25 deletions packages/sveltekit/src/server/load.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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();
}
},
});
}
49 changes: 47 additions & 2 deletions packages/sveltekit/test/server/handle.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -43,7 +43,6 @@ function mockEvent(override: Record<string, unknown> = {}): Parameters<Handle>[0
isDataRequest: false,

...override,
isSubRequest: false,
};

return event;
Expand Down Expand Up @@ -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);
}

Expand Down Expand Up @@ -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;
Expand Down
Loading