Skip to content

fix: Schedule the execution of the finish to let all the spans being closed first #3022

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 1 commit into from
Nov 4, 2020
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
7 changes: 5 additions & 2 deletions packages/node/src/handlers.ts
Original file line number Diff line number Diff line change
Expand Up @@ -63,8 +63,11 @@ export function tracingHandler(): (
(res as any).__sentry_transaction = transaction;

res.once('finish', () => {
transaction.setHttpStatus(res.statusCode);
transaction.finish();
// We schedule the immediate execution of the `finish` to let all the spans being closed first.
setImmediate(() => {
transaction.setHttpStatus(res.statusCode);
transaction.finish();
});
});

next();
Expand Down
43 changes: 37 additions & 6 deletions packages/node/test/handlers.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -247,7 +247,7 @@ describe('tracingHandler', () => {
expect(transaction).toEqual(expect.objectContaining({ name: `GET ${urlString}`, op: 'http.server' }));
});

it('pulls status code from the response', async () => {
it('pulls status code from the response', done => {
const transaction = new Transaction({ name: 'mockTransaction' });
jest.spyOn(sentryCore, 'startTransaction').mockReturnValue(transaction as TransactionType);
const finishTransaction = jest.spyOn(transaction, 'finish');
Expand All @@ -256,9 +256,12 @@ describe('tracingHandler', () => {
res.statusCode = 200;
res.emit('finish');

expect(finishTransaction).toHaveBeenCalled();
expect(transaction.status).toBe(SpanStatus.Ok);
expect(transaction.tags).toEqual(expect.objectContaining({ 'http.status_code': '200' }));
setImmediate(() => {
expect(finishTransaction).toHaveBeenCalled();
expect(transaction.status).toBe(SpanStatus.Ok);
expect(transaction.tags).toEqual(expect.objectContaining({ 'http.status_code': '200' }));
done();
});
});

it('strips query string from request path', () => {
Expand Down Expand Up @@ -291,14 +294,42 @@ describe('tracingHandler', () => {
expect(transaction?.name).toBe(`GET ${urlString}`);
});

it('closes the transaction when request processing is done', () => {
it('closes the transaction when request processing is done', done => {
const transaction = new Transaction({ name: 'mockTransaction' });
jest.spyOn(sentryCore, 'startTransaction').mockReturnValue(transaction as TransactionType);
const finishTransaction = jest.spyOn(transaction, 'finish');

sentryTracingMiddleware(req, res, next);
res.emit('finish');

setImmediate(() => {
expect(finishTransaction).toHaveBeenCalled();
done();
});
});

it('lets all spans being finished before calling `finish` itself, despite being registered to `res.finish` event first', done => {
const transaction = new Transaction({ name: 'mockTransaction' });
transaction.initSpanRecorder();
const span = transaction.startChild({
description: 'reallyCoolHandler',
op: 'middleware',
});
jest.spyOn(sentryCore, 'startTransaction').mockReturnValue(transaction as TransactionType);
const finishSpan = jest.spyOn(span, 'finish');
const finishTransaction = jest.spyOn(transaction, 'finish');

sentryTracingMiddleware(req, res, next);
res.once('finish', () => {
span.finish();
});
res.emit('finish');

expect(finishTransaction).toHaveBeenCalled();
setImmediate(() => {
expect(finishSpan).toHaveBeenCalled();
expect(finishTransaction).toHaveBeenCalled();
expect(span.endTimestamp).toBeLessThan(transaction.endTimestamp!);
done();
});
});
}); // end describe('tracingHandler')