diff --git a/pom.xml b/pom.xml index a7009e3e0..623a81e38 100644 --- a/pom.xml +++ b/pom.xml @@ -190,6 +190,12 @@ 3.17.2 test + + org.skyscreamer + jsonassert + 1.5.0 + test + org.aspectj aspectjtools diff --git a/powertools-logging/pom.xml b/powertools-logging/pom.xml index 038f6a31d..f2b210636 100644 --- a/powertools-logging/pom.xml +++ b/powertools-logging/pom.xml @@ -103,6 +103,16 @@ assertj-core test + + com.amazonaws + aws-lambda-java-events + test + + + org.skyscreamer + jsonassert + test + \ No newline at end of file diff --git a/powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/internal/LambdaLoggingAspect.java b/powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/internal/LambdaLoggingAspect.java index ec3f64165..8414d5307 100644 --- a/powertools-logging/src/main/java/software/amazon/lambda/powertools/logging/internal/LambdaLoggingAspect.java +++ b/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,6 +186,16 @@ private Object[] logFromInputStream(final ProceedingJoinPoint pjp) { return args; } + private Optional 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()); } @@ -188,7 +203,7 @@ private Logger logger(final ProceedingJoinPoint pjp) { private static Optional 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(); } diff --git a/powertools-logging/src/test/java/org/apache/logging/log4j/core/layout/LambdaJsonLayoutTest.java b/powertools-logging/src/test/java/org/apache/logging/log4j/core/layout/LambdaJsonLayoutTest.java index 4db93fd34..5fc0398d1 100644 --- a/powertools-logging/src/test/java/org/apache/logging/log4j/core/layout/LambdaJsonLayoutTest.java +++ b/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(); diff --git a/powertools-logging/src/test/java/software/amazon/lambda/powertools/logging/handlers/PowerLogToolEnabled.java b/powertools-logging/src/test/java/software/amazon/lambda/powertools/logging/handlers/PowerLogToolEnabled.java index 5678c0e95..097d26756 100644 --- a/powertools-logging/src/test/java/software/amazon/lambda/powertools/logging/handlers/PowerLogToolEnabled.java +++ b/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 { - private final Logger LOG = LogManager.getLogger(PowerToolLogEventEnabled.class); + private final Logger LOG = LogManager.getLogger(PowerLogToolEnabled.class); @Override @PowertoolsLogging diff --git a/powertools-logging/src/test/java/software/amazon/lambda/powertools/logging/internal/LambdaLoggingAspectTest.java b/powertools-logging/src/test/java/software/amazon/lambda/powertools/logging/internal/LambdaLoggingAspectTest.java index 91e76a154..71f1dcec9 100644 --- a/powertools-logging/src/test/java/software/amazon/lambda/powertools/logging/internal/LambdaLoggingAspectTest.java +++ b/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 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 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 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 parseToMap(String stringAsJson) { + try { + return new ObjectMapper().readValue(stringAsJson, Map.class); + } catch (JsonProcessingException e) { + fail("Failed parsing logger line " + stringAsJson); + return emptyMap(); + } + } } \ No newline at end of file diff --git a/powertools-logging/src/test/resources/s3EventNotification.json b/powertools-logging/src/test/resources/s3EventNotification.json new file mode 100644 index 000000000..feb88ec02 --- /dev/null +++ b/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" + } + } + } + ] +} \ No newline at end of file