Skip to content

fix(remix): Use domains to prevent scope bleed #5570

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 23 commits into from
Aug 16, 2022
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
23 commits
Select commit Hold shift + click to select a range
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
32 changes: 19 additions & 13 deletions packages/remix/src/utils/instrumentServer.ts
Original file line number Diff line number Diff line change
@@ -1,8 +1,9 @@
/* eslint-disable max-lines */
import { captureException, getCurrentHub } from '@sentry/node';
import { getActiveTransaction, hasTracingEnabled, Span } from '@sentry/tracing';
import { WrappedFunction } from '@sentry/types';
import { captureException, getCurrentHub, Hub } from '@sentry/node';
import { getActiveTransaction, hasTracingEnabled } from '@sentry/tracing';
import { Transaction, WrappedFunction } from '@sentry/types';
import { addExceptionMechanism, fill, isNodeEnv, loadModule, logger, serializeBaggage } from '@sentry/utils';
import * as domain from 'domain';

import {
AppData,
Expand Down Expand Up @@ -291,9 +292,9 @@ export function startRequestHandlerTransaction(
url: URL,
method: string,
routes: ServerRoute[],
hub: Hub,
pkg?: ReactRouterDomPkg,
): Span | undefined {
const hub = getCurrentHub();
): Transaction {
const currentScope = hub.getScope();
const matches = matchServerRoutes(routes, url.pathname, pkg);

Expand All @@ -311,24 +312,28 @@ export function startRequestHandlerTransaction(
},
});

if (transaction) {
currentScope?.setSpan(transaction);
}
currentScope?.setSpan(transaction);
return transaction;
}

function wrapRequestHandler(origRequestHandler: RequestHandler, build: ServerBuild): RequestHandler {
const routes = createRoutes(build.routes);
const pkg = loadModule<ReactRouterDomPkg>('react-router-dom');
return async function (this: unknown, request: Request, loadContext?: unknown): Promise<Response> {
const url = new URL(request.url);
const hub = getCurrentHub();
const options = hub.getClient()?.getOptions();

const transaction = startRequestHandlerTransaction(url, request.method, routes, pkg);
if (!options || !hasTracingEnabled(options)) {
return origRequestHandler.call(this, request, loadContext);
}

const url = new URL(request.url);
const transaction = startRequestHandlerTransaction(url, request.method, routes, hub, pkg);

const res = (await origRequestHandler.call(this, request, loadContext)) as Response;

transaction?.setHttpStatus(res.status);
transaction?.finish();
transaction.setHttpStatus(res.status);
transaction.finish();

return res;
};
Expand Down Expand Up @@ -416,7 +421,8 @@ function makeWrappedCreateRequestHandler(
const newBuild = instrumentBuild(build);
const requestHandler = origCreateRequestHandler.call(this, newBuild, ...args);

return wrapRequestHandler(requestHandler, newBuild);
const local = domain.create();
return local.bind(() => wrapRequestHandler(requestHandler, newBuild))();
};
}

Expand Down
95 changes: 84 additions & 11 deletions packages/remix/src/utils/serverAdapters/express.ts
Original file line number Diff line number Diff line change
@@ -1,4 +1,9 @@
import { extractRequestData, loadModule } from '@sentry/utils';
import { getCurrentHub } from '@sentry/hub';
import { flush } from '@sentry/node';
import { hasTracingEnabled } from '@sentry/tracing';
import { Transaction } from '@sentry/types';
import { extractRequestData, loadModule, logger } from '@sentry/utils';
import * as domain from 'domain';

import {
createRoutes,
Expand Down Expand Up @@ -35,20 +40,26 @@ function wrapExpressRequestHandler(
res: ExpressResponse,
next: ExpressNextFunction,
): Promise<void> {
const request = extractRequestData(req);
// eslint-disable-next-line @typescript-eslint/unbound-method
res.end = wrapEndMethod(res.end);

if (!request.url || !request.method) {
return origRequestHandler.call(this, req, res, next);
}
const local = domain.create();
local.add(req);
local.add(res);

const url = new URL(request.url);
local.run(async () => {
const request = extractRequestData(req);
const hub = getCurrentHub();
const options = hub.getClient()?.getOptions();

const transaction = startRequestHandlerTransaction(url, request.method, routes, pkg);
if (!options || !hasTracingEnabled(options) || !request.url || !request.method) {
return origRequestHandler.call(this, req, res, next);
}

await origRequestHandler.call(this, req, res, next);

transaction?.setHttpStatus(res.statusCode);
transaction?.finish();
const url = new URL(request.url);
startRequestHandlerTransaction(url, request.method, routes, hub, pkg);
await origRequestHandler.call(this, req, res, next);
});
};
}

Expand All @@ -57,11 +68,73 @@ function wrapExpressRequestHandler(
*/
export function wrapExpressCreateRequestHandler(
origCreateRequestHandler: ExpressCreateRequestHandler,
// eslint-disable-next-line @typescript-eslint/no-explicit-any
): (options: any) => ExpressRequestHandler {
// eslint-disable-next-line @typescript-eslint/no-explicit-any
return function (this: unknown, options: any): ExpressRequestHandler {
const newBuild = instrumentBuild((options as ExpressCreateRequestHandlerOptions).build);
const requestHandler = origCreateRequestHandler.call(this, { ...options, build: newBuild });

return wrapExpressRequestHandler(requestHandler, newBuild);
};
}

export type AugmentedExpressResponse = ExpressResponse & {
__sentryTransaction?: Transaction;
};

type ResponseEndMethod = AugmentedExpressResponse['end'];
type WrappedResponseEndMethod = AugmentedExpressResponse['end'];

/**
* Wrap `res.end()` so that it closes the transaction and flushes events before letting the request finish.
*
* Note: This wraps a sync method with an async method. While in general that's not a great idea in terms of keeping
* things in the right order, in this case it's safe, because the native `.end()` actually *is* async, and its run
* actually *is* awaited, just manually so (which reflects the fact that the core of the request/response code in Node
* by far predates the introduction of `async`/`await`). When `.end()` is done, it emits the `prefinish` event, and
* only once that fires does request processing continue. See
* https://github.com/nodejs/node/commit/7c9b607048f13741173d397795bac37707405ba7.
*
* @param origEnd The original `res.end()` method
* @returns The wrapped version
*/
function wrapEndMethod(origEnd: ResponseEndMethod): WrappedResponseEndMethod {
return async function newEnd(this: AugmentedExpressResponse, ...args: unknown[]) {
await finishSentryProcessing(this);

return origEnd.call(this, ...args);
};
}

/**
* Close the open transaction (if any) and flush events to Sentry.
*
* @param res The outgoing response for this request, on which the transaction is stored
*/
async function finishSentryProcessing(res: AugmentedExpressResponse): Promise<void> {
const { __sentryTransaction: transaction } = res;

if (transaction) {
transaction.setHttpStatus(res.statusCode);

// Push `transaction.finish` to the next event loop so open spans have a better chance of finishing before the
// transaction closes, and make sure to wait until that's done before flushing events
await new Promise(resolve => {
setImmediate(() => {
transaction.finish();
resolve();
});
});
}

// Flush the event queue to ensure that events get sent to Sentry before the response is finished and the lambda
// ends. If there was an error, rethrow it so that the normal exception-handling mechanisms can apply.
try {
__DEBUG_BUILD__ && logger.log('Flushing events...');
await flush(2000);
__DEBUG_BUILD__ && logger.log('Done flushing events');
} catch (e) {
__DEBUG_BUILD__ && logger.log('Error while flushing events:\n', e);
}
}
18 changes: 18 additions & 0 deletions packages/remix/test/integration/app/routes/scope-bleed/$id.tsx
Original file line number Diff line number Diff line change
@@ -0,0 +1,18 @@
import { json, LoaderFunction } from '@remix-run/node';

import * as Sentry from '@sentry/remix';

export const loader: LoaderFunction = async ({ params: { id } }) => {
const timeTil = parseInt(id || '', 10) * 1000;
await new Promise(resolve => setTimeout(resolve, 3000 - timeTil));
Sentry.setTag(`tag${id}`, id);
return json({ test: 'test' });
};

export default function ScopeBleed() {
return (
<div>
<h1>Hello</h1>
</div>
);
}
46 changes: 40 additions & 6 deletions packages/remix/test/integration/test/server/loader.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -14,13 +14,12 @@ describe.each(['builtin', 'express'])('Remix API Loaders with adapter = %s', ada
const config = await runServer(adapter);
const url = `${config.url}/loader-json-response/-2`;

let [transaction, event] = await getMultipleEnvelopeRequest({ ...config, url }, { count: 2 });
const envelopes = await getMultipleEnvelopeRequest({ ...config, url }, { count: 2 });

// The event envelope is returned before the transaction envelope when using express adapter.
// We can update this when we merge the envelope filtering utility.
adapter === 'express' && ([event, transaction] = [transaction, event]);
const event = envelopes[0][2].type === 'transaction' ? envelopes[1][2] : envelopes[0][2];
const transaction = envelopes[0][2].type === 'transaction' ? envelopes[0][2] : envelopes[1][2];

assertSentryTransaction(transaction[2], {
assertSentryTransaction(transaction, {
contexts: {
trace: {
status: 'internal_error',
Expand All @@ -31,7 +30,7 @@ describe.each(['builtin', 'express'])('Remix API Loaders with adapter = %s', ada
},
});

assertSentryEvent(event[2], {
assertSentryEvent(event, {
exception: {
values: [
{
Expand Down Expand Up @@ -136,4 +135,39 @@ describe.each(['builtin', 'express'])('Remix API Loaders with adapter = %s', ada
},
});
});

it('makes sure scope does not bleed between requests', async () => {
Copy link
Member

Choose a reason for hiding this comment

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

Did this test previously fail? IOW, would it actually detect scope bleed if we were to accidentally re-introduce it?

Copy link
Member Author

Choose a reason for hiding this comment

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

This test did previously fail - but now it seems to be sometimes passing 🤔, worried it's a flaky test then. @lobsterkatie any ideas for a good test against scope bleed?

Copy link
Member

Choose a reason for hiding this comment

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

Hmmm... I would assume we basically have to force them to be simultaneous, right? This test would pass regardless, as long as there were only one request/transaction at at time, so maybe the flakiness is coming from the requests just getting through so quickly that they end up being sequential. Could you introduce a variable delay into each request, and set them off at a set interval, to guarantee they'd all be in flight at the same time? I'm picturing something like (assuming 5 requests):

Request 1: Starts at timestamp 0, waits 5 seconds to set its tag, waits another second, finishes
Request 2: Starts at timestamp 1 second, waits 4 seconds to set its tag, waits another second, finishes
...
Request 5: Starts at timestamp 4 seconds, waits 1 second to set its tag, waits another second, finishes

That way, you know that 5 seconds in, all five requests should be trying to set their tags more or less at the same moment, and should also all be finishing at more or less the same time (meaning they'd all be trying to grab scope data to attach to the event roughly simultaneously).

(You might also consider introducing a tiny bit of randomness (wait anywhere between 0.99 and 1.01 seconds to start each request, and the do it again for finishing, for example), just so that the order in which requests set and get their tags is mixed up.)

If everything still comes through cleanly, then I think we'd've proved the point, right?

Copy link
Member Author

Choose a reason for hiding this comment

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

Yup, and we've tested on express as well. Thanks Katie, used a simple version of your logic here.

I tried the randomness, but it wasn't working that well, so elected to do this.

const { url, server, scope } = await runServer(adapter);

const envelopes = await Promise.all([
getEnvelopeRequest({ url: `${url}/scope-bleed/1`, server, scope }, { endServer: false }),
getEnvelopeRequest({ url: `${url}/scope-bleed/2`, server, scope }, { endServer: false }),
getEnvelopeRequest({ url: `${url}/scope-bleed/3`, server, scope }, { endServer: false }),
getEnvelopeRequest({ url: `${url}/scope-bleed/4`, server, scope }, { endServer: false }),
]);

scope.persist(false);
await new Promise(resolve => server.close(resolve));

assertSentryTransaction(envelopes[0][2], {
tags: {
tag4: '4',
},
});
assertSentryTransaction(envelopes[1][2], {
tags: {
tag3: '3',
},
});
assertSentryTransaction(envelopes[2][2], {
tags: {
tag2: '2',
},
});
assertSentryTransaction(envelopes[3][2], {
tags: {
tag1: '1',
},
});
});
});