fix: move logging of input/output and req/res to serde (#1526)

* chore: move logging of input/request to serde

* chore: move logging of output/response to serde

* test: update loggerMiddleware tests

* test: add tests for serializerMiddleware

* test: add tests for deserializerMiddleware

* test: prefix mock to loggerMiddleware tests

Author: trivikr

packages/middleware-logger/src/loggerMiddleware.spec.ts

@@ -1,4 +1,4 @@
-import { BuildHandlerArguments, Logger, MiddlewareStack } from "@aws-sdk/types";
+import { Logger, MiddlewareStack } from "@aws-sdk/types";
 
 import { getLoggerPlugin, loggerMiddleware, loggerMiddlewareOptions } from "./loggerMiddleware";
 
@@ -19,9 +19,9 @@ describe("getLoggerPlugin", () => {
 });
 
 describe("loggerMiddleware", () => {
-  const next = jest.fn();
+  const mockNext = jest.fn();
 
-  const args = {
+  const mockArgs = {
     input: {
       inputKey: "inputValue",
     },
@@ -32,10 +32,6 @@ describe("loggerMiddleware", () => {
   };
 
   const mockResponse = {
-    response: {
-      statusCode: 200,
-      headers: {},
-    },
     output: {
       $metadata: {
         statusCode: 200,
@@ -46,67 +42,44 @@ describe("loggerMiddleware", () => {
   };
 
   beforeEach(() => {
-    next.mockResolvedValueOnce(mockResponse);
+    mockNext.mockResolvedValueOnce(mockResponse);
   });
 
   afterEach(() => {
     jest.clearAllMocks();
   });
 
   it("returns without logging if context.logger is not defined", async () => {
-    const response = await loggerMiddleware()(next, {})(args as BuildHandlerArguments<any>);
-    expect(next).toHaveBeenCalledTimes(1);
+    const response = await loggerMiddleware()(mockNext, {})(mockArgs);
+    expect(mockNext).toHaveBeenCalledTimes(1);
     expect(response).toStrictEqual(mockResponse);
   });
 
-  it("returns without logging if context.logger doesn't have debug/info functions", async () => {
+  it("returns without logging if context.logger doesn't have info function", async () => {
     const logger = {} as Logger;
-    const response = await loggerMiddleware()(next, { logger })(args as BuildHandlerArguments<any>);
-    expect(next).toHaveBeenCalledTimes(1);
+    const response = await loggerMiddleware()(mockNext, { logger })(mockArgs);
+    expect(mockNext).toHaveBeenCalledTimes(1);
     expect(response).toStrictEqual(mockResponse);
   });
 
-  it("logs $metadata, input, output if context.logger has info function", async () => {
+  it("logs $metadata if context.logger has info function", async () => {
     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()(next, context)(args as BuildHandlerArguments<any>);
-    expect(next).toHaveBeenCalledTimes(1);
+    const response = await loggerMiddleware()(mockNext, context)(mockArgs);
+    expect(mockNext).toHaveBeenCalledTimes(1);
     expect(response).toStrictEqual(mockResponse);
 
-    expect(inputFilterSensitiveLog).toHaveBeenCalledTimes(1);
-    expect(outputFilterSensitiveLog).toHaveBeenCalledTimes(1);
     expect(logger.info).toHaveBeenCalledTimes(1);
 
     const {
-      output: { $metadata, ...outputWithoutMetadata },
+      output: { $metadata },
     } = mockResponse;
     expect(logger.info).toHaveBeenCalledWith({
       $metadata,
-      input: args.input,
-      output: outputWithoutMetadata,
-    });
-  });
-
-  it("logs httpRequest, httpResponse if context.logger has debug function", async () => {
-    const logger = ({ debug: jest.fn() } as unknown) as Logger;
-    const response = await loggerMiddleware()(next, { logger })(args as BuildHandlerArguments<any>);
-    expect(next).toHaveBeenCalledTimes(1);
-    expect(response).toStrictEqual(mockResponse);
-
-    expect(logger.debug).toHaveBeenCalledTimes(2);
-    expect(logger.debug).toHaveBeenNthCalledWith(1, {
-      httpRequest: args.request,
-    });
-    expect(logger.debug).toHaveBeenNthCalledWith(2, {
-      httpResponse: mockResponse.response,
     });
   });
 });

packages/middleware-logger/src/loggerMiddleware.ts

@@ -13,7 +13,7 @@ export const loggerMiddleware = () => <Output extends MetadataBearer = MetadataB
   next: BuildHandler<any, Output>,
   context: HandlerExecutionContext
 ): BuildHandler<any, Output> => async (args: BuildHandlerArguments<any>): Promise<BuildHandlerOutput<Output>> => {
-  const { logger, inputFilterSensitiveLog, outputFilterSensitiveLog } = context;
+  const { logger } = context;
 
   const response = await next(args);
 
@@ -22,23 +22,14 @@ export const loggerMiddleware = () => <Output extends MetadataBearer = MetadataB
   }
 
   const {
-    output: { $metadata, ...outputWithoutMetadata },
+    output: { $metadata },
   } = response;
 
-  if (typeof logger.debug === "function") {
-    logger.debug({
-      httpRequest: args.request,
-    });
-    logger.debug({
-      httpResponse: response.response,
-    });
-  }
-
+  // TODO: Populate custom metadata in https://github.com/aws/aws-sdk-js-v3/issues/1491#issuecomment-692174256
+  // $metadata will be removed in https://github.com/aws/aws-sdk-js-v3/issues/1490
   if (typeof logger.info === "function") {
     logger.info({
       $metadata,
-      input: inputFilterSensitiveLog(args.input),
-      output: outputFilterSensitiveLog(outputWithoutMetadata),
     });
   }
 

packages/middleware-serde/jest.config.js

@@ -0,0 +1,5 @@
+const base = require("../../jest.config.base.js");
+
+module.exports = {
+  ...base,
+};

packages/middleware-serde/src/deserializerMiddleware.spec.ts

@@ -0,0 +1,98 @@
+import { Logger } from "@aws-sdk/types";
+
+import { deserializerMiddleware } from "./deserializerMiddleware";
+
+describe("deserializerMiddleware", () => {
+  const mockNext = jest.fn();
+  const mockDeserializer = jest.fn();
+
+  const mockOptions = {
+    endpoint: () =>
+      Promise.resolve({
+        protocol: "protocol",
+        hostname: "hostname",
+        path: "path",
+      }),
+  };
+
+  const mockArgs = {
+    input: {
+      inputKey: "inputValue",
+    },
+    request: {
+      method: "GET",
+      headers: {},
+    },
+  };
+
+  const mockOutput = {
+    $metadata: {
+      statusCode: 200,
+      requestId: "requestId",
+    },
+    outputKey: "outputValue",
+  };
+
+  const mockNextResponse = {
+    response: {
+      statusCode: 200,
+      headers: {},
+    },
+  };
+
+  const mockResponse = {
+    response: mockNextResponse.response,
+    output: mockOutput,
+  };
+
+  beforeEach(() => {
+    mockNext.mockResolvedValueOnce(mockNextResponse);
+    mockDeserializer.mockResolvedValueOnce(mockOutput);
+  });
+
+  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;
+
+    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 });
+  });
+
+  it("logs response if context.logger has debug function", async () => {
+    const logger = ({ debug: jest.fn() } as unknown) as Logger;
+
+    const response = await deserializerMiddleware(mockOptions, mockDeserializer)(mockNext, { logger })(mockArgs);
+
+    expect(response).toStrictEqual(mockResponse);
+    expect(logger.debug).toHaveBeenCalledTimes(1);
+    expect(logger.debug).toHaveBeenCalledWith({ httpResponse: mockNextResponse.response });
+  });
+});

packages/middleware-serde/src/deserializerMiddleware.ts

@@ -3,21 +3,42 @@ import {
   DeserializeHandlerArguments,
   DeserializeHandlerOutput,
   DeserializeMiddleware,
+  HandlerExecutionContext,
   ResponseDeserializer,
 } from "@aws-sdk/types";
 
-export function deserializerMiddleware<Input extends object, Output extends object, RuntimeUtils = any>(
+export const deserializerMiddleware = <Input extends object, Output extends object, RuntimeUtils = any>(
   options: RuntimeUtils,
   deserializer: ResponseDeserializer<any, any, RuntimeUtils>
-): DeserializeMiddleware<Input, Output> {
-  return (next: DeserializeHandler<Input, Output>): DeserializeHandler<Input, Output> => async (
-    args: DeserializeHandlerArguments<Input>
-  ): Promise<DeserializeHandlerOutput<Output>> => {
-    const { response } = await next(args);
-    const parsed = await deserializer(response, options);
-    return {
-      response,
-      output: parsed as Output,
-    };
+): DeserializeMiddleware<Input, Output> => (
+  next: DeserializeHandler<Input, Output>,
+  context: HandlerExecutionContext
+): DeserializeHandler<Input, Output> => async (
+  args: DeserializeHandlerArguments<Input>
+): Promise<DeserializeHandlerOutput<Output>> => {
+  const { logger, outputFilterSensitiveLog } = context;
+
+  const { response } = await next(args);
+
+  if (typeof logger?.debug === "function") {
+    logger.debug({
+      httpResponse: response,
+    });
+  }
+
+  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,
   };
-}
+};

packages/middleware-serde/src/serializerMiddleware.spec.ts

@@ -0,0 +1,96 @@
+import { Logger } from "@aws-sdk/types";
+
+import { serializerMiddleware } from "./serializerMiddleware";
+
+describe("serializerMiddleware", () => {
+  const mockNext = jest.fn();
+  const mockSerializer = jest.fn();
+
+  const mockOptions = {
+    endpoint: () =>
+      Promise.resolve({
+        protocol: "protocol",
+        hostname: "hostname",
+        path: "path",
+      }),
+  };
+
+  const mockArgs = {
+    input: {
+      inputKey: "inputValue",
+    },
+  };
+
+  const mockRequest = {
+    method: "GET",
+    headers: {},
+  };
+
+  const mockResponse = {
+    statusCode: 200,
+    headers: {},
+  };
+
+  const mockOutput = {
+    $metadata: {
+      statusCode: 200,
+      requestId: "requestId",
+    },
+    outputKey: "outputValue",
+  };
+
+  const mockReturn = {
+    response: mockResponse,
+    output: mockOutput,
+  };
+
+  beforeEach(() => {
+    mockNext.mockResolvedValueOnce(mockReturn);
+    mockSerializer.mockResolvedValueOnce(mockRequest);
+  });
+
+  afterEach(() => {
+    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 });
+  });
+
+  it("logs request if context.logger has debug function", async () => {
+    const logger = ({ debug: jest.fn() } as unknown) as Logger;
+
+    const response = await serializerMiddleware(mockOptions, mockSerializer)(mockNext, { logger })(mockArgs);
+
+    expect(response).toStrictEqual(mockReturn);
+    expect(logger.debug).toHaveBeenCalledTimes(1);
+    expect(logger.debug).toHaveBeenCalledWith({ httpRequest: mockRequest });
+  });
+});