From 4f9e56f1b7fd1cd9374b2577786e4ab0f6602aaa Mon Sep 17 00:00:00 2001 From: Trivikram Kamat <16024985+trivikr@users.noreply.github.com> Date: Tue, 15 Dec 2020 16:55:56 -0800 Subject: [PATCH] feat(middleware-logger): log clientName, commandName, input, output (#1788) --- .../src/loggerMiddleware.spec.ts | 156 ++++++++++++------ .../middleware-logger/src/loggerMiddleware.ts | 14 +- .../src/deserializerMiddleware.spec.ts | 39 +---- .../src/deserializerMiddleware.ts | 13 -- .../src/serializerMiddleware.spec.ts | 48 ++---- .../src/serializerMiddleware.ts | 9 - 6 files changed, 132 insertions(+), 147 deletions(-) diff --git a/packages/middleware-logger/src/loggerMiddleware.spec.ts b/packages/middleware-logger/src/loggerMiddleware.spec.ts index 749dc97f952a5..9a5d71484d671 100644 --- a/packages/middleware-logger/src/loggerMiddleware.spec.ts +++ b/packages/middleware-logger/src/loggerMiddleware.spec.ts @@ -31,6 +31,16 @@ describe("loggerMiddleware", () => { }, }; + const mockOutput = { + $metadata: { + statusCode: 200, + requestId: "requestId", + attempts: 2, + totalRetryDelay: 350, + }, + outputKey: "outputValue", + }; + const mockResponse = { response: { statusCode: 200, @@ -40,9 +50,7 @@ describe("loggerMiddleware", () => { "x-amz-cf-id": "cfId", }, }, - output: { - outputKey: "outputValue", - }, + output: mockOutput, }; afterEach(() => { @@ -64,61 +72,99 @@ describe("loggerMiddleware", () => { expect(response).toStrictEqual(mockResponse); }); - it("logs metadata if context.logger has info function", async () => { - mockNext.mockResolvedValueOnce(mockResponse); - const logger = ({ info: jest.fn() } as unknown) as Logger; - - const context = { - logger, - }; - - const response = await loggerMiddleware()(mockNext, context)(mockArgs); - expect(mockNext).toHaveBeenCalledTimes(1); - expect(response).toStrictEqual(mockResponse); - - expect(logger.info).toHaveBeenCalledTimes(1); - - expect(logger.info).toHaveBeenCalledWith({ - metadata: { - statusCode: mockResponse.response.statusCode, - requestId: mockResponse.response.headers["x-amzn-requestid"], - extendedRequestId: mockResponse.response.headers["x-amz-id-2"], - cfId: mockResponse.response.headers["x-amz-cf-id"], - }, + describe("logs if context.logger has info function", () => { + it("success case with clientName, commandName, input, metadata", async () => { + mockNext.mockResolvedValueOnce(mockResponse); + + const logger = ({ info: jest.fn() } as unknown) as Logger; + const clientName = "mockClientName"; + const commandName = "mockCommandName"; + + const mockInputLog = { inputKey: "inputKey", inputSensitiveKey: "SENSITIVE_VALUE" }; + const inputFilterSensitiveLog = jest.fn().mockReturnValueOnce(mockInputLog); + const mockOutputLog = { outputKey: "outputKey", outputSensitiveKey: "SENSITIVE_VALUE" }; + const outputFilterSensitiveLog = jest.fn().mockReturnValueOnce(mockOutputLog); + + const context = { + logger, + clientName, + commandName, + inputFilterSensitiveLog, + outputFilterSensitiveLog, + }; + + const response = await loggerMiddleware()(mockNext, context)(mockArgs); + expect(mockNext).toHaveBeenCalledTimes(1); + expect(response).toStrictEqual(mockResponse); + + expect(inputFilterSensitiveLog).toHaveBeenCalledTimes(1); + expect(inputFilterSensitiveLog).toHaveBeenCalledWith(mockArgs.input); + + const { $metadata, ...outputWithoutMetadata } = mockOutput; + expect(outputFilterSensitiveLog).toHaveBeenCalledTimes(1); + expect(outputFilterSensitiveLog).toHaveBeenCalledWith(outputWithoutMetadata); + + expect(logger.info).toHaveBeenCalledTimes(1); + expect(logger.info).toHaveBeenCalledWith({ + clientName, + commandName, + input: mockInputLog, + output: mockOutputLog, + metadata: { + statusCode: mockResponse.response.statusCode, + requestId: mockResponse.response.headers["x-amzn-requestid"], + extendedRequestId: mockResponse.response.headers["x-amz-id-2"], + cfId: mockResponse.response.headers["x-amz-cf-id"], + retry: { + attempts: $metadata.attempts, + totalDelay: $metadata.totalRetryDelay, + }, + }, + }); }); - }); - it("logs header x-amzn-request-id as requestId if x-amzn-requestid is not present", async () => { - const requestIdBackup = "requestIdBackup"; - const customResponse = { - ...mockResponse, - response: { - ...mockResponse.response, - headers: { - "x-amzn-request-id": requestIdBackup, + it("header x-amzn-request-id as requestId if x-amzn-requestid is not present", async () => { + const requestIdBackup = "requestIdBackup"; + const customResponse = { + ...mockResponse, + response: { + ...mockResponse.response, + headers: { + "x-amzn-request-id": requestIdBackup, + }, }, - }, - }; - mockNext.mockResolvedValueOnce(customResponse); - const logger = ({ info: jest.fn() } as unknown) as Logger; - - const context = { - logger, - }; - - const response = await loggerMiddleware()(mockNext, context)(mockArgs); - expect(mockNext).toHaveBeenCalledTimes(1); - expect(response).toStrictEqual(customResponse); - - expect(logger.info).toHaveBeenCalledTimes(1); - - expect(logger.info).toHaveBeenCalledWith({ - metadata: { - statusCode: customResponse.response.statusCode, - requestId: requestIdBackup, - extendedRequestId: undefined, - cfId: undefined, - }, + }; + mockNext.mockResolvedValueOnce(customResponse); + const logger = ({ info: jest.fn() } as unknown) as Logger; + const inputFilterSensitiveLog = jest.fn().mockImplementationOnce((input) => input); + const outputFilterSensitiveLog = jest.fn().mockImplementationOnce((output) => output); + + const context = { + logger, + inputFilterSensitiveLog, + outputFilterSensitiveLog, + }; + + const response = await loggerMiddleware()(mockNext, context)(mockArgs); + expect(mockNext).toHaveBeenCalledTimes(1); + expect(response).toStrictEqual(customResponse); + + const { $metadata, ...outputWithoutMetadata } = mockOutput; + expect(logger.info).toHaveBeenCalledTimes(1); + expect(logger.info).toHaveBeenCalledWith({ + input: mockArgs.input, + output: outputWithoutMetadata, + metadata: { + statusCode: customResponse.response.statusCode, + requestId: requestIdBackup, + extendedRequestId: undefined, + cfId: undefined, + retry: { + attempts: $metadata.attempts, + totalDelay: $metadata.totalRetryDelay, + }, + }, + }); }); }); }); diff --git a/packages/middleware-logger/src/loggerMiddleware.ts b/packages/middleware-logger/src/loggerMiddleware.ts index 42c3b36f74e6b..c4c0117ef143d 100644 --- a/packages/middleware-logger/src/loggerMiddleware.ts +++ b/packages/middleware-logger/src/loggerMiddleware.ts @@ -16,7 +16,7 @@ export const loggerMiddleware = () => => async ( args: InitializeHandlerArguments ): Promise> => { - const { logger } = context; + const { clientName, commandName, inputFilterSensitiveLog, logger, outputFilterSensitiveLog } = context; const response = await next(args); @@ -24,15 +24,23 @@ export const loggerMiddleware = () => { @@ -51,38 +49,17 @@ describe("deserializerMiddleware", () => { }); afterEach(() => { - expect(mockNext).toHaveBeenCalledTimes(1); - expect(mockNext).toHaveBeenCalledWith(mockArgs); - expect(mockDeserializer).toHaveBeenCalledTimes(1); - expect(mockDeserializer).toHaveBeenCalledWith(mockNextResponse.response, mockOptions); jest.clearAllMocks(); }); - it("returns without logging if context.logger is not defined", async () => { - const response = await deserializerMiddleware(mockOptions, mockDeserializer)(mockNext, {})(mockArgs); - expect(response).toStrictEqual(mockResponse); - }); - - it("returns without logging if context.logger doesn't have debug/info function", async () => { - const logger = {} as Logger; - const response = await deserializerMiddleware(mockOptions, mockDeserializer)(mockNext, { logger })(mockArgs); - expect(response).toStrictEqual(mockResponse); - }); - - it("logs output if context.logger has info function", async () => { - const logger = ({ info: jest.fn() } as unknown) as Logger; + it("calls deserializer and populates response object", async () => { + await expect(deserializerMiddleware(mockOptions, mockDeserializer)(mockNext, {})(mockArgs)).resolves.toStrictEqual( + mockResponse + ); - const outputFilterSensitiveLog = jest.fn().mockImplementationOnce((output) => output); - const response = await deserializerMiddleware(mockOptions, mockDeserializer)(mockNext, { - logger, - outputFilterSensitiveLog: outputFilterSensitiveLog, - })(mockArgs); - - const { $metadata, ...outputWithoutMetadata } = mockOutput; - expect(response).toStrictEqual(mockResponse); - expect(outputFilterSensitiveLog).toHaveBeenCalledTimes(1); - expect(outputFilterSensitiveLog).toHaveBeenCalledWith(outputWithoutMetadata); - expect(logger.info).toHaveBeenCalledTimes(1); - expect(logger.info).toHaveBeenCalledWith({ output: outputWithoutMetadata }); + expect(mockNext).toHaveBeenCalledTimes(1); + expect(mockNext).toHaveBeenCalledWith(mockArgs); + expect(mockDeserializer).toHaveBeenCalledTimes(1); + expect(mockDeserializer).toHaveBeenCalledWith(mockNextResponse.response, mockOptions); }); }); diff --git a/packages/middleware-serde/src/deserializerMiddleware.ts b/packages/middleware-serde/src/deserializerMiddleware.ts index c8af8b60c8e5c..56377bf21a88e 100644 --- a/packages/middleware-serde/src/deserializerMiddleware.ts +++ b/packages/middleware-serde/src/deserializerMiddleware.ts @@ -16,21 +16,8 @@ export const deserializerMiddleware = => async ( args: DeserializeHandlerArguments ): Promise> => { - const { logger, outputFilterSensitiveLog } = context; - const { response } = await next(args); - const parsed = await deserializer(response, options); - - // Log parsed after $metadata is removed in https://github.com/aws/aws-sdk-js-v3/issues/1490 - const { $metadata, ...outputWithoutMetadata } = parsed; - - if (typeof logger?.info === "function") { - logger.info({ - output: outputFilterSensitiveLog(outputWithoutMetadata), - }); - } - return { response, output: parsed as Output, diff --git a/packages/middleware-serde/src/serializerMiddleware.spec.ts b/packages/middleware-serde/src/serializerMiddleware.spec.ts index dac41875ccf32..079c0a15b8be6 100644 --- a/packages/middleware-serde/src/serializerMiddleware.spec.ts +++ b/packages/middleware-serde/src/serializerMiddleware.spec.ts @@ -1,4 +1,4 @@ -import { Logger } from "@aws-sdk/types"; +import { EndpointBearer } from "@aws-sdk/types"; import { serializerMiddleware } from "./serializerMiddleware"; @@ -15,12 +15,6 @@ describe("serializerMiddleware", () => { }), }; - const mockArgs = { - input: { - inputKey: "inputValue", - }, - }; - const mockRequest = { method: "GET", headers: {}, @@ -44,43 +38,25 @@ describe("serializerMiddleware", () => { output: mockOutput, }; + const mockArgs = { + input: { + inputKey: "inputValue", + }, + }; + beforeEach(() => { mockNext.mockResolvedValueOnce(mockReturn); mockSerializer.mockResolvedValueOnce(mockRequest); }); - afterEach(() => { + it("calls serializer and populates request object", async () => { + await expect(serializerMiddleware(mockOptions, mockSerializer)(mockNext, {})(mockArgs)).resolves.toStrictEqual( + mockReturn + ); + expect(mockSerializer).toHaveBeenCalledTimes(1); expect(mockSerializer).toHaveBeenCalledWith(mockArgs.input, mockOptions); expect(mockNext).toHaveBeenCalledTimes(1); expect(mockNext).toHaveBeenCalledWith({ ...mockArgs, request: mockRequest }); - jest.clearAllMocks(); - }); - - it("returns without logging if context.logger is not defined", async () => { - const response = await serializerMiddleware(mockOptions, mockSerializer)(mockNext, {})(mockArgs); - expect(response).toStrictEqual(mockReturn); - }); - - it("returns without logging if context.logger doesn't have debug/info function", async () => { - const logger = {} as Logger; - const response = await serializerMiddleware(mockOptions, mockSerializer)(mockNext, { logger })(mockArgs); - expect(response).toStrictEqual(mockReturn); - }); - - it("logs input if context.logger has info function", async () => { - const logger = ({ info: jest.fn() } as unknown) as Logger; - - const inputFilterSensitiveLog = jest.fn().mockImplementationOnce((input) => input); - const response = await serializerMiddleware(mockOptions, mockSerializer)(mockNext, { - logger, - inputFilterSensitiveLog, - })(mockArgs); - - expect(response).toStrictEqual(mockReturn); - expect(inputFilterSensitiveLog).toHaveBeenCalledTimes(1); - expect(inputFilterSensitiveLog).toHaveBeenCalledWith(mockArgs.input); - expect(logger.info).toHaveBeenCalledTimes(1); - expect(logger.info).toHaveBeenCalledWith({ input: mockArgs.input }); }); }); diff --git a/packages/middleware-serde/src/serializerMiddleware.ts b/packages/middleware-serde/src/serializerMiddleware.ts index 58d0d0e90cb2a..49b7601fc7bc5 100644 --- a/packages/middleware-serde/src/serializerMiddleware.ts +++ b/packages/middleware-serde/src/serializerMiddleware.ts @@ -17,16 +17,7 @@ export const serializerMiddleware = => async ( args: SerializeHandlerArguments ): Promise> => { - const { logger, inputFilterSensitiveLog } = context; - - if (typeof logger?.info === "function") { - logger.info({ - input: inputFilterSensitiveLog(args.input), - }); - } - const request = await serializer(args.input, options); - return next({ ...args, request,