diff --git a/packages/node/src/handlers.ts b/packages/node/src/handlers.ts index c4af0ed2bbab..bcdb94467353 100644 --- a/packages/node/src/handlers.ts +++ b/packages/node/src/handlers.ts @@ -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(); diff --git a/packages/node/test/handlers.test.ts b/packages/node/test/handlers.test.ts index b88648860e97..7e995d7e8d6b 100644 --- a/packages/node/test/handlers.test.ts +++ b/packages/node/test/handlers.test.ts @@ -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'); @@ -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', () => { @@ -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')