From df2fc25dfc4d2946f7db9c7f1a9014620b34cc79 Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Wed, 15 Dec 2021 18:47:48 +0100 Subject: [PATCH 1/5] WIP: captureLambdaHandler middleware --- packages/tracing/npm-shrinkwrap.json | 18 ++- packages/tracing/package-lock.json | 6 - packages/tracing/package.json | 3 +- packages/tracing/src/Tracer.ts | 12 ++ packages/tracing/src/middleware/middy.ts | 46 ++++++ packages/tracing/tests/unit/Tracer.test.ts | 2 + packages/tracing/tests/unit/middy.test.ts | 160 +++++++++++++++++++++ packages/tracing/tsconfig.json | 5 +- 8 files changed, 242 insertions(+), 10 deletions(-) delete mode 100644 packages/tracing/package-lock.json create mode 100644 packages/tracing/src/middleware/middy.ts create mode 100644 packages/tracing/tests/unit/middy.test.ts diff --git a/packages/tracing/npm-shrinkwrap.json b/packages/tracing/npm-shrinkwrap.json index 127b07113a..dcf5db118e 100644 --- a/packages/tracing/npm-shrinkwrap.json +++ b/packages/tracing/npm-shrinkwrap.json @@ -9,6 +9,7 @@ "version": "0.0.0", "license": "MIT", "dependencies": { + "@middy/core": "^2.5.3", "aws-xray-sdk-core": "^3.3.3" }, "devDependencies": { @@ -971,6 +972,14 @@ "node": "^10.13.0 || ^12.13.0 || ^14.15.0 || >=15.0.0" } }, + "node_modules/@middy/core": { + "version": "2.5.3", + "resolved": "https://registry.npmjs.org/@middy/core/-/core-2.5.3.tgz", + "integrity": "sha512-hCXlRglDu48sl03IjDGjcJwfwElIPAf0fwBu08kqE80qpnouZ1hGH1lZbkbJjAhz6DkSR+79YArUQKUYaM2k1g==", + "engines": { + "node": ">=12" + } + }, "node_modules/@nodelib/fs.scandir": { "version": "2.1.5", "resolved": "https://registry.npmjs.org/@nodelib/fs.scandir/-/fs.scandir-2.1.5.tgz", @@ -2313,7 +2322,8 @@ "esprima": "^4.0.1", "estraverse": "^5.2.0", "esutils": "^2.0.2", - "optionator": "^0.8.1" + "optionator": "^0.8.1", + "source-map": "~0.6.1" }, "bin": { "escodegen": "bin/escodegen.js", @@ -3948,6 +3958,7 @@ "@types/node": "*", "anymatch": "^3.0.3", "fb-watchman": "^2.0.0", + "fsevents": "^2.3.2", "graceful-fs": "^4.2.4", "jest-regex-util": "^27.4.0", "jest-serializer": "^27.4.0", @@ -6696,6 +6707,11 @@ "chalk": "^4.0.0" } }, + "@middy/core": { + "version": "2.5.3", + "resolved": "https://registry.npmjs.org/@middy/core/-/core-2.5.3.tgz", + "integrity": "sha512-hCXlRglDu48sl03IjDGjcJwfwElIPAf0fwBu08kqE80qpnouZ1hGH1lZbkbJjAhz6DkSR+79YArUQKUYaM2k1g==" + }, "@nodelib/fs.scandir": { "version": "2.1.5", "resolved": "https://registry.npmjs.org/@nodelib/fs.scandir/-/fs.scandir-2.1.5.tgz", diff --git a/packages/tracing/package-lock.json b/packages/tracing/package-lock.json deleted file mode 100644 index 279fcefa11..0000000000 --- a/packages/tracing/package-lock.json +++ /dev/null @@ -1,6 +0,0 @@ -{ - "name": "tracing", - "lockfileVersion": 2, - "requires": true, - "packages": {} -} diff --git a/packages/tracing/package.json b/packages/tracing/package.json index 582d1777dd..c24f4ec84b 100644 --- a/packages/tracing/package.json +++ b/packages/tracing/package.json @@ -54,6 +54,7 @@ "url": "https://github.com/awslabs/aws-lambda-powertools-typescript/issues" }, "dependencies": { + "@middy/core": "^2.5.3", "aws-xray-sdk-core": "^3.3.3" } -} \ No newline at end of file +} diff --git a/packages/tracing/src/Tracer.ts b/packages/tracing/src/Tracer.ts index 849d8328cb..205414910c 100644 --- a/packages/tracing/src/Tracer.ts +++ b/packages/tracing/src/Tracer.ts @@ -351,6 +351,14 @@ class Tracer implements TracerInterface { return segment; } + + public isCaptureErrorEnabled(): boolean { + return this.captureError; + } + + public isCaptureResponseEnabled(): boolean { + return this.captureResponse; + } /** * Retrieve the current value of `ColdStart`. @@ -373,6 +381,10 @@ class Tracer implements TracerInterface { return false; } + public isTracingEnabled(): boolean { + return this.tracingEnabled; + } + /** * Adds annotation to existing segment or subsegment. * diff --git a/packages/tracing/src/middleware/middy.ts b/packages/tracing/src/middleware/middy.ts new file mode 100644 index 0000000000..b0dc8229a0 --- /dev/null +++ b/packages/tracing/src/middleware/middy.ts @@ -0,0 +1,46 @@ +import middy from '@middy/core'; +import { Subsegment } from 'aws-xray-sdk-core'; +import { Tracer } from '../Tracer'; + +const captureLambdaHandler = (target: Tracer): middy.MiddlewareObj => { + let subsegment: Subsegment | undefined; + const captureLambdaHandlerBefore = async (request: middy.Request): Promise => { + if (target.isTracingEnabled()) { + subsegment = new Subsegment(`## ${request.context.functionName}`); + target.setSegment(subsegment); + + if (Tracer.coldStart) { + target.putAnnotation('ColdStart', true); + } + } + }; + + const captureLambdaHandlerAfter = async (request: middy.Request): Promise => { + if (target.isTracingEnabled()) { + if (request.error) { + if (target.isCaptureErrorEnabled() === false) { + subsegment?.addErrorFlag(); + } else { + subsegment?.addError(request.error, false); + } + // TODO: should this error be thrown?? + // throw error; + } else { + if (request.response !== undefined && target.isCaptureResponseEnabled() === true) { + target.putMetadata(`${request.context.functionName} response`, request.response); + } + } + + subsegment?.close(); + } + }; + + return { + before: captureLambdaHandlerBefore, + after: captureLambdaHandlerAfter, + }; +}; + +export { + captureLambdaHandler, +}; \ No newline at end of file diff --git a/packages/tracing/tests/unit/Tracer.test.ts b/packages/tracing/tests/unit/Tracer.test.ts index 8bcd1142b8..0721b4db1b 100644 --- a/packages/tracing/tests/unit/Tracer.test.ts +++ b/packages/tracing/tests/unit/Tracer.test.ts @@ -2,7 +2,9 @@ import { context as dummyContext } from '../../../../tests/resources/contexts/he // eslint-disable-next-line @typescript-eslint/ban-ts-comment // @ts-ignore import * as dummyEvent from '../../../../tests/resources/events/custom/hello-world.json'; +// import { captureLambdaHandler } from '../../src/middleware/middy'; import { LambdaInterface } from '../../examples/utils/lambda'; +// import middy from '@middy/core'; import { Tracer } from '../../src'; import { Callback, Context } from 'aws-lambda/handler'; import { Segment, setContextMissingStrategy, Subsegment } from 'aws-xray-sdk-core'; diff --git a/packages/tracing/tests/unit/middy.test.ts b/packages/tracing/tests/unit/middy.test.ts new file mode 100644 index 0000000000..9e432f8f7d --- /dev/null +++ b/packages/tracing/tests/unit/middy.test.ts @@ -0,0 +1,160 @@ +import { captureLambdaHandler } from '../../src/middleware/middy'; +import middy from '@middy/core'; +// import { EnvironmentVariablesService } from '../../../src/config'; +import { Tracer } from './../../src'; +import type { Context, Handler } from 'aws-lambda/handler'; +import { Segment, setContextMissingStrategy, Subsegment } from 'aws-xray-sdk-core'; + +jest.spyOn(console, 'debug').mockImplementation(() => null); +jest.spyOn(console, 'warn').mockImplementation(() => null); +jest.spyOn(console, 'error').mockImplementation(() => null); + +describe('Middy middlewares', () => { + const ENVIRONMENT_VARIABLES = process.env; + + const mockContext: Context = { + callbackWaitsForEmptyEventLoop: true, + functionVersion: '$LATEST', + functionName: 'foo-bar-function', + memoryLimitInMB: '128', + logGroupName: '/aws/lambda/foo-bar-function-123456abcdef', + logStreamName: '2021/03/09/[$LATEST]abcdef123456abcdef123456abcdef123456', + invokedFunctionArn: 'arn:aws:lambda:eu-central-1:123456789012:function:Example', + awsRequestId: Math.floor(Math.random() * 1000000000).toString(), + getRemainingTimeInMillis: () => 1234, + done: () => console.log('Done!'), + fail: () => console.log('Failed!'), + succeed: () => console.log('Succeeded!'), + }; + + beforeEach(() => { + Tracer.coldStart = true; + jest.clearAllMocks(); + jest.resetModules(); + process.env = { ...ENVIRONMENT_VARIABLES }; + }); + + afterAll(() => { + process.env = ENVIRONMENT_VARIABLES; + }); + describe('Middleware: captureLambdaHandler', () => { + + test('when used while tracing is disabled, it does nothing', async () => { + + // Prepare + const tracer: Tracer = new Tracer({ enabled: false }); + const setSegmentSpy = jest.spyOn(tracer.provider, 'setSegment').mockImplementation(); + const getSegmentSpy = jest.spyOn(tracer.provider, 'getSegment') + .mockImplementationOnce(() => new Segment('facade', process.env._X_AMZN_TRACE_ID || null)) + .mockImplementationOnce(() => new Subsegment('## foo-bar-function')); + const lambdaHandler: Handler = async (_event: unknown, _context: Context) => ({ + foo: 'bar' + }); + const handler = middy(lambdaHandler).use(captureLambdaHandler(tracer)); + const context = Object.assign({}, mockContext); + + // Act + await handler({}, context, () => console.log('Lambda invoked!')); + + // Assess + expect(setSegmentSpy).toHaveBeenCalledTimes(0); + expect(getSegmentSpy).toHaveBeenCalledTimes(0); + + }); + + test('when used as decorator while POWERTOOLS_TRACER_CAPTURE_RESPONSE is set to false, it does not capture the response as metadata', async () => { + + // Prepare + process.env.POWERTOOLS_TRACER_CAPTURE_RESPONSE = 'false'; + const tracer: Tracer = new Tracer(); + const newSubsegment: Segment | Subsegment | undefined = new Subsegment('## foo-bar-function'); + const setSegmentSpy = jest.spyOn(tracer.provider, 'setSegment').mockImplementation(); + jest.spyOn(tracer.provider, 'getSegment').mockImplementation(() => newSubsegment); + setContextMissingStrategy(() => null); + const lambdaHandler: Handler = async (_event: unknown, _context: Context) => ({ + foo: 'bar' + }); + const handler = middy(lambdaHandler).use(captureLambdaHandler(tracer)); + const context = Object.assign({}, mockContext); + + // Act + await handler({}, context, () => console.log('Lambda invoked!')); + + // Assess + expect(setSegmentSpy).toHaveBeenCalledTimes(1); + expect('metadata' in newSubsegment).toBe(false); + delete process.env.POWERTOOLS_TRACER_CAPTURE_RESPONSE; + + }); + + test('when used as decorator and with standard config, it captures the response as metadata', async () => { + + // Prepare + const tracer: Tracer = new Tracer(); + const newSubsegment: Segment | Subsegment | undefined = new Subsegment('## foo-bar-function'); + const setSegmentSpy = jest.spyOn(tracer.provider, 'setSegment').mockImplementation(); + jest.spyOn(tracer.provider, 'getSegment').mockImplementation(() => newSubsegment); + setContextMissingStrategy(() => null); + const lambdaHandler: Handler = async (_event: unknown, _context: Context) => ({ + foo: 'bar' + }); + const handler = middy(lambdaHandler).use(captureLambdaHandler(tracer)); + const context = Object.assign({}, mockContext); + + // Act + await handler({}, context, () => console.log('Lambda invoked!')); + + // Assess + expect(setSegmentSpy).toHaveBeenCalledTimes(1); + expect(setSegmentSpy).toHaveBeenCalledWith(expect.objectContaining({ + name: '## foo-bar-function', + })); + expect(newSubsegment).toEqual(expect.objectContaining({ + name: '## foo-bar-function', + metadata: { + 'hello-world': { + 'foo-bar-function response': { + foo: 'bar', + }, + }, + } + })); + + }); + + test('when used as decorator while POWERTOOLS_TRACER_CAPTURE_ERROR is set to false, it does not capture the exceptions', async () => { + + // Prepare + process.env.POWERTOOLS_TRACER_CAPTURE_ERROR = 'false'; + const tracer: Tracer = new Tracer(); + const newSubsegment: Segment | Subsegment | undefined = new Subsegment('## foo-bar-function'); + const setSegmentSpy = jest.spyOn(tracer.provider, 'setSegment').mockImplementation(); + jest.spyOn(tracer.provider, 'getSegment').mockImplementation(() => newSubsegment); + setContextMissingStrategy(() => null); + const addErrorSpy = jest.spyOn(newSubsegment, 'addError'); + const addErrorFlagSpy = jest.spyOn(newSubsegment, 'addErrorFlag'); + const lambdaHandler: Handler = async (_event: unknown, _context: Context) => { + throw new Error('Exception thrown!'); + }; + const handler = middy(lambdaHandler).use(captureLambdaHandler(tracer)); + const context = Object.assign({}, mockContext); + + // Act + await handler({}, context, () => console.log('Lambda invoked!')); + + // Assess + expect(setSegmentSpy).toHaveBeenCalledTimes(1); + expect(setSegmentSpy).toHaveBeenCalledWith(expect.objectContaining({ + name: '## foo-bar-function', + })); + expect('cause' in newSubsegment).toBe(false); + expect(addErrorFlagSpy).toHaveBeenCalledTimes(1); + expect(addErrorSpy).toHaveBeenCalledTimes(0); + + delete process.env.POWERTOOLS_TRACER_CAPTURE_ERROR; + + }); + + }); + +}); \ No newline at end of file diff --git a/packages/tracing/tsconfig.json b/packages/tracing/tsconfig.json index d28abaa6d5..d687ab2e93 100644 --- a/packages/tracing/tsconfig.json +++ b/packages/tracing/tsconfig.json @@ -14,9 +14,10 @@ "resolveJsonModule": true, "pretty": true, "baseUrl": "src/", - "rootDirs": [ "src/" ] + "rootDirs": [ "src/" ], + "esModuleInterop": true }, - "include": [ "src/**/*", "examples/**/*", "tests/**/*" ], + "include": [ "src/**/*", "examples/**/*", "**/tests/**/*" ], "exclude": [ "./node_modules"], "watchOptions": { "watchFile": "useFsEvents", From ccba5efbe111e4f34904225920b0580f4544daf4 Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Wed, 15 Dec 2021 19:26:02 +0100 Subject: [PATCH 2/5] Completed captureLambdaHandler middleware --- packages/tracing/src/Tracer.ts | 3 +- packages/tracing/src/middleware/middy.ts | 34 +++--- packages/tracing/tests/unit/Tracer.test.ts | 47 +++++---- packages/tracing/tests/unit/middy.test.ts | 115 +++++++++++++++++++-- 4 files changed, 152 insertions(+), 47 deletions(-) diff --git a/packages/tracing/src/Tracer.ts b/packages/tracing/src/Tracer.ts index 205414910c..193c062990 100644 --- a/packages/tracing/src/Tracer.ts +++ b/packages/tracing/src/Tracer.ts @@ -242,8 +242,7 @@ class Tracer implements TracerInterface { this.addResponseAsMetadata(result, context.functionName); } catch (error) { this.addErrorAsMetadata(error as Error); - // TODO: should this error be thrown?? If thrown we get a ERR_UNHANDLED_REJECTION. If not aren't we are basically catching a Customer error? - // throw error; + throw error; } finally { subsegment?.close(); } diff --git a/packages/tracing/src/middleware/middy.ts b/packages/tracing/src/middleware/middy.ts index b0dc8229a0..74010fe475 100644 --- a/packages/tracing/src/middleware/middy.ts +++ b/packages/tracing/src/middleware/middy.ts @@ -3,13 +3,12 @@ import { Subsegment } from 'aws-xray-sdk-core'; import { Tracer } from '../Tracer'; const captureLambdaHandler = (target: Tracer): middy.MiddlewareObj => { - let subsegment: Subsegment | undefined; const captureLambdaHandlerBefore = async (request: middy.Request): Promise => { if (target.isTracingEnabled()) { - subsegment = new Subsegment(`## ${request.context.functionName}`); + const subsegment = new Subsegment(`## ${request.context.functionName}`); target.setSegment(subsegment); - if (Tracer.coldStart) { + if (Tracer.isColdStart()) { target.putAnnotation('ColdStart', true); } } @@ -17,27 +16,32 @@ const captureLambdaHandler = (target: Tracer): middy.MiddlewareObj => { const captureLambdaHandlerAfter = async (request: middy.Request): Promise => { if (target.isTracingEnabled()) { - if (request.error) { - if (target.isCaptureErrorEnabled() === false) { - subsegment?.addErrorFlag(); - } else { - subsegment?.addError(request.error, false); - } - // TODO: should this error be thrown?? - // throw error; - } else { - if (request.response !== undefined && target.isCaptureResponseEnabled() === true) { - target.putMetadata(`${request.context.functionName} response`, request.response); - } + const subsegment = target.getSegment(); + if (request.response !== undefined && target.isCaptureResponseEnabled() === true) { + target.putMetadata(`${request.context.functionName} response`, request.response); } subsegment?.close(); } }; + const captureLambdaHandlerError = async (request: middy.Request): Promise => { + if (target.isTracingEnabled()) { + const subsegment = target.getSegment(); + if (target.isCaptureErrorEnabled() === false) { + subsegment?.addErrorFlag(); + } else { + subsegment?.addError(request.error as Error, false); + } + // TODO: should this error be thrown?? I.e. should we stop the event flow & return? + // throw error; + } + }; + return { before: captureLambdaHandlerBefore, after: captureLambdaHandlerAfter, + onError: captureLambdaHandlerError }; }; diff --git a/packages/tracing/tests/unit/Tracer.test.ts b/packages/tracing/tests/unit/Tracer.test.ts index 0721b4db1b..fb721cb078 100644 --- a/packages/tracing/tests/unit/Tracer.test.ts +++ b/packages/tracing/tests/unit/Tracer.test.ts @@ -2,9 +2,7 @@ import { context as dummyContext } from '../../../../tests/resources/contexts/he // eslint-disable-next-line @typescript-eslint/ban-ts-comment // @ts-ignore import * as dummyEvent from '../../../../tests/resources/events/custom/hello-world.json'; -// import { captureLambdaHandler } from '../../src/middleware/middy'; import { LambdaInterface } from '../../examples/utils/lambda'; -// import middy from '@middy/core'; import { Tracer } from '../../src'; import { Callback, Context } from 'aws-lambda/handler'; import { Segment, setContextMissingStrategy, Subsegment } from 'aws-xray-sdk-core'; @@ -454,18 +452,21 @@ describe('Class: Tracer', () => { } // Act - await new Lambda().handler(dummyEvent, dummyContext, () => console.log('Lambda invoked!')); - - // Assess - expect(captureAsyncFuncSpy).toHaveBeenCalledTimes(1); - expect(newSubsegment).toEqual(expect.objectContaining({ - name: '## foo-bar-function', - })); - expect('cause' in newSubsegment).toBe(false); - expect(addErrorFlagSpy).toHaveBeenCalledTimes(1); - expect(addErrorSpy).toHaveBeenCalledTimes(0); + try { + await new Lambda().handler(dummyEvent, dummyContext, () => console.log('Lambda invoked!')); + } catch (error) { + // Assess + expect(captureAsyncFuncSpy).toHaveBeenCalledTimes(1); + expect(newSubsegment).toEqual(expect.objectContaining({ + name: '## foo-bar-function', + })); + expect('cause' in newSubsegment).toBe(false); + expect(addErrorFlagSpy).toHaveBeenCalledTimes(1); + expect(addErrorSpy).toHaveBeenCalledTimes(0); + } delete process.env.POWERTOOLS_TRACER_CAPTURE_ERROR; + }); test('when used as decorator and with standard config, it captures the exception correctly', async () => { @@ -490,16 +491,18 @@ describe('Class: Tracer', () => { } // Act - await new Lambda().handler(dummyEvent, dummyContext, () => console.log('Lambda invoked!')); - - // Assess - expect(captureAsyncFuncSpy).toHaveBeenCalledTimes(1); - expect(newSubsegment).toEqual(expect.objectContaining({ - name: '## foo-bar-function', - })); - expect('cause' in newSubsegment).toBe(true); - expect(addErrorSpy).toHaveBeenCalledTimes(1); - expect(addErrorSpy).toHaveBeenCalledWith(new Error('Exception thrown!'), false); + try { + await new Lambda().handler(dummyEvent, dummyContext, () => console.log('Lambda invoked!')); + } catch (error) { + // Assess + expect(captureAsyncFuncSpy).toHaveBeenCalledTimes(1); + expect(newSubsegment).toEqual(expect.objectContaining({ + name: '## foo-bar-function', + })); + expect('cause' in newSubsegment).toBe(true); + expect(addErrorSpy).toHaveBeenCalledTimes(1); + expect(addErrorSpy).toHaveBeenCalledWith(new Error('Exception thrown!'), false); + } }); diff --git a/packages/tracing/tests/unit/middy.test.ts b/packages/tracing/tests/unit/middy.test.ts index 9e432f8f7d..e90be949e7 100644 --- a/packages/tracing/tests/unit/middy.test.ts +++ b/packages/tracing/tests/unit/middy.test.ts @@ -62,7 +62,32 @@ describe('Middy middlewares', () => { }); - test('when used as decorator while POWERTOOLS_TRACER_CAPTURE_RESPONSE is set to false, it does not capture the response as metadata', async () => { + test('when used while tracing is disabled, even if the handler throws an error, it does nothing', async () => { + + // Prepare + const tracer: Tracer = new Tracer({ enabled: false }); + const setSegmentSpy = jest.spyOn(tracer.provider, 'setSegment').mockImplementation(); + const getSegmentSpy = jest.spyOn(tracer.provider, 'getSegment') + .mockImplementationOnce(() => new Segment('facade', process.env._X_AMZN_TRACE_ID || null)) + .mockImplementationOnce(() => new Subsegment('## foo-bar-function')); + const lambdaHandler: Handler = async (_event: unknown, _context: Context) => { + throw new Error('Exception thrown!'); + }; + const handler = middy(lambdaHandler).use(captureLambdaHandler(tracer)); + const context = Object.assign({}, mockContext); + + // Act + try { + await handler({}, context, () => console.log('Lambda invoked!')); + } catch (error) { + // Assess + expect(setSegmentSpy).toHaveBeenCalledTimes(0); + expect(getSegmentSpy).toHaveBeenCalledTimes(0); + } + + }); + + test('when used while POWERTOOLS_TRACER_CAPTURE_RESPONSE is set to false, it does not capture the response as metadata', async () => { // Prepare process.env.POWERTOOLS_TRACER_CAPTURE_RESPONSE = 'false'; @@ -87,7 +112,7 @@ describe('Middy middlewares', () => { }); - test('when used as decorator and with standard config, it captures the response as metadata', async () => { + test('when used with standard config, it captures the response as metadata', async () => { // Prepare const tracer: Tracer = new Tracer(); @@ -122,7 +147,7 @@ describe('Middy middlewares', () => { }); - test('when used as decorator while POWERTOOLS_TRACER_CAPTURE_ERROR is set to false, it does not capture the exceptions', async () => { + test('when used while POWERTOOLS_TRACER_CAPTURE_ERROR is set to false, it does not capture the exceptions', async () => { // Prepare process.env.POWERTOOLS_TRACER_CAPTURE_ERROR = 'false'; @@ -140,20 +165,94 @@ describe('Middy middlewares', () => { const context = Object.assign({}, mockContext); // Act - await handler({}, context, () => console.log('Lambda invoked!')); + try { + await handler({}, context, () => console.log('Lambda invoked!')); + } catch (error) { + // Assess + expect(setSegmentSpy).toHaveBeenCalledTimes(1); + expect(setSegmentSpy).toHaveBeenCalledWith(expect.objectContaining({ + name: '## foo-bar-function', + })); + expect('cause' in newSubsegment).toBe(false); + expect(addErrorFlagSpy).toHaveBeenCalledTimes(1); + expect(addErrorSpy).toHaveBeenCalledTimes(0); + } + + 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('## foo-bar-function'); + 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)); + const context = Object.assign({}, mockContext); + + // Act + try { + await handler({}, context, () => console.log('Lambda invoked!')); + } catch (error) { // Assess expect(setSegmentSpy).toHaveBeenCalledTimes(1); expect(setSegmentSpy).toHaveBeenCalledWith(expect.objectContaining({ name: '## foo-bar-function', })); - expect('cause' in newSubsegment).toBe(false); - expect(addErrorFlagSpy).toHaveBeenCalledTimes(1); - expect(addErrorSpy).toHaveBeenCalledTimes(0); + expect('cause' in newSubsegment).toBe(true); + expect(addErrorSpy).toHaveBeenCalledTimes(1); + expect(addErrorSpy).toHaveBeenCalledWith(new Error('Exception thrown!'), false); + } - delete process.env.POWERTOOLS_TRACER_CAPTURE_ERROR; + }); + test('when used with standard config, it annotates ColdStart correctly', async () => { + + // Prepare + const tracer: Tracer = new Tracer(); + const newSubsegmentFirstInvocation: Segment | Subsegment | undefined = new Subsegment('## foo-bar-function'); + const newSubsegmentSecondInvocation: Segment | Subsegment | undefined = new Subsegment('## foo-bar-function'); + const setSegmentSpy = jest.spyOn(tracer.provider, 'setSegment').mockImplementation(); + jest.spyOn(tracer.provider, 'getSegment') + .mockImplementationOnce(() => newSubsegmentFirstInvocation) + .mockImplementation(() => newSubsegmentSecondInvocation); + setContextMissingStrategy(() => null); + const addAnnotationSpy = jest.spyOn(tracer, 'putAnnotation'); + const lambdaHandler: Handler = async (_event: unknown, _context: Context) => ({ + foo: 'bar' }); + const handler = middy(lambdaHandler).use(captureLambdaHandler(tracer)); + const context = Object.assign({}, mockContext); + + // Act + await handler({}, context, () => console.log('Lambda invoked!')); + await handler({}, context, () => console.log('Lambda invoked!')); + + // Assess + expect(setSegmentSpy).toHaveBeenCalledTimes(2); + expect(setSegmentSpy).toHaveBeenCalledWith(expect.objectContaining({ + name: '## foo-bar-function', + })); + expect(addAnnotationSpy).toHaveBeenCalledTimes(1); + expect(addAnnotationSpy).toHaveBeenCalledWith('ColdStart', true); + expect(newSubsegmentFirstInvocation).toEqual(expect.objectContaining({ + name: '## foo-bar-function', + annotations: { + 'ColdStart': true, + } + })); + expect(newSubsegmentSecondInvocation).toEqual(expect.objectContaining({ + name: '## foo-bar-function' + })); }); From 6addea67e1c9ecd199b8c0ee3c84254b0dbe3f05 Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Wed, 15 Dec 2021 20:09:21 +0100 Subject: [PATCH 3/5] Documentation --- docs/core/tracer.md | 33 +++++----------- packages/tracing/src/Tracer.ts | 49 ++++++++++++++++++++++-- packages/tracing/src/index.ts | 3 +- packages/tracing/src/middleware/middy.ts | 28 +++++++++++++- 4 files changed, 83 insertions(+), 30 deletions(-) diff --git a/docs/core/tracer.md b/docs/core/tracer.md index 21c3bf2cf4..38fbfd330b 100644 --- a/docs/core/tracer.md +++ b/docs/core/tracer.md @@ -42,17 +42,16 @@ You can quickly start by importing the `Tracer` class, initialize it outside the === "Middleware" - ```typescript hl_lines="1 3 6" + ```typescript hl_lines="1-2 4 7 9" import { Tracer } from '@aws-lambda-powertools/tracer'; + import middy from '@middy/core'; const tracer = Tracer(); // Sets service via env var // OR tracer = Tracer({ service: 'example' }); - // TODO: update example once middleware has been implemented. - - export const handler = async (_event: any, _context: any) => { + export const handler = middy(async (_event: any, _context: any) => { ... - } + }).use(captureLambdaHandler(tracer)); ``` === "Decorator" @@ -76,7 +75,7 @@ You can quickly start by importing the `Tracer` class, initialize it outside the === "Manual" - ```typescript hl_lines="1-2 4 8-9 11 17 20 24" + ```typescript hl_lines="1-2 4 9-10 12 18 21 25" import { Tracer } from '@aws-lambda-powertools/tracer'; import { Segment } from 'aws-xray-sdk-core'; @@ -107,8 +106,7 @@ You can quickly start by importing the `Tracer` class, initialize it outside the } ``` - -When using thes `captureLambdaHanlder` decorator or the `TBD` middleware, Tracer performs these additional tasks to ease operations: +When using the `captureLambdaHanlder` decorator or middleware, Tracer performs these additional tasks to ease operations: * Handles the lifecycle of the subsegment * Creates a `ColdStart` annotation to easily filter traces that have had an initialization overhead @@ -148,23 +146,10 @@ When using thes `captureLambdaHanlder` decorator or the `TBD` middleware, Tracer ### Methods -You can trace other methods using the `captureMethod` decorator. - -=== "Middleware" - - ```typescript hl_lines="1 3 6" - import { Tracer } from '@aws-lambda-powertools/tracer'; - - const tracer = Tracer(); +You can trace other methods using the `captureMethod` decorator or manual instrumentation. - // TODO: update example once middleware has been implemented. - - - - export const handler = async (_event: any, _context: any) => { - ... - } - ``` +!!! info + We currently support a middleware for tracing methods, [let us know](https://github.com/awslabs/aws-lambda-powertools-typecsript/issues/new?assignees=&labels=feature-request%2C+triage&template=feature_request.md&title=) if you'd like to see one! === "Decorator" diff --git a/packages/tracing/src/Tracer.ts b/packages/tracing/src/Tracer.ts index 193c062990..7a0668f67c 100644 --- a/packages/tracing/src/Tracer.ts +++ b/packages/tracing/src/Tracer.ts @@ -20,11 +20,28 @@ import { Segment, Subsegment } from 'aws-xray-sdk-core'; * ## Usage * * ### Functions usage with middlewares - * TBD + * + * If you use function-based Lambda handlers you can use the [captureLambdaHanlder()](./_aws_lambda_powertools_tracer.Tracer.html) middy middleware to automatically: + * * handle the subsegment lifecycle + * * add the `ColdStart` annotation + * * add the function response as metadata + * * add the function error as metadata (if any) + * + * @example + * ```typescript + * import { Tracer, captureLambdaHandler } from '@aws-lambda-powertools/tracer'; + * import middy from '@middy/core'; + * + * const tracer = new Tracer({ serviceName: 'my-service' }); + * + * export const handler = middy(async (_event: any, _context: any) => { + * ... + * }).use(captureLambdaHandler(tracer)); + * ``` * * ### Object oriented usage with decorators * - * If you use TypeScript Classes to wrap your Lambda handler you can use the [@tracer.captureLambdaHanlder()](./_aws_lambda_powertools_tracer.Tracer.html#captureLambdaHanlder) decorator to automatically: + * If instead you use TypeScript Classes to wrap your Lambda handler you can use the [@tracer.captureLambdaHanlder()](./_aws_lambda_powertools_tracer.Tracer.html#captureLambdaHanlder) decorator to automatically: * * handle the subsegment lifecycle * * add the `ColdStart` annotation * * add the function response as metadata @@ -65,7 +82,7 @@ import { Segment, Subsegment } from 'aws-xray-sdk-core'; * const subsegment = new Subsegment(`## ${context.functionName}`); * tracer.setSegment(subsegment); * // Add the ColdStart annotation - * this.putAnnotation('ColdStart', tracer.coldStart); + * this.putAnnotation('ColdStart', tracer.isColdStart()); * * let res; * try { @@ -351,10 +368,26 @@ class Tracer implements TracerInterface { return segment; } + /** + * Get the current value of the `captureError` property. + * + * You can use this method during manual instrumentation to determine + * if tracer should be capturing errors. + * + * @returns captureError - `true` if errors should be captured, `false` otherwise. + */ public isCaptureErrorEnabled(): boolean { return this.captureError; } + /** + * Get the current value of the `captureResponse` property. + * + * You can use this method during manual instrumentation to determine + * if tracer should be capturing function responses. + * + * @returns captureResponse - `true` if responses should be captured, `false` otherwise. + */ public isCaptureResponseEnabled(): boolean { return this.captureResponse; } @@ -368,7 +401,7 @@ class Tracer implements TracerInterface { * * @see https://docs.aws.amazon.com/lambda/latest/dg/runtimes-context.html * - * @returns boolean - true if is cold start otherwise false + * @returns boolean - `true` if is cold start, otherwise `false` */ public static isColdStart(): boolean { if (Tracer.coldStart === true) { @@ -380,6 +413,14 @@ class Tracer implements TracerInterface { return false; } + /** + * Get the current value of the `tracingEnabled` property. + * + * You can use this method during manual instrumentation to determine + * if tracer is currently enabled. + * + * @returns tracingEnabled - `true` if tracing is enabled, `false` otherwise. + */ public isTracingEnabled(): boolean { return this.tracingEnabled; } diff --git a/packages/tracing/src/index.ts b/packages/tracing/src/index.ts index 0412c64c09..4e2259de59 100644 --- a/packages/tracing/src/index.ts +++ b/packages/tracing/src/index.ts @@ -1,3 +1,4 @@ export * from './helpers'; export * from './Tracer'; -export * from './TracerInterface'; \ No newline at end of file +export * from './TracerInterface'; +export * from './middleware/middy'; \ No newline at end of file diff --git a/packages/tracing/src/middleware/middy.ts b/packages/tracing/src/middleware/middy.ts index 74010fe475..79a37b18d0 100644 --- a/packages/tracing/src/middleware/middy.ts +++ b/packages/tracing/src/middleware/middy.ts @@ -2,6 +2,30 @@ import middy from '@middy/core'; import { Subsegment } from 'aws-xray-sdk-core'; import { Tracer } from '../Tracer'; +/** + * A middy middleware automating capture of metadata and annotations on segments or subsegments ofr a Lambda Handler. + * + * Using this middleware on your handler function will automatically: + * * handle the subsegment lifecycle + * * add the `ColdStart` annotation + * * add the function response as metadata + * * add the function error as metadata (if any) + * + * @example + * ```typescript + * import { Tracer, captureLambdaHandler } from '@aws-lambda-powertools/tracer'; + * import middy from '@middy/core'; + * + * const tracer = new Tracer({ serviceName: 'my-service' }); + * + * export const handler = middy(async (_event: any, _context: any) => { + * ... + * }).use(captureLambdaHandler(tracer)); + * ``` + * + * @param tracer - The Tracer instance to use for tracing + * @returns middleware object - The middy middleware object + */ const captureLambdaHandler = (target: Tracer): middy.MiddlewareObj => { const captureLambdaHandlerBefore = async (request: middy.Request): Promise => { if (target.isTracingEnabled()) { @@ -34,7 +58,9 @@ const captureLambdaHandler = (target: Tracer): middy.MiddlewareObj => { subsegment?.addError(request.error as Error, false); } // TODO: should this error be thrown?? I.e. should we stop the event flow & return? - // throw error; + // throw request.error; + + subsegment?.close(); } }; From 5341c4719eb3be69409705dd1825f49dfd59844a Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Fri, 17 Dec 2021 16:22:03 +0100 Subject: [PATCH 4/5] Improved error catching in tests --- packages/tracing/tests/unit/Tracer.test.ts | 46 ++++++++--------- packages/tracing/tests/unit/middy.test.ts | 60 +++++++++------------- 2 files changed, 45 insertions(+), 61 deletions(-) diff --git a/packages/tracing/tests/unit/Tracer.test.ts b/packages/tracing/tests/unit/Tracer.test.ts index fb721cb078..157cda7412 100644 --- a/packages/tracing/tests/unit/Tracer.test.ts +++ b/packages/tracing/tests/unit/Tracer.test.ts @@ -451,19 +451,16 @@ describe('Class: Tracer', () => { } - // Act - try { - await new Lambda().handler(dummyEvent, dummyContext, () => console.log('Lambda invoked!')); - } catch (error) { - // Assess - expect(captureAsyncFuncSpy).toHaveBeenCalledTimes(1); - expect(newSubsegment).toEqual(expect.objectContaining({ - name: '## foo-bar-function', - })); - expect('cause' in newSubsegment).toBe(false); - expect(addErrorFlagSpy).toHaveBeenCalledTimes(1); - expect(addErrorSpy).toHaveBeenCalledTimes(0); - } + // Act & Assess + await expect(new Lambda().handler({}, dummyContext, () => console.log('Lambda invoked!'))).rejects.toThrowError(Error); + expect(captureAsyncFuncSpy).toHaveBeenCalledTimes(1); + expect(newSubsegment).toEqual(expect.objectContaining({ + name: '## foo-bar-function', + })); + expect('cause' in newSubsegment).toBe(false); + expect(addErrorFlagSpy).toHaveBeenCalledTimes(1); + expect(addErrorSpy).toHaveBeenCalledTimes(0); + expect.assertions(6); delete process.env.POWERTOOLS_TRACER_CAPTURE_ERROR; @@ -490,19 +487,16 @@ describe('Class: Tracer', () => { } - // Act - try { - await new Lambda().handler(dummyEvent, dummyContext, () => console.log('Lambda invoked!')); - } catch (error) { - // Assess - expect(captureAsyncFuncSpy).toHaveBeenCalledTimes(1); - expect(newSubsegment).toEqual(expect.objectContaining({ - name: '## foo-bar-function', - })); - expect('cause' in newSubsegment).toBe(true); - expect(addErrorSpy).toHaveBeenCalledTimes(1); - expect(addErrorSpy).toHaveBeenCalledWith(new Error('Exception thrown!'), false); - } + // Act & Assess + await expect(new Lambda().handler({}, dummyContext, () => console.log('Lambda invoked!'))).rejects.toThrowError(Error); + expect(captureAsyncFuncSpy).toHaveBeenCalledTimes(1); + expect(newSubsegment).toEqual(expect.objectContaining({ + name: '## foo-bar-function', + })); + expect('cause' in newSubsegment).toBe(true); + expect(addErrorSpy).toHaveBeenCalledTimes(1); + expect(addErrorSpy).toHaveBeenCalledWith(new Error('Exception thrown!'), false); + expect.assertions(6); }); diff --git a/packages/tracing/tests/unit/middy.test.ts b/packages/tracing/tests/unit/middy.test.ts index e90be949e7..adef075f66 100644 --- a/packages/tracing/tests/unit/middy.test.ts +++ b/packages/tracing/tests/unit/middy.test.ts @@ -1,6 +1,5 @@ import { captureLambdaHandler } from '../../src/middleware/middy'; import middy from '@middy/core'; -// import { EnvironmentVariablesService } from '../../../src/config'; import { Tracer } from './../../src'; import type { Context, Handler } from 'aws-lambda/handler'; import { Segment, setContextMissingStrategy, Subsegment } from 'aws-xray-sdk-core'; @@ -76,14 +75,11 @@ describe('Middy middlewares', () => { const handler = middy(lambdaHandler).use(captureLambdaHandler(tracer)); const context = Object.assign({}, mockContext); - // Act - try { - await handler({}, context, () => console.log('Lambda invoked!')); - } catch (error) { - // Assess - expect(setSegmentSpy).toHaveBeenCalledTimes(0); - expect(getSegmentSpy).toHaveBeenCalledTimes(0); - } + // Act & Assess + await expect(handler({}, context, () => console.log('Lambda invoked!'))).rejects.toThrowError(Error); + expect(setSegmentSpy).toHaveBeenCalledTimes(0); + expect(getSegmentSpy).toHaveBeenCalledTimes(0); + expect.assertions(3); }); @@ -164,19 +160,16 @@ describe('Middy middlewares', () => { const handler = middy(lambdaHandler).use(captureLambdaHandler(tracer)); const context = Object.assign({}, mockContext); - // Act - try { - await handler({}, context, () => console.log('Lambda invoked!')); - } catch (error) { - // Assess - expect(setSegmentSpy).toHaveBeenCalledTimes(1); - expect(setSegmentSpy).toHaveBeenCalledWith(expect.objectContaining({ - name: '## foo-bar-function', - })); - expect('cause' in newSubsegment).toBe(false); - expect(addErrorFlagSpy).toHaveBeenCalledTimes(1); - expect(addErrorSpy).toHaveBeenCalledTimes(0); - } + // Act & Assess + await expect(handler({}, context, () => console.log('Lambda invoked!'))).rejects.toThrowError(Error); + expect(setSegmentSpy).toHaveBeenCalledTimes(1); + expect(setSegmentSpy).toHaveBeenCalledWith(expect.objectContaining({ + name: '## foo-bar-function', + })); + expect('cause' in newSubsegment).toBe(false); + expect(addErrorFlagSpy).toHaveBeenCalledTimes(1); + expect(addErrorSpy).toHaveBeenCalledTimes(0); + expect.assertions(6); delete process.env.POWERTOOLS_TRACER_CAPTURE_ERROR; @@ -199,19 +192,16 @@ describe('Middy middlewares', () => { const handler = middy(lambdaHandler).use(captureLambdaHandler(tracer)); const context = Object.assign({}, mockContext); - // Act - try { - await handler({}, context, () => console.log('Lambda invoked!')); - } catch (error) { - // Assess - expect(setSegmentSpy).toHaveBeenCalledTimes(1); - expect(setSegmentSpy).toHaveBeenCalledWith(expect.objectContaining({ - name: '## foo-bar-function', - })); - expect('cause' in newSubsegment).toBe(true); - expect(addErrorSpy).toHaveBeenCalledTimes(1); - expect(addErrorSpy).toHaveBeenCalledWith(new Error('Exception thrown!'), false); - } + // Act & Assess + await expect(handler({}, context, () => console.log('Lambda invoked!'))).rejects.toThrowError(Error); + expect(setSegmentSpy).toHaveBeenCalledTimes(1); + expect(setSegmentSpy).toHaveBeenCalledWith(expect.objectContaining({ + name: '## foo-bar-function', + })); + expect('cause' in newSubsegment).toBe(true); + expect(addErrorSpy).toHaveBeenCalledTimes(1); + expect(addErrorSpy).toHaveBeenCalledWith(new Error('Exception thrown!'), false); + expect.assertions(6); }); From c954226ba4a3950ee8dff96d16ac3e30ea25e6d7 Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Fri, 17 Dec 2021 16:25:37 +0100 Subject: [PATCH 5/5] Typos in docs --- docs/core/tracer.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/docs/core/tracer.md b/docs/core/tracer.md index 38fbfd330b..7fc1ab031e 100644 --- a/docs/core/tracer.md +++ b/docs/core/tracer.md @@ -106,7 +106,7 @@ You can quickly start by importing the `Tracer` class, initialize it outside the } ``` -When using the `captureLambdaHanlder` decorator or middleware, Tracer performs these additional tasks to ease operations: +When using the `captureLambdaHandler` decorator or middleware, Tracer performs these additional tasks to ease operations: * Handles the lifecycle of the subsegment * Creates a `ColdStart` annotation to easily filter traces that have had an initialization overhead @@ -149,7 +149,7 @@ When using the `captureLambdaHanlder` decorator or middleware, Tracer performs t You can trace other methods using the `captureMethod` decorator or manual instrumentation. !!! info - We currently support a middleware for tracing methods, [let us know](https://github.com/awslabs/aws-lambda-powertools-typecsript/issues/new?assignees=&labels=feature-request%2C+triage&template=feature_request.md&title=) if you'd like to see one! + We currently support a middleware for tracing methods, [let us know](https://github.com/awslabs/aws-lambda-powertools-typescript/issues/new?assignees=&labels=feature-request%2C+triage&template=feature_request.md&title=) if you'd like to see one! === "Decorator"