feat(logging): Log buffering support for Logj42 and Logback (#2103)

* Log buffer PoC with log4j2 appender implementation.

* Add buffer cleaning to avoid memory leak and flushBufferOnUncaughtError option to Logging aspect.

* Call appenders with logevent directly from BufferingAppender.

* Extract buffer management logic into KeyBuffer class and keep log4j appender minimal.

* Unit tests for BufferingAppender

* Rename to Log4jConstants.

* Make Appender detection independent of plugin name.

* Add assertions in unit test to test multiple appenders.

* Make assertion stronger to assert that each message appears twice because we configured two appenders as proxies.

* Add logback implementation. Decouple KeyBuffer and BufferingAppender to avoid circular dependency when flushing buffer on error.

* Log error in AppStream example.

* Update Logging E2E test to use log buffering.

* Prepare Logging E2E test to support paramaterized versions by logging backend.

* Add Logging E2E tests for both logback and log4j2.

* Debug not found appender on Linux.

* Isolate log4j context loading in unit tests.

* Avoid logging config leakage in log4j unit test.

* Avoid config leaking in logback unit tests.

* Update Graal metadata for powertools-logging.

* Update Graal metadata for powertools-logging-log4j.

* Update Graal metadata for powertools-logging-logback.

* Address Sonar findings.

* Address pmd findings.

* Set allowCommentedBlocks=true in pmd rules.

* Fix thread-safety issue in double-checked singleton instance creation.

* Increase scope of thread-safety tests in KeyBuffer.

* Try to satisfy pmd executor service closing.

* Try to satisfy pmd executor service closing.

* Add PMD suppressions with reason where appropriate.

* Add PMD suppressions with reason where appropriate.

* Restore original example.

* Enable log sampling again.

* Restore formatting in pmd ruleset.

* Update Javadoc of BufferingAppenders.

* Remove unncessary cleanup.

* Remove duplicated infrastructure clearnup in LoggingE2E.

* Make javadoc for Keybuffer more concise.

* Add comment for large event rejection.

* Fix grammer in error message.

* Remove redundant tests in PowertoolsLoggingTest.

* Add developer documentation.

* Fix sonar finding.

* Clarify log buffering log level configuration with upper and lower bound example.

* Update docs/core/logging.md

Co-authored-by: Stefano Vozza <svozza@gmail.com>

* Update docs/core/logging.md

Co-authored-by: Stefano Vozza <svozza@gmail.com>

---------

Co-authored-by: Stefano Vozza <svozza@gmail.com>

Author: phipag

.github/pmd-ruleset.xml

@@ -350,6 +350,9 @@
     </rule>
     <rule ref="category/java/errorprone.xml/EmptyCatchBlock">
         <priority>1</priority>
+        <properties>
+            <property name="allowCommentedBlocks" value="true" />
+        </properties>
     </rule>
     <!--     <rule ref="category/java/errorprone.xml/EmptyFinalizer" /> -->
     <!--     <rule ref="category/java/errorprone.xml/EmptyFinallyBlock" /> -->
@@ -641,4 +644,4 @@
             </property>
         </properties>
     </rule>
-</ruleset>
+</ruleset>

docs/core/logging.md

@@ -97,11 +97,6 @@ public APIGatewayProxyResponseEvent handleRequest(final APIGatewayProxyRequestEv
         }
     }
 
-    @Tracing
-    private void log() {
-        log.info("inside threaded logging for function");
-    }
-
     @Tracing(namespace = "getPageContents", captureMode = CaptureMode.DISABLED)
     private String getPageContents(String address) throws IOException {
         URL url = new URL(address);

examples/powertools-examples-core-utilities/sam/src/main/java/helloworld/App.java

@@ -14,46 +14,49 @@
 
 package helloworld;
 
-import com.amazonaws.services.lambda.runtime.Context;
-import com.amazonaws.services.lambda.runtime.RequestStreamHandler;
-import com.fasterxml.jackson.databind.ObjectMapper;
-
+import java.io.BufferedReader;
+import java.io.BufferedWriter;
 import java.io.IOException;
 import java.io.InputStream;
+import java.io.InputStreamReader;
 import java.io.OutputStream;
+import java.io.OutputStreamWriter;
+import java.io.PrintWriter;
 import java.nio.charset.StandardCharsets;
 
-import org.apache.logging.log4j.LogManager;
-import org.apache.logging.log4j.Logger;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
+
+import com.amazonaws.services.lambda.runtime.Context;
+import com.amazonaws.services.lambda.runtime.RequestStreamHandler;
+import com.fasterxml.jackson.databind.ObjectMapper;
+
 import software.amazon.lambda.powertools.logging.Logging;
 import software.amazon.lambda.powertools.metrics.FlushMetrics;
 
-import java.io.InputStreamReader;
-import java.io.BufferedReader;
-import java.io.BufferedWriter;
-import java.io.OutputStreamWriter;
-import java.io.PrintWriter;
-
 public class AppStream implements RequestStreamHandler {
     private static final ObjectMapper mapper = new ObjectMapper();
-    private final static Logger log = LogManager.getLogger(AppStream.class);
+    private static final Logger log = LoggerFactory.getLogger(AppStream.class);
 
     @Override
     @Logging(logEvent = true)
     @FlushMetrics(namespace = "ServerlessAirline", service = "payment", captureColdStart = true)
-    // RequestStreamHandler can be used instead of RequestHandler for cases when you'd like to deserialize request body or serialize response body yourself, instead of allowing that to happen automatically
-    // Note that you still need to return a proper JSON for API Gateway to handle 
-    // See Lambda Response format for examples: https://docs.aws.amazon.com/apigateway/latest/developerguide/http-api-develop-integrations-lambda.html
+    // RequestStreamHandler can be used instead of RequestHandler for cases when you'd like to deserialize request body
+    // or serialize response body yourself, instead of allowing that to happen automatically
+    // Note that you still need to return a proper JSON for API Gateway to handle
+    // See Lambda Response format for examples:
+    // https://docs.aws.amazon.com/apigateway/latest/developerguide/http-api-develop-integrations-lambda.html
     public void handleRequest(InputStream input, OutputStream output, Context context) {
         try (BufferedReader reader = new BufferedReader(new InputStreamReader(input, StandardCharsets.UTF_8));
-             PrintWriter writer = new PrintWriter(new BufferedWriter(new OutputStreamWriter(output, StandardCharsets.UTF_8)))) {
+                PrintWriter writer = new PrintWriter(
+                        new BufferedWriter(new OutputStreamWriter(output, StandardCharsets.UTF_8)))) {
 
-            log.info("Received: " + mapper.writerWithDefaultPrettyPrinter().writeValueAsString(mapper.readTree(reader)));
+            log.info(
+                    "Received: " + mapper.writerWithDefaultPrettyPrinter().writeValueAsString(mapper.readTree(reader)));
 
             writer.write("{\"body\": \"" + System.currentTimeMillis() + "\"} ");
         } catch (IOException e) {
             log.error("Something has gone wrong: ", e);
         }
     }
 }
-

examples/powertools-examples-core-utilities/sam/src/main/java/helloworld/AppStream.java

@@ -4,13 +4,13 @@
         <Console name="JsonAppender" target="SYSTEM_OUT">
             <JsonTemplateLayout eventTemplateUri="classpath:LambdaJsonLayout.json" />
         </Console>
+        <BufferingAppender name="BufferedAppender" bufferAtVerbosity="DEBUG">
+            <AppenderRef ref="JsonAppender" />
+        </BufferingAppender>
     </Appenders>
     <Loggers>
-        <Logger name="JsonLogger" level="INFO" additivity="false">
-            <AppenderRef ref="JsonAppender"/>
-        </Logger>
-        <Root level="info">
-            <AppenderRef ref="JsonAppender"/>
+        <Root level="debug">
+            <AppenderRef ref="BufferedAppender" />
         </Root>
     </Loggers>
-</Configuration>
+</Configuration>

examples/powertools-examples-core-utilities/sam/src/main/resources/log4j2.xml

@@ -1,4 +1,4 @@
-AWSTemplateFormatVersion: '2010-09-09'
+AWSTemplateFormatVersion: "2010-09-09"
 Transform: AWS::Serverless-2016-10-31
 Description: >
   CoreUtilities
@@ -13,7 +13,7 @@ Globals:
     Environment:
       Variables:
         # Powertools for AWS Lambda (Java) env vars: https://docs.powertools.aws.dev/lambda/java/#environment-variables
-        POWERTOOLS_LOG_LEVEL: INFO
+        POWERTOOLS_LOG_LEVEL: DEBUG # We use log buffering to buffer DEBUG logs (see log4j2.xml)
         POWERTOOLS_LOGGER_SAMPLE_RATE: 0.1
         POWERTOOLS_LOGGER_LOG_EVENT: true
         POWERTOOLS_METRICS_NAMESPACE: Coreutilities

examples/powertools-examples-core-utilities/sam/template.yaml

@@ -8,20 +8,15 @@
         <version>2.3.0</version>
     </parent>
 
-    <artifactId>e2e-test-handler-logging</artifactId>
+    <artifactId>e2e-test-handler-logging-log4j</artifactId>
     <packaging>jar</packaging>
-    <name>E2E test handler – Logging</name>
+    <name>E2E test handler – Logging Log4j</name>
 
     <dependencies>
         <dependency>
             <groupId>software.amazon.lambda</groupId>
             <artifactId>powertools-logging-log4j</artifactId>
         </dependency>
-        <dependency>
-            <groupId>org.apache.logging.log4j</groupId>
-            <artifactId>log4j-layout-template-json</artifactId>
-            <version>2.25.1</version>
-        </dependency>
         <dependency>
             <groupId>org.aspectj</groupId>
             <artifactId>aspectjrt</artifactId>

powertools-e2e-tests/handlers/logging/pom.xml renamed to powertools-e2e-tests/handlers/logging-log4j/pom.xml

@@ -14,12 +14,15 @@
 
 package software.amazon.lambda.powertools.e2e;
 
-import com.amazonaws.services.lambda.runtime.Context;
-import com.amazonaws.services.lambda.runtime.RequestHandler;
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 import org.slf4j.MDC;
+
+import com.amazonaws.services.lambda.runtime.Context;
+import com.amazonaws.services.lambda.runtime.RequestHandler;
+
 import software.amazon.lambda.powertools.logging.Logging;
+import software.amazon.lambda.powertools.logging.PowertoolsLogging;
 
 public class Function implements RequestHandler<Input, String> {
     private static final Logger LOG = LoggerFactory.getLogger(Function.class);
@@ -29,6 +32,9 @@ public String handleRequest(Input input, Context context) {
         input.getKeys().forEach(MDC::put);
         LOG.info(input.getMessage());
 
+        // Flush buffer manually since we buffer at INFO level to test log buffering
+        PowertoolsLogging.flushBuffer();
+
         return "OK";
     }
-}
+}

powertools-e2e-tests/handlers/logging/src/main/java/software/amazon/lambda/powertools/e2e/Function.java renamed to powertools-e2e-tests/handlers/logging-log4j/src/main/java/software/amazon/lambda/powertools/e2e/Function.java

@@ -20,9 +20,6 @@ public class Input {
     private String message;
     private Map<String, String> keys;
 
-    public Input() {
-    }
-
     public String getMessage() {
         return message;
     }