diff --git a/packages/tracer/src/Tracer.ts b/packages/tracer/src/Tracer.ts index c780ef6f48..41415facfa 100644 --- a/packages/tracer/src/Tracer.ts +++ b/packages/tracer/src/Tracer.ts @@ -406,8 +406,14 @@ class Tracer extends Utility implements TracerInterface { tracerRef.addErrorAsMetadata(error as Error); throw error; } finally { - subsegment?.close(); - subsegment?.flush(); + try { + subsegment?.close(); + } catch (error) { + console.warn( + `Failed to close or serialize segment, ${subsegment?.name}. We are catching the error but data might be lost.`, + error + ); + } } return result; @@ -489,8 +495,14 @@ class Tracer extends Utility implements TracerInterface { throw error; } finally { - subsegment?.close(); - subsegment?.flush(); + try { + subsegment?.close(); + } catch (error) { + console.warn( + `Failed to close or serialize segment, ${subsegment?.name}. We are catching the error but data might be lost.`, + error + ); + } } return result; diff --git a/packages/tracer/src/middleware/middy.ts b/packages/tracer/src/middleware/middy.ts index 1d1a8b63f6..cc0477f01f 100644 --- a/packages/tracer/src/middleware/middy.ts +++ b/packages/tracer/src/middleware/middy.ts @@ -70,7 +70,14 @@ const captureLambdaHandler = ( if (handlerSegment === undefined || lambdaSegment === null) { return; } - handlerSegment.close(); + try { + handlerSegment.close(); + } catch (error) { + console.warn( + `Failed to close or serialize segment, ${handlerSegment.name}. We are catching the error but data might be lost.`, + error + ); + } target.setSegment(lambdaSegment); }; diff --git a/packages/tracer/src/provider/ProviderService.ts b/packages/tracer/src/provider/ProviderService.ts index 380bdc7dd4..271a820310 100644 --- a/packages/tracer/src/provider/ProviderService.ts +++ b/packages/tracer/src/provider/ProviderService.ts @@ -103,6 +103,7 @@ class ProviderService implements ProviderServiceInterface { return; } + segment.addMetadata(key, value, namespace); } diff --git a/packages/tracer/tests/unit/Tracer.test.ts b/packages/tracer/tests/unit/Tracer.test.ts index 983764f65f..df6838ad13 100644 --- a/packages/tracer/tests/unit/Tracer.test.ts +++ b/packages/tracer/tests/unit/Tracer.test.ts @@ -914,6 +914,49 @@ describe('Class: Tracer', () => { otherDummyMethodSpy.mock.invocationCallOrder[0]; expect(otherDummyCallOrder).toBeLessThan(dummyCallOrder); }); + + it('catches the error and logs a warning when a segment fails to close/serialize', async () => { + // Prepare + const tracer: Tracer = new Tracer(); + const handlerSubsegment: Segment | Subsegment | undefined = + new Subsegment('### dummyMethod'); + jest + .spyOn(tracer.provider, 'getSegment') + .mockImplementation(() => handlerSubsegment); + setContextMissingStrategy(() => null); + jest + .spyOn(tracer.provider, 'captureAsyncFunc') + .mockImplementation(async (methodName, callBackFn) => { + await callBackFn(handlerSubsegment); + }); + const logWarningSpy = jest.spyOn(console, 'warn'); + const closeSpy = jest + .spyOn(handlerSubsegment, 'close') + .mockImplementation(() => { + throw new Error('dummy error'); + }); + + class Lambda implements LambdaInterface { + @tracer.captureLambdaHandler() + public async handler( + _event: unknown, + _context: Context + ): Promise { + return 'foo bar'; + } + } + + // Act + await new Lambda().handler(event, context); + + // Assess + expect(closeSpy).toHaveBeenCalledTimes(1); + expect(logWarningSpy).toHaveBeenNthCalledWith( + 1, + `Failed to close or serialize segment, ${handlerSubsegment.name}. We are catching the error but data might be lost.`, + new Error('dummy error') + ); + }); }); describe('Method: captureMethod', () => { @@ -1328,6 +1371,53 @@ describe('Class: Tracer', () => { expect.anything() ); }); + + it('catches the error and logs a warning when a segment fails to close/serialize', async () => { + // Prepare + const tracer: Tracer = new Tracer(); + const handlerSubsegment: Segment | Subsegment | undefined = + new Subsegment('### dummyMethod'); + jest + .spyOn(tracer.provider, 'getSegment') + .mockImplementation(() => handlerSubsegment); + setContextMissingStrategy(() => null); + jest + .spyOn(tracer.provider, 'captureAsyncFunc') + .mockImplementation(async (methodName, callBackFn) => { + await callBackFn(handlerSubsegment); + }); + const logWarningSpy = jest.spyOn(console, 'warn'); + const closeSpy = jest + .spyOn(handlerSubsegment, 'close') + .mockImplementation(() => { + throw new Error('dummy error'); + }); + + class Lambda implements LambdaInterface { + @tracer.captureMethod() + public async dummyMethod(some: string): Promise { + return some; + } + + public async handler( + _event: unknown, + _context: Context + ): Promise { + return await this.dummyMethod('foo bar'); + } + } + + // Act + await new Lambda().handler(event, context); + + // Assess + expect(closeSpy).toHaveBeenCalledTimes(1); + expect(logWarningSpy).toHaveBeenNthCalledWith( + 1, + `Failed to close or serialize segment, ${handlerSubsegment.name}. We are catching the error but data might be lost.`, + new Error('dummy error') + ); + }); }); describe('Method: captureAWS', () => { diff --git a/packages/tracer/tests/unit/middy.test.ts b/packages/tracer/tests/unit/middy.test.ts index 7948817baf..dc7af9d553 100644 --- a/packages/tracer/tests/unit/middy.test.ts +++ b/packages/tracer/tests/unit/middy.test.ts @@ -215,157 +215,200 @@ describe('Middy middleware', () => { delete process.env.POWERTOOLS_TRACER_CAPTURE_ERROR; }); - }); - test('when used with standard config, it captures the exception correctly', async () => { - // Prepare - const tracer: Tracer = new Tracer(); - const newSubsegment: Segment | Subsegment | undefined = new Subsegment( - '## index.handler' - ); - const setSegmentSpy = jest - .spyOn(tracer.provider, 'setSegment') - .mockImplementation(); - jest - .spyOn(tracer.provider, 'getSegment') - .mockImplementation(() => newSubsegment); - setContextMissingStrategy(() => null); - const addErrorSpy = jest.spyOn(newSubsegment, 'addError'); - const lambdaHandler: Handler = async ( - _event: unknown, - _context: Context - ) => { - throw new Error('Exception thrown!'); - }; - const handler = middy(lambdaHandler).use(captureLambdaHandler(tracer)); - - // Act & Assess - await expect( - handler({}, context, () => console.log('Lambda invoked!')) - ).rejects.toThrowError(Error); - expect(setSegmentSpy).toHaveBeenCalledTimes(2); - expect('cause' in newSubsegment).toBe(true); - expect(addErrorSpy).toHaveBeenCalledTimes(1); - expect(addErrorSpy).toHaveBeenCalledWith( - new Error('Exception thrown!'), - false - ); - expect.assertions(5); - }); + test('when used with standard config, it captures the exception correctly', async () => { + // Prepare + const tracer: Tracer = new Tracer(); + const newSubsegment: Segment | Subsegment | undefined = new Subsegment( + '## index.handler' + ); + const setSegmentSpy = jest + .spyOn(tracer.provider, 'setSegment') + .mockImplementation(); + jest + .spyOn(tracer.provider, 'getSegment') + .mockImplementation(() => newSubsegment); + setContextMissingStrategy(() => null); + const addErrorSpy = jest.spyOn(newSubsegment, 'addError'); + const lambdaHandler: Handler = async ( + _event: unknown, + _context: Context + ) => { + throw new Error('Exception thrown!'); + }; + const handler = middy(lambdaHandler).use(captureLambdaHandler(tracer)); - test('when used with standard config, it annotates ColdStart correctly', async () => { - // Prepare - const tracer: Tracer = new Tracer(); - jest.spyOn(tracer.provider, 'setSegment').mockImplementation(() => ({})); - jest - .spyOn(tracer.provider, 'getSegment') - .mockImplementationOnce(() => new Segment('facade')) - .mockImplementationOnce(() => new Subsegment('## index.handler')) - .mockImplementationOnce(() => new Segment('facade')) - .mockImplementation(() => new Subsegment('## index.handler')); - const putAnnotationSpy = jest.spyOn(tracer, 'putAnnotation'); + // Act & Assess + await expect( + handler({}, context, () => console.log('Lambda invoked!')) + ).rejects.toThrowError(Error); + expect(setSegmentSpy).toHaveBeenCalledTimes(2); + expect('cause' in newSubsegment).toBe(true); + expect(addErrorSpy).toHaveBeenCalledTimes(1); + expect(addErrorSpy).toHaveBeenCalledWith( + new Error('Exception thrown!'), + false + ); + expect.assertions(5); + }); - const handler = middy(async (_event: unknown, _context: Context) => ({ - foo: 'bar', - })).use(captureLambdaHandler(tracer)); + test('when used with standard config, it annotates ColdStart correctly', async () => { + // Prepare + const tracer: Tracer = new Tracer(); + jest.spyOn(tracer.provider, 'setSegment').mockImplementation(() => ({})); + jest + .spyOn(tracer.provider, 'getSegment') + .mockImplementationOnce(() => new Segment('facade')) + .mockImplementationOnce(() => new Subsegment('## index.handler')) + .mockImplementationOnce(() => new Segment('facade')) + .mockImplementation(() => new Subsegment('## index.handler')); + const putAnnotationSpy = jest.spyOn(tracer, 'putAnnotation'); - // Act - await handler({}, context); - await handler({}, context); + const handler = middy(async (_event: unknown, _context: Context) => ({ + foo: 'bar', + })).use(captureLambdaHandler(tracer)); - // Assess - // 2x Cold Start + 2x Service - expect(putAnnotationSpy).toHaveBeenCalledTimes(4); - expect(putAnnotationSpy).toHaveBeenNthCalledWith(1, 'ColdStart', true); - expect(putAnnotationSpy).toHaveBeenNthCalledWith(3, 'ColdStart', false); - }); + // Act + await handler({}, context); + await handler({}, context); - test('when used with standard config, it annotates Service correctly', async () => { - // Prepare - const tracer: Tracer = new Tracer(); - jest.spyOn(tracer.provider, 'setSegment').mockImplementation(() => ({})); - jest - .spyOn(tracer.provider, 'getSegment') - .mockImplementationOnce(() => new Segment('facade')) - .mockImplementation(() => new Subsegment('## index.handler')); - const putAnnotationSpy = jest.spyOn(tracer, 'putAnnotation'); + // Assess + // 2x Cold Start + 2x Service + expect(putAnnotationSpy).toHaveBeenCalledTimes(4); + expect(putAnnotationSpy).toHaveBeenNthCalledWith(1, 'ColdStart', true); + expect(putAnnotationSpy).toHaveBeenNthCalledWith(3, 'ColdStart', false); + }); - const handler = middy(async (_event: unknown, _context: Context) => ({ - foo: 'bar', - })).use(captureLambdaHandler(tracer)); + test('when used with standard config, it annotates Service correctly', async () => { + // Prepare + const tracer: Tracer = new Tracer(); + jest.spyOn(tracer.provider, 'setSegment').mockImplementation(() => ({})); + jest + .spyOn(tracer.provider, 'getSegment') + .mockImplementationOnce(() => new Segment('facade')) + .mockImplementation(() => new Subsegment('## index.handler')); + const putAnnotationSpy = jest.spyOn(tracer, 'putAnnotation'); - // Act - await handler({}, context); + const handler = middy(async (_event: unknown, _context: Context) => ({ + foo: 'bar', + })).use(captureLambdaHandler(tracer)); - // Assess - // The first call is for the Cold Start annotation - expect(putAnnotationSpy).toHaveBeenCalledTimes(2); - expect(putAnnotationSpy).toHaveBeenNthCalledWith( - 2, - 'Service', - 'hello-world' - ); + // Act + await handler({}, context); + + // Assess + // The first call is for the Cold Start annotation + expect(putAnnotationSpy).toHaveBeenCalledTimes(2); + expect(putAnnotationSpy).toHaveBeenNthCalledWith( + 2, + 'Service', + 'hello-world' + ); + }); + + test('when enabled, and another middleware returns early, it still closes and restores the segments correctly', async () => { + // Prepare + const tracer = new Tracer(); + const setSegmentSpy = jest + .spyOn(tracer.provider, 'setSegment') + .mockImplementation(() => ({})); + jest.spyOn(tracer, 'annotateColdStart').mockImplementation(() => ({})); + jest + .spyOn(tracer, 'addServiceNameAnnotation') + .mockImplementation(() => ({})); + const facadeSegment1 = new Segment('facade'); + const handlerSubsegment1 = new Subsegment('## index.handlerA'); + jest + .spyOn(facadeSegment1, 'addNewSubsegment') + .mockImplementation(() => handlerSubsegment1); + const facadeSegment2 = new Segment('facade'); + const handlerSubsegment2 = new Subsegment('## index.handlerB'); + jest + .spyOn(facadeSegment2, 'addNewSubsegment') + .mockImplementation(() => handlerSubsegment2); + jest + .spyOn(tracer.provider, 'getSegment') + .mockImplementationOnce(() => facadeSegment1) + .mockImplementationOnce(() => facadeSegment2); + const myCustomMiddleware = (): middy.MiddlewareObj => { + const before = async ( + request: middy.Request + ): Promise => { + // Return early on the second invocation + if (request.event.idx === 1) { + // Cleanup Powertools resources + await cleanupMiddlewares(request); + + // Then return early + return 'foo'; + } + }; + + return { + before, + }; + }; + const handler = middy((): void => { + console.log('Hello world!'); + }) + .use(captureLambdaHandler(tracer, { captureResponse: false })) + .use(myCustomMiddleware()); + + // Act + await handler({ idx: 0 }, context); + await handler({ idx: 1 }, context); + + // Assess + // Check that the subsegments are closed + expect(handlerSubsegment1.isClosed()).toBe(true); + expect(handlerSubsegment2.isClosed()).toBe(true); + // Check that the segments are restored + expect(setSegmentSpy).toHaveBeenCalledTimes(4); + expect(setSegmentSpy).toHaveBeenNthCalledWith(2, facadeSegment1); + expect(setSegmentSpy).toHaveBeenNthCalledWith(4, facadeSegment2); + }); }); - test('when enabled, and another middleware returns early, it still closes and restores the segments correctly', async () => { + it('catches the error and logs a warning when the segment closing/serialization fails upon closing the segment', async () => { // Prepare const tracer = new Tracer(); - const setSegmentSpy = jest - .spyOn(tracer.provider, 'setSegment') - .mockImplementation(() => ({})); + const facadeSegment = new Segment('facade'); + const handlerSubsegment = new Subsegment('## index.handler'); + jest + .spyOn(tracer.provider, 'getSegment') + .mockImplementationOnce(() => facadeSegment) + .mockImplementationOnce(() => handlerSubsegment); jest.spyOn(tracer, 'annotateColdStart').mockImplementation(() => ({})); jest .spyOn(tracer, 'addServiceNameAnnotation') .mockImplementation(() => ({})); - const facadeSegment1 = new Segment('facade'); - const handlerSubsegment1 = new Subsegment('## index.handlerA'); - jest - .spyOn(facadeSegment1, 'addNewSubsegment') - .mockImplementation(() => handlerSubsegment1); - const facadeSegment2 = new Segment('facade'); - const handlerSubsegment2 = new Subsegment('## index.handlerB'); - jest - .spyOn(facadeSegment2, 'addNewSubsegment') - .mockImplementation(() => handlerSubsegment2); + const setSegmentSpy = jest + .spyOn(tracer.provider, 'setSegment') + .mockImplementation(() => ({})); jest - .spyOn(tracer.provider, 'getSegment') - .mockImplementationOnce(() => facadeSegment1) - .mockImplementationOnce(() => facadeSegment2); - const myCustomMiddleware = (): middy.MiddlewareObj => { - const before = async ( - request: middy.Request - ): Promise => { - // Return early on the second invocation - if (request.event.idx === 1) { - // Cleanup Powertools resources - await cleanupMiddlewares(request); - - // Then return early - return 'foo'; - } - }; - - return { - before, - }; - }; + .spyOn(facadeSegment, 'addNewSubsegment') + .mockImplementation(() => handlerSubsegment); const handler = middy((): void => { console.log('Hello world!'); - }) - .use(captureLambdaHandler(tracer, { captureResponse: false })) - .use(myCustomMiddleware()); + }).use(captureLambdaHandler(tracer)); + const logWarningSpy = jest.spyOn(console, 'warn'); + const closeSpy = jest + .spyOn(handlerSubsegment, 'close') + .mockImplementation(() => { + throw new Error('dummy error'); + }); // Act await handler({ idx: 0 }, context); - await handler({ idx: 1 }, context); // Assess - // Check that the subsegments are closed - expect(handlerSubsegment1.isClosed()).toBe(true); - expect(handlerSubsegment2.isClosed()).toBe(true); + expect(closeSpy).toHaveBeenCalledTimes(1); + expect(logWarningSpy).toHaveBeenNthCalledWith( + 1, + `Failed to close or serialize segment, ${handlerSubsegment.name}. We are catching the error but data might be lost.`, + new Error('dummy error') + ); // Check that the segments are restored - expect(setSegmentSpy).toHaveBeenCalledTimes(4); - expect(setSegmentSpy).toHaveBeenNthCalledWith(2, facadeSegment1); - expect(setSegmentSpy).toHaveBeenNthCalledWith(4, facadeSegment2); + expect(setSegmentSpy).toHaveBeenNthCalledWith(2, facadeSegment); }); });