feat(middleware-logger): log clientName, commandName, input, output

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,
+          },
+        },
+      });
     });
   });
 });

packages/middleware-logger/src/loggerMiddleware.ts

@@ -16,23 +16,31 @@ export const loggerMiddleware = () => <Output extends MetadataBearer = MetadataB
 ): InitializeHandler<any, Output> => async (
   args: InitializeHandlerArguments<any>
 ): Promise<InitializeHandlerOutput<Output>> => {
-  const { logger } = context;
+  const { clientName, commandName, inputFilterSensitiveLog, logger, outputFilterSensitiveLog } = context;
 
   const response = await next(args);
 
   if (!logger) {
     return response;
   }
 
-  const httpResponse = response.response as HttpResponse;
-
   if (typeof logger.info === "function") {
+    const httpResponse = response.response as HttpResponse;
+    const { $metadata, ...outputWithoutMetadata } = response.output;
     logger.info({
+      clientName,
+      commandName,
+      input: inputFilterSensitiveLog(args.input),
+      output: outputFilterSensitiveLog(outputWithoutMetadata),
       metadata: {
         statusCode: httpResponse.statusCode,
         requestId: httpResponse.headers["x-amzn-requestid"] ?? httpResponse.headers["x-amzn-request-id"],
         extendedRequestId: httpResponse.headers["x-amz-id-2"],
         cfId: httpResponse.headers["x-amz-cf-id"],
+        retry: {
+          attempts: $metadata.attempts,
+          totalDelay: $metadata.totalRetryDelay,
+        },
       },
     });
   }

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

@@ -1,5 +1,3 @@
-import { Logger } from "@aws-sdk/types";
-
 import { deserializerMiddleware } from "./deserializerMiddleware";
 
 describe("deserializerMiddleware", () => {
@@ -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);
   });
 });

packages/middleware-serde/src/deserializerMiddleware.ts

@@ -16,21 +16,8 @@ export const deserializerMiddleware = <Input extends object, Output extends obje
 ): DeserializeHandler<Input, Output> => async (
   args: DeserializeHandlerArguments<Input>
 ): Promise<DeserializeHandlerOutput<Output>> => {
-  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,

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 });
   });
 });

packages/middleware-serde/src/serializerMiddleware.ts

@@ -17,16 +17,7 @@ export const serializerMiddleware = <Input extends object, Output extends object
 ): SerializeHandler<Input, Output> => async (
   args: SerializeHandlerArguments<Input>
 ): Promise<SerializeHandlerOutput<Output>> => {
-  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,