Logging enhancements (#49)

* Util method to add multiple custom keys to logs

* test case for log level overrride via env variable

Co-authored-by: Pankaj Agrawal <[email protected]>

Author: pankajagrawal16

docs/content/core/logging.mdx

@@ -37,6 +37,20 @@ Powertools extends the functionality of Log4J. Below is an example log4j2.xml fi
 </Configuration>
 ```
 
+You can also override log level by setting `LOG_LEVEL` env var  - Here is an example using AWS Serverless Application Model (SAM)
+
+```yaml:title=template.yaml
+Resources:
+    HelloWorldFunction:
+        Type: AWS::Serverless::Function
+        Properties:
+        ...
+        Runtime: java8
+        Environment:
+            Variables:
+                LOG_LEVEL: DEBUG # highlight-line
+```
+
 You can also explicitly set a service name via `POWERTOOLS_SERVICE_NAME` env var. This sets **service** key that will be present across all log statements.
 
 ## Standard structured keys
@@ -137,6 +151,14 @@ public class App implements RequestHandler<APIGatewayProxyRequestEvent, APIGatew
         ...
         PowertoolsLogger.appendKey("test", "willBeLogged");
         ...
+
+        ...
+         Map<String, String> customKeys = new HashMap<>();
+         customKeys.put("test", "value");
+         customKeys.put("test1", "value1");
+
+         PowertoolsLogger.appendKeys(customKeys);
+        ...
     }
 }
 ```

powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/PowertoolsLogger.java

@@ -13,6 +13,8 @@
  */
 package software.amazon.lambda.powertools.logging;
 
+import java.util.Map;
+
 import org.apache.logging.log4j.ThreadContext;
 
 /**
@@ -32,4 +34,15 @@ public class PowertoolsLogger {
     public static void appendKey(String key, String value) {
         ThreadContext.put(key, value);
     }
+
+
+    /**
+     * Appends additional key and value to each log entry made. Duplicate values
+     * for the same key will be replaced with the latest.
+     *
+     * @param customKeys Map of custom keys values to be appended to logs
+     */
+    public static void appendKeys(Map<String, String> customKeys) {
+        ThreadContext.putAll(customKeys);
+    }
 }

powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/internal/LambdaLoggingAspect.java

@@ -49,17 +49,21 @@
 @Aspect
 public final class LambdaLoggingAspect {
     private static final ObjectMapper mapper = new ObjectMapper();
-    private static final String LOG_LEVEL = System.getenv("LOG_LEVEL");
+    private static String LOG_LEVEL = System.getenv("LOG_LEVEL");
 
     static {
+        resetLogLevels();
+    }
+
+    private static void resetLogLevels() {
         if (LOG_LEVEL != null) {
             LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
             Configurator.setAllLevels(LogManager.getRootLogger().getName(), Level.getLevel(LOG_LEVEL));
             ctx.updateLoggers();
         }
     }
 
-    @SuppressWarnings({"EmptyMethod", "unused"})
+    @SuppressWarnings({"EmptyMethod"})
     @Pointcut("@annotation(powertoolsLogging)")
     public void callAt(PowertoolsLogging powertoolsLogging) {
     }

powertools-logging/src/test/java/org/apache/logging/log4j/core/layout/LambdaJsonLayoutTest.java

@@ -14,6 +14,8 @@
 package org.apache.logging.log4j.core.layout;
 
 import java.io.IOException;
+import java.lang.reflect.InvocationTargetException;
+import java.lang.reflect.Method;
 import java.nio.channels.FileChannel;
 import java.nio.file.Files;
 import java.nio.file.Paths;
@@ -28,8 +30,10 @@
 import org.junit.jupiter.api.Test;
 import org.mockito.Mock;
 import software.amazon.lambda.powertools.logging.handlers.PowerLogToolEnabled;
+import software.amazon.lambda.powertools.logging.internal.LambdaLoggingAspect;
 
 import static java.util.Collections.emptyMap;
+import static org.apache.commons.lang3.reflect.FieldUtils.writeStaticField;
 import static org.assertj.core.api.Assertions.assertThat;
 import static org.assertj.core.api.Assertions.fail;
 import static org.mockito.Mockito.when;
@@ -43,11 +47,13 @@ class LambdaJsonLayoutTest {
     private Context context;
 
     @BeforeEach
-    void setUp() throws IOException {
+    void setUp() throws IOException, IllegalAccessException, NoSuchMethodException, InvocationTargetException {
         initMocks(this);
         setupContext();
         //Make sure file is cleaned up before running full stack logging regression
         FileChannel.open(Paths.get("target/logfile.json"), StandardOpenOption.WRITE).truncate(0).close();
+        writeStaticField(LambdaLoggingAspect.class, "LOG_LEVEL", "INFO", true);
+        resetLogLevel();
     }
 
     @Test
@@ -66,6 +72,32 @@ void shouldLogInStructuredFormat() throws IOException {
                         .containsKey("service"));
     }
 
+    @Test
+    void shouldModifyLogLevelBasedOnEnvVariable() throws IllegalAccessException, IOException, NoSuchMethodException, InvocationTargetException {
+        writeStaticField(LambdaLoggingAspect.class, "LOG_LEVEL", "DEBUG", true);
+        resetLogLevel();
+
+        handler.handleRequest("test", context);
+
+        assertThat(Files.lines(Paths.get("target/logfile.json")))
+                .hasSize(2)
+                .satisfies(line -> {
+                    assertThat(parseToMap(line.get(0)))
+                            .containsEntry("level", "INFO")
+                            .containsEntry("message", "Test event");
+
+                    assertThat(parseToMap(line.get(1)))
+                            .containsEntry("level", "DEBUG")
+                            .containsEntry("message", "Test debug event");
+                });
+    }
+
+    private void resetLogLevel() throws NoSuchMethodException, IllegalAccessException, InvocationTargetException {
+        Method resetLogLevels = LambdaLoggingAspect.class.getDeclaredMethod("resetLogLevels");
+        resetLogLevels.setAccessible(true);
+        resetLogLevels.invoke(null);
+    }
+
     private Map<String, Object> parseToMap(String stringAsJson) {
         try {
             return new ObjectMapper().readValue(stringAsJson, Map.class);

powertools-logging/src/test/java/software/amazon/lambda/powertools/logging/PowertoolsLoggerTest.java

@@ -13,6 +13,9 @@
  */
 package software.amazon.lambda.powertools.logging;
 
+import java.util.HashMap;
+import java.util.Map;
+
 import org.apache.logging.log4j.ThreadContext;
 import org.junit.jupiter.api.BeforeEach;
 import org.junit.jupiter.api.Test;
@@ -35,4 +38,18 @@ void shouldSetCustomKeyOnThreadContext() {
                 .hasSize(1)
                 .containsEntry("test", "value");
     }
+
+    @Test
+    void shouldSetCustomKeyAsMapOnThreadContext() {
+        Map<String, String> customKeys = new HashMap<>();
+        customKeys.put("test", "value");
+        customKeys.put("test1", "value1");
+
+        PowertoolsLogger.appendKeys(customKeys);
+
+        assertThat(ThreadContext.getImmutableContext())
+                .hasSize(2)
+                .containsEntry("test", "value")
+                .containsEntry("test1", "value1");
+    }
 }

powertools-logging/src/test/java/software/amazon/lambda/powertools/logging/handlers/PowerLogToolEnabled.java

@@ -26,6 +26,7 @@ public class PowerLogToolEnabled implements RequestHandler<Object, Object> {
     @PowertoolsLogging
     public Object handleRequest(Object input, Context context) {
         LOG.info("Test event");
+        LOG.debug("Test debug event");
         return null;
     }