feat(middleware-logger): log request errors (#4252)

Author: simonbuchan

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

@@ -72,6 +72,14 @@ describe("loggerMiddleware", () => {
     expect(response).toStrictEqual(mockResponse);
   });
 
+  it("rejects without logging if context.logger doesn't have error function", async () => {
+    const nextError = new Error("next error");
+    mockNext.mockRejectedValueOnce(nextError);
+    const logger = {} as Logger;
+    const response = await expect(loggerMiddleware()(mockNext, { logger })(mockArgs)).rejects.toThrow(nextError);
+    expect(mockNext).toHaveBeenCalledTimes(1);
+  });
+
   describe("logs if context.logger has info function", () => {
     it("success case with clientName, commandName, input, metadata", async () => {
       mockNext.mockResolvedValueOnce(mockResponse);
@@ -198,4 +206,120 @@ describe("loggerMiddleware", () => {
       });
     });
   });
+
+  describe("logs if context.logger has error function", () => {
+    it("should reject if next throws synchronously", async () => {
+      const { $metadata } = mockOutput;
+      const nextError = new Error("example error");
+      Object.assign(nextError, { $metadata });
+      mockNext.mockImplementationOnce(() => {
+        throw nextError;
+      });
+
+      const clientName = "mockClientName";
+      const commandName = "mockCommandName";
+
+      const logger = { error: jest.fn() } as unknown as Logger;
+      const inputFilterSensitiveLog = jest.fn().mockImplementationOnce((input) => input);
+      const outputFilterSensitiveLog = jest.fn().mockImplementationOnce((output) => output);
+
+      const context = {
+        clientName,
+        commandName,
+        logger,
+        inputFilterSensitiveLog,
+        outputFilterSensitiveLog,
+      };
+
+      await expect(loggerMiddleware()(mockNext, context)(mockArgs)).rejects.toThrow(nextError);
+      expect(mockNext).toHaveBeenCalledTimes(1);
+
+      expect(logger.error).toHaveBeenCalledTimes(1);
+      expect(logger.error).toHaveBeenCalledWith({
+        clientName,
+        commandName,
+        input: mockArgs.input,
+        error: nextError,
+        metadata: $metadata,
+      });
+    });
+
+    it("should reject if next rejects", async () => {
+      const { $metadata } = mockOutput;
+      const nextError = new Error("example error");
+      Object.assign(nextError, { $metadata });
+      mockNext.mockRejectedValueOnce(nextError);
+
+      const clientName = "mockClientName";
+      const commandName = "mockCommandName";
+
+      const logger = { error: jest.fn() } as unknown as Logger;
+      const inputFilterSensitiveLog = jest.fn().mockImplementationOnce((input) => input);
+      const outputFilterSensitiveLog = jest.fn().mockImplementationOnce((output) => output);
+
+      const context = {
+        clientName,
+        commandName,
+        logger,
+        inputFilterSensitiveLog,
+        outputFilterSensitiveLog,
+      };
+
+      await expect(loggerMiddleware()(mockNext, context)(mockArgs)).rejects.toThrow(nextError);
+      expect(mockNext).toHaveBeenCalledTimes(1);
+
+      expect(logger.error).toHaveBeenCalledTimes(1);
+      expect(logger.error).toHaveBeenCalledWith({
+        clientName,
+        commandName,
+        input: mockArgs.input,
+        error: nextError,
+        metadata: $metadata,
+      });
+    });
+
+    it("should use override log filters for DynamoDBDocumentClient if present", async () => {
+      const { $metadata } = mockOutput;
+      const nextError = new Error("example error");
+      Object.assign(nextError, { $metadata });
+      mockNext.mockRejectedValueOnce(nextError);
+
+      const logger = { error: 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: HandlerExecutionContext = {
+        logger,
+        clientName,
+        commandName,
+        dynamoDbDocumentClientOptions: {
+          overrideInputFilterSensitiveLog: inputFilterSensitiveLog,
+          overrideOutputFilterSensitiveLog: outputFilterSensitiveLog,
+        },
+        inputFilterSensitiveLog() {
+          throw new Error("should not be called");
+        },
+        outputFilterSensitiveLog() {
+          throw new Error("should not be called");
+        },
+      };
+
+      await expect(loggerMiddleware()(mockNext, context)(mockArgs)).rejects.toThrow(nextError);
+      expect(mockNext).toHaveBeenCalledTimes(1);
+
+      expect(logger.error).toHaveBeenCalledTimes(1);
+      expect(logger.error).toHaveBeenCalledWith({
+        clientName,
+        commandName,
+        input: mockInputLog,
+        error: nextError,
+        metadata: $metadata,
+      });
+    });
+  });
 });

packages/middleware-logger/src/loggerMiddleware.ts

@@ -16,35 +16,33 @@ export const loggerMiddleware =
     context: HandlerExecutionContext
   ): InitializeHandler<any, Output> =>
   async (args: InitializeHandlerArguments<any>): Promise<InitializeHandlerOutput<Output>> => {
-    const response = await next(args);
-    const {
-      clientName,
-      commandName,
-      logger,
-      inputFilterSensitiveLog,
-      outputFilterSensitiveLog,
-      dynamoDbDocumentClientOptions = {},
-    } = context;
+    const { clientName, commandName, logger, dynamoDbDocumentClientOptions = {} } = context;
 
     const { overrideInputFilterSensitiveLog, overrideOutputFilterSensitiveLog } = dynamoDbDocumentClientOptions;
+    const inputFilterSensitiveLog = overrideInputFilterSensitiveLog ?? context.inputFilterSensitiveLog;
+    const outputFilterSensitiveLog = overrideOutputFilterSensitiveLog ?? context.outputFilterSensitiveLog;
 
-    if (!logger) {
-      return response;
-    }
-
-    if (typeof logger.info === "function") {
+    try {
+      const response = await next(args);
       const { $metadata, ...outputWithoutMetadata } = response.output;
-
-      logger.info({
+      logger?.info?.({
         clientName,
         commandName,
-        input: (overrideInputFilterSensitiveLog ?? inputFilterSensitiveLog)(args.input),
-        output: (overrideOutputFilterSensitiveLog ?? outputFilterSensitiveLog)(outputWithoutMetadata),
+        input: inputFilterSensitiveLog(args.input),
+        output: outputFilterSensitiveLog(outputWithoutMetadata),
         metadata: $metadata,
       });
+      return response;
+    } catch (error) {
+      logger?.error?.({
+        clientName,
+        commandName,
+        input: inputFilterSensitiveLog(args.input),
+        error,
+        metadata: (error as any).$metadata,
+      });
+      throw error;
     }
-
-    return response;
   };
 
 export const loggerMiddlewareOptions: InitializeHandlerOptions & AbsoluteLocation = {