fix: Log event via object mapper and not depend on toString

pom.xml

@@ -190,6 +190,12 @@
                 <version>3.17.2</version>
                 <scope>test</scope>
             </dependency>
+            <dependency>
+                <groupId>org.skyscreamer</groupId>
+                <artifactId>jsonassert</artifactId>
+                <version>1.5.0</version>
+                <scope>test</scope>
+            </dependency>
             <dependency>
                 <groupId>org.aspectj</groupId>
                 <artifactId>aspectjtools</artifactId>

powertools-logging/pom.xml

@@ -103,6 +103,16 @@
             <artifactId>assertj-core</artifactId>
             <scope>test</scope>
         </dependency>
+        <dependency>
+            <groupId>com.amazonaws</groupId>
+            <artifactId>aws-lambda-java-events</artifactId>
+            <scope>test</scope>
+        </dependency>
+        <dependency>
+            <groupId>org.skyscreamer</groupId>
+            <artifactId>jsonassert</artifactId>
+            <scope>test</scope>
+        </dependency>
     </dependencies>
 
 </project>

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

@@ -23,6 +23,7 @@
 import java.util.Optional;
 import java.util.Random;
 
+import com.fasterxml.jackson.core.JsonProcessingException;
 import com.fasterxml.jackson.databind.ObjectMapper;
 import org.apache.logging.log4j.Level;
 import org.apache.logging.log4j.LogManager;
@@ -37,6 +38,7 @@
 import software.amazon.lambda.powertools.logging.PowertoolsLogging;
 
 import static java.util.Optional.empty;
+import static java.util.Optional.of;
 import static java.util.Optional.ofNullable;
 import static software.amazon.lambda.powertools.core.internal.LambdaHandlerProcessor.coldStartDone;
 import static software.amazon.lambda.powertools.core.internal.LambdaHandlerProcessor.extractContext;
@@ -147,7 +149,8 @@ private Object[] logEvent(final ProceedingJoinPoint pjp) {
         if (isHandlerMethod(pjp)) {
             if (placedOnRequestHandler(pjp)) {
                 Logger log = logger(pjp);
-                log.info(pjp.getArgs()[0]);
+                asJson(pjp, pjp.getArgs()[0])
+                        .ifPresent(log::info);
             }
 
             if (placedOnStreamHandler(pjp)) {
@@ -171,7 +174,9 @@ private Object[] logFromInputStream(final ProceedingJoinPoint pjp) {
             args[0] = new ByteArrayInputStream(bytes);
 
             Logger log = logger(pjp);
-            log.info(MAPPER.readValue(bytes, Map.class));
+
+            asJson(pjp, MAPPER.readValue(bytes, Map.class))
+                    .ifPresent(log::info);
 
         } catch (IOException e) {
             Logger log = logger(pjp);
@@ -181,14 +186,24 @@ private Object[] logFromInputStream(final ProceedingJoinPoint pjp) {
         return args;
     }
 
+    private Optional<String> asJson(final ProceedingJoinPoint pjp,
+                                    final Object target) {
+        try {
+            return ofNullable(MAPPER.writeValueAsString(target));
+        } catch (JsonProcessingException e) {
+            logger(pjp).error("Failed logging event of type {}", target.getClass(), e);
+            return empty();
+        }
+    }
+
     private Logger logger(final ProceedingJoinPoint pjp) {
         return LogManager.getLogger(pjp.getSignature().getDeclaringType());
     }
 
     private static Optional<String> getXrayTraceId() {
         final String X_AMZN_TRACE_ID = getenv("_X_AMZN_TRACE_ID");
         if(X_AMZN_TRACE_ID != null) {
-            return ofNullable(X_AMZN_TRACE_ID.split(";")[0].replace("Root=", ""));
+            return of(X_AMZN_TRACE_ID.split(";")[0].replace("Root=", ""));
         }
         return empty();
     }

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

@@ -39,7 +39,7 @@
 import static org.assertj.core.api.Assertions.assertThat;
 import static org.assertj.core.api.Assertions.fail;
 import static org.mockito.Mockito.when;
-import static org.mockito.MockitoAnnotations.initMocks;
+import static org.mockito.MockitoAnnotations.openMocks;
 
 class LambdaJsonLayoutTest {
 
@@ -50,7 +50,7 @@ class LambdaJsonLayoutTest {
 
     @BeforeEach
     void setUp() throws IOException, IllegalAccessException, NoSuchMethodException, InvocationTargetException {
-        initMocks(this);
+        openMocks(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();

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

@@ -20,7 +20,7 @@
 import software.amazon.lambda.powertools.logging.PowertoolsLogging;
 
 public class PowerLogToolEnabled implements RequestHandler<Object, Object> {
-    private final Logger LOG = LogManager.getLogger(PowerToolLogEventEnabled.class);
+    private final Logger LOG = LogManager.getLogger(PowerLogToolEnabled.class);
 
     @Override
     @PowertoolsLogging

powertools-logging/src/test/java/software/amazon/lambda/powertools/logging/internal/LambdaLoggingAspectTest.java

@@ -13,23 +13,33 @@
  */
 package software.amazon.lambda.powertools.logging.internal;
 
+import java.io.BufferedReader;
 import java.io.ByteArrayInputStream;
 import java.io.ByteArrayOutputStream;
 import java.io.IOException;
+import java.io.InputStreamReader;
+import java.lang.reflect.InvocationTargetException;
+import java.lang.reflect.Method;
+import java.nio.channels.FileChannel;
 import java.nio.charset.StandardCharsets;
-import java.util.HashMap;
+import java.nio.file.Files;
+import java.nio.file.Paths;
+import java.nio.file.StandardOpenOption;
 import java.util.Map;
 
 import com.amazonaws.services.lambda.runtime.Context;
 import com.amazonaws.services.lambda.runtime.RequestHandler;
 import com.amazonaws.services.lambda.runtime.RequestStreamHandler;
+import com.amazonaws.services.lambda.runtime.events.models.s3.S3EventNotification;
+import com.fasterxml.jackson.core.JsonProcessingException;
 import com.fasterxml.jackson.databind.ObjectMapper;
+import org.apache.logging.log4j.Level;
 import org.apache.logging.log4j.ThreadContext;
+import org.json.JSONException;
 import org.junit.jupiter.api.BeforeEach;
 import org.junit.jupiter.api.Test;
 import org.mockito.Mock;
 import org.mockito.MockedStatic;
-import org.mockito.Mockito;
 import software.amazon.lambda.powertools.core.internal.LambdaHandlerProcessor;
 import software.amazon.lambda.powertools.logging.handlers.PowerLogToolEnabled;
 import software.amazon.lambda.powertools.logging.handlers.PowerLogToolEnabledForStream;
@@ -38,11 +48,23 @@
 import software.amazon.lambda.powertools.logging.handlers.PowerToolLogEventEnabled;
 import software.amazon.lambda.powertools.logging.handlers.PowerToolLogEventEnabledForStream;
 
+import static com.amazonaws.services.lambda.runtime.events.models.s3.S3EventNotification.RequestParametersEntity;
+import static com.amazonaws.services.lambda.runtime.events.models.s3.S3EventNotification.ResponseElementsEntity;
+import static com.amazonaws.services.lambda.runtime.events.models.s3.S3EventNotification.S3BucketEntity;
+import static com.amazonaws.services.lambda.runtime.events.models.s3.S3EventNotification.S3Entity;
+import static com.amazonaws.services.lambda.runtime.events.models.s3.S3EventNotification.S3EventNotificationRecord;
+import static com.amazonaws.services.lambda.runtime.events.models.s3.S3EventNotification.S3ObjectEntity;
+import static com.amazonaws.services.lambda.runtime.events.models.s3.S3EventNotification.UserIdentityEntity;
+import static java.util.Collections.emptyMap;
+import static java.util.Collections.singletonList;
+import static java.util.stream.Collectors.joining;
 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.mockStatic;
 import static org.mockito.Mockito.when;
 import static org.mockito.MockitoAnnotations.openMocks;
+import static org.skyscreamer.jsonassert.JSONAssert.assertEquals;
 import static software.amazon.lambda.powertools.logging.internal.SystemWrapper.getenv;
 
 class LambdaLoggingAspectTest {
@@ -55,13 +77,16 @@ class LambdaLoggingAspectTest {
     private Context context;
 
     @BeforeEach
-    void setUp() throws IllegalAccessException {
+    void setUp() throws IllegalAccessException, IOException, NoSuchMethodException, InvocationTargetException {
         openMocks(this);
         ThreadContext.clearAll();
         writeStaticField(LambdaHandlerProcessor.class, "IS_COLD_START", null, true);
         setupContext();
         requestHandler = new PowerLogToolEnabled();
         requestStreamHandler = new PowerLogToolEnabledForStream();
+        //Make sure file is cleaned up before running full stack logging regression
+        FileChannel.open(Paths.get("target/logfile.json"), StandardOpenOption.WRITE).truncate(0).close();
+        resetLogLevel(Level.INFO);
     }
 
     @Test
@@ -140,30 +165,41 @@ void shouldHaveNoEffectIfNotUsedOnLambdaHandler() {
     }
 
     @Test
-    void shouldLogEventForHandler() {
+    void shouldLogEventForHandler() throws IOException, JSONException {
         requestHandler = new PowerToolLogEventEnabled();
+        S3EventNotification s3EventNotification = s3EventNotification();
 
-        requestHandler.handleRequest(new Object(), context);
+        requestHandler.handleRequest(s3EventNotification, context);
 
-        assertThat(ThreadContext.getImmutableContext())
-                .hasSize(EXPECTED_CONTEXT_SIZE);
+        Map<String, Object> log = parseToMap(Files.lines(Paths.get("target/logfile.json")).collect(joining()));
+
+        String event = (String) log.get("message");
+
+        String expectEvent = new BufferedReader(new InputStreamReader(this.getClass().getResourceAsStream("/s3EventNotification.json")))
+                .lines().collect(joining("\n"));
+
+        assertEquals(expectEvent, event, false);
     }
 
     @Test
-    void shouldLogEventForStreamAndLambdaStreamIsValid() throws IOException {
+    void shouldLogEventForStreamAndLambdaStreamIsValid() throws IOException, JSONException {
         requestStreamHandler = new PowerToolLogEventEnabledForStream();
         ByteArrayOutputStream output = new ByteArrayOutputStream();
+        S3EventNotification s3EventNotification = s3EventNotification();
 
-        Map<String, String> testPayload = new HashMap<>();
-        testPayload.put("test", "payload");
-
-        requestStreamHandler.handleRequest(new ByteArrayInputStream(new ObjectMapper().writeValueAsBytes(testPayload)), output, context);
+        requestStreamHandler.handleRequest(new ByteArrayInputStream(new ObjectMapper().writeValueAsBytes(s3EventNotification)), output, context);
 
         assertThat(new String(output.toByteArray(), StandardCharsets.UTF_8))
-                .isEqualTo("{\"test\":\"payload\"}");
+                .isNotEmpty();
 
-        assertThat(ThreadContext.getImmutableContext())
-                .hasSize(EXPECTED_CONTEXT_SIZE);
+        Map<String, Object> log = parseToMap(Files.lines(Paths.get("target/logfile.json")).collect(joining()));
+
+        String event = (String) log.get("message");
+
+        String expectEvent = new BufferedReader(new InputStreamReader(this.getClass().getResourceAsStream("/s3EventNotification.json")))
+                .lines().collect(joining("\n"));
+
+        assertEquals(expectEvent, event, false);
     }
 
     @Test
@@ -197,4 +233,44 @@ private void setupContext() {
         when(context.getFunctionVersion()).thenReturn("1");
         when(context.getMemoryLimitInMB()).thenReturn(10);
     }
+
+    private void resetLogLevel(Level level) throws NoSuchMethodException, IllegalAccessException, InvocationTargetException {
+        Method resetLogLevels = LambdaLoggingAspect.class.getDeclaredMethod("resetLogLevels", Level.class);
+        resetLogLevels.setAccessible(true);
+        resetLogLevels.invoke(null, level);
+        writeStaticField(LambdaLoggingAspect.class, "LEVEL_AT_INITIALISATION", level, true);
+    }
+
+    private S3EventNotification s3EventNotification() {
+        S3EventNotificationRecord record = new S3EventNotificationRecord("us-west-2",
+                "ObjectCreated:Put",
+                "aws:s3",
+                null,
+                "2.1",
+                new RequestParametersEntity("127.0.0.1"),
+                new ResponseElementsEntity("C3D13FE58DE4C810", "FMyUVURIY8/IgAtTv8xRjskZQpcIZ9KG4V5Wp6S7S/JRWeUWerMUE5JgHvANOjpD"),
+                new S3Entity("testConfigRule",
+                        new S3BucketEntity("mybucket",
+                                new UserIdentityEntity("A3NL1KOZZKExample"),
+                                "arn:aws:s3:::mybucket"),
+                        new S3ObjectEntity("HappyFace.jpg",
+                                1024L,
+                                "d41d8cd98f00b204e9800998ecf8427e",
+                                "096fKKXTRTtl3on89fVO.nfljtsv6qko",
+                                "0055AED6DCD90281E5"),
+                        "1.0"),
+                new UserIdentityEntity("AIDAJDPLRKLG7UEXAMPLE")
+        );
+
+        return new S3EventNotification(singletonList(record));
+    }
+
+    private Map<String, Object> parseToMap(String stringAsJson) {
+        try {
+            return new ObjectMapper().readValue(stringAsJson, Map.class);
+        } catch (JsonProcessingException e) {
+            fail("Failed parsing logger line " + stringAsJson);
+            return emptyMap();
+        }
+    }
 }

powertools-logging/src/test/resources/s3EventNotification.json

@@ -0,0 +1,38 @@
+{
+  "records":[
+    {
+      "eventVersion":"2.1",
+      "eventSource":"aws:s3",
+      "awsRegion":"us-west-2",
+      "eventName":"ObjectCreated:Put",
+      "userIdentity":{
+        "principalId":"AIDAJDPLRKLG7UEXAMPLE"
+      },
+      "requestParameters":{
+        "sourceIPAddress":"127.0.0.1"
+      },
+      "responseElements":{
+        "xAmzId2":"C3D13FE58DE4C810",
+        "xAmzRequestId":"FMyUVURIY8/IgAtTv8xRjskZQpcIZ9KG4V5Wp6S7S/JRWeUWerMUE5JgHvANOjpD"
+      },
+      "s3":{
+        "s3SchemaVersion":"1.0",
+        "configurationId":"testConfigRule",
+        "bucket":{
+          "name":"mybucket",
+          "ownerIdentity":{
+            "principalId":"A3NL1KOZZKExample"
+          },
+          "arn":"arn:aws:s3:::mybucket"
+        },
+        "object":{
+          "key":"HappyFace.jpg",
+          "size":1024,
+          "eTag":"d41d8cd98f00b204e9800998ecf8427e",
+          "versionId":"096fKKXTRTtl3on89fVO.nfljtsv6qko",
+          "sequencer":"0055AED6DCD90281E5"
+        }
+      }
+    }
+  ]
+}