fix: LoggingAspect precedence to be last for accepting mutated args

.github/workflows/build.yml

@@ -12,6 +12,7 @@ on:
       - 'powertools-validation/**'
       - 'powertools-parameters/**'
       - 'powertools-metrics/**'
+      - 'powertools-test-suite/**'
       - 'pom.xml'
       - '.github/workflows/**'
   push:
@@ -25,6 +26,7 @@ on:
       - 'powertools-validation/**'
       - 'powertools-parameters/**'
       - 'powertools-metrics/**'
+      - 'powertools-test-suite/**'
       - 'pom.xml'
       - '.github/workflows/**'
 jobs:

.github/workflows/spotbugs.yml

@@ -12,6 +12,7 @@ on:
       - 'powertools-validation/**'
       - 'powertools-parameters/**'
       - 'powertools-metrics/**'
+      - 'powertools-test-suite/**'
       - 'pom.xml'
       - '.github/workflows/**'
 jobs:

pom.xml

@@ -34,6 +34,7 @@
         <module>powertools-metrics</module>
         <module>powertools-parameters</module>
         <module>powertools-validation</module>
+        <module>powertools-test-suite</module>
     </modules>
 
     <scm>
@@ -88,6 +89,21 @@
                 <artifactId>powertools-core</artifactId>
                 <version>${project.version}</version>
             </dependency>
+            <dependency>
+                <groupId>software.amazon.lambda</groupId>
+                <artifactId>powertools-logging</artifactId>
+                <version>${project.version}</version>
+            </dependency>
+            <dependency>
+                <groupId>software.amazon.lambda</groupId>
+                <artifactId>powertools-sqs</artifactId>
+                <version>${project.version}</version>
+            </dependency>
+            <dependency>
+                <groupId>software.amazon.lambda</groupId>
+                <artifactId>powertools-tracing</artifactId>
+                <version>${project.version}</version>
+            </dependency>
             <dependency>
                 <groupId>com.amazonaws</groupId>
                 <artifactId>aws-lambda-java-core</artifactId>

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

@@ -37,6 +37,7 @@
 import org.aspectj.lang.ProceedingJoinPoint;
 import org.aspectj.lang.annotation.Around;
 import org.aspectj.lang.annotation.Aspect;
+import org.aspectj.lang.annotation.DeclarePrecedence;
 import org.aspectj.lang.annotation.Pointcut;
 import software.amazon.lambda.powertools.logging.Logging;
 import software.amazon.lambda.powertools.logging.LoggingUtils;
@@ -57,6 +58,7 @@
 import static software.amazon.lambda.powertools.logging.LoggingUtils.objectMapper;
 
 @Aspect
+@DeclarePrecedence("*, SqsLargeMessageAspect, LambdaLoggingAspect")
 public final class LambdaLoggingAspect {
     private static final Logger LOG = LogManager.getLogger(LambdaLoggingAspect.class);
     private static final Random SAMPLER = new Random();

powertools-test-suite/pom.xml

@@ -0,0 +1,151 @@
+<?xml version="1.0" encoding="UTF-8"?>
+<project xmlns="http://maven.apache.org/POM/4.0.0"
+         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
+         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
+    <modelVersion>4.0.0</modelVersion>
+
+    <artifactId>powertools-test-suite</artifactId>
+    <packaging>jar</packaging>
+
+    <parent>
+        <artifactId>powertools-parent</artifactId>
+        <groupId>software.amazon.lambda</groupId>
+        <version>1.7.3</version>
+    </parent>
+
+    <name>AWS Lambda Powertools Java library Test Suite</name>
+    <description>
+        A suite of tests for interactions between the various Powertools modules.
+    </description>
+    <url>https://aws.amazon.com/lambda/</url>
+    <issueManagement>
+        <system>GitHub Issues</system>
+        <url>https://github.com/awslabs/aws-lambda-powertools-java/issues</url>
+    </issueManagement>
+    <scm>
+        <url>https://github.com/awslabs/aws-lambda-powertools-java.git</url>
+    </scm>
+    <developers>
+        <developer>
+            <name>AWS Lambda Powertools team</name>
+            <organization>Amazon Web Services</organization>
+            <organizationUrl>https://aws.amazon.com/</organizationUrl>
+        </developer>
+    </developers>
+
+    <properties>
+        <maven.deploy.skip>true</maven.deploy.skip>
+    </properties>
+
+    <distributionManagement>
+        <snapshotRepository>
+            <id>ossrh</id>
+            <url>https://aws.oss.sonatype.org/content/repositories/snapshots</url>
+        </snapshotRepository>
+    </distributionManagement>
+
+    <dependencies>
+        <dependency>
+            <groupId>software.amazon.lambda</groupId>
+            <artifactId>powertools-core</artifactId>
+        </dependency>
+        <dependency>
+            <groupId>org.apache.logging.log4j</groupId>
+            <artifactId>log4j-jcl</artifactId>
+            <version>2.14.1</version>
+        </dependency>
+        <dependency>
+            <groupId>com.amazonaws</groupId>
+            <artifactId>aws-lambda-java-core</artifactId>
+        </dependency>
+        <dependency>
+            <groupId>com.amazonaws</groupId>
+            <artifactId>aws-lambda-java-events</artifactId>
+        </dependency>
+        <dependency>
+            <groupId>software.amazon.lambda</groupId>
+            <artifactId>powertools-logging</artifactId>
+        </dependency>
+        <dependency>
+            <groupId>software.amazon.lambda</groupId>
+            <artifactId>powertools-tracing</artifactId>
+        </dependency>
+        <dependency>
+            <groupId>software.amazon.lambda</groupId>
+            <artifactId>powertools-sqs</artifactId>
+        </dependency>
+
+        <!-- Test dependencies -->
+        <dependency>
+            <groupId>org.junit.jupiter</groupId>
+            <artifactId>junit-jupiter-api</artifactId>
+            <scope>test</scope>
+        </dependency>
+        <dependency>
+            <groupId>org.junit.jupiter</groupId>
+            <artifactId>junit-jupiter-engine</artifactId>
+            <scope>test</scope>
+        </dependency>
+        <dependency>
+            <groupId>org.apache.commons</groupId>
+            <artifactId>commons-lang3</artifactId>
+            <scope>test</scope>
+        </dependency>
+        <dependency>
+            <groupId>org.mockito</groupId>
+            <artifactId>mockito-core</artifactId>
+            <scope>test</scope>
+        </dependency>
+        <dependency>
+            <groupId>org.aspectj</groupId>
+            <artifactId>aspectjweaver</artifactId>
+            <scope>test</scope>
+        </dependency>
+        <dependency>
+            <groupId>org.assertj</groupId>
+            <artifactId>assertj-core</artifactId>
+            <scope>test</scope>
+        </dependency>
+        <dependency>
+            <groupId>org.skyscreamer</groupId>
+            <artifactId>jsonassert</artifactId>
+            <scope>test</scope>
+        </dependency>
+    </dependencies>
+
+    <build>
+        <plugins>
+            <plugin>
+                <groupId>org.codehaus.mojo</groupId>
+                <artifactId>aspectj-maven-plugin</artifactId>
+                <version>1.14.0</version>
+                <configuration>
+                    <source>${maven.compiler.source}</source>
+                    <target>${maven.compiler.target}</target>
+                    <complianceLevel>${maven.compiler.target}</complianceLevel>
+                    <aspectLibraries>
+                        <aspectLibrary>
+                            <groupId>software.amazon.lambda</groupId>
+                            <artifactId>powertools-logging</artifactId>
+                        </aspectLibrary>
+                        <aspectLibrary>
+                            <groupId>software.amazon.lambda</groupId>
+                            <artifactId>powertools-tracing</artifactId>
+                        </aspectLibrary>
+                        <aspectLibrary>
+                            <groupId>software.amazon.lambda</groupId>
+                            <artifactId>powertools-sqs</artifactId>
+                        </aspectLibrary>
+                    </aspectLibraries>
+                </configuration>
+                <executions>
+                    <execution>
+                        <goals>
+                            <goal>compile</goal>
+                        </goals>
+                    </execution>
+                </executions>
+            </plugin>
+        </plugins>
+    </build>
+</project>

powertools-test-suite/src/test/java/software/amazon/lambda/powertools/testsuite/LoggingOrderTest.java

@@ -0,0 +1,168 @@
+package software.amazon.lambda.powertools.testsuite;
+
+
+import java.io.ByteArrayInputStream;
+import java.io.ByteArrayOutputStream;
+import java.io.IOException;
+import java.lang.reflect.InvocationTargetException;
+import java.lang.reflect.Method;
+import java.nio.channels.FileChannel;
+import java.nio.charset.StandardCharsets;
+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.events.SQSEvent;
+import com.amazonaws.services.lambda.runtime.events.models.s3.S3EventNotification;
+import com.amazonaws.services.s3.AmazonS3;
+import com.amazonaws.services.s3.model.S3Object;
+import com.amazonaws.xray.AWSXRay;
+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.junit.jupiter.api.AfterEach;
+import org.junit.jupiter.api.BeforeEach;
+import org.junit.jupiter.api.Test;
+import org.mockito.Mock;
+import software.amazon.lambda.powertools.core.internal.LambdaHandlerProcessor;
+import software.amazon.lambda.powertools.logging.internal.LambdaLoggingAspect;
+import software.amazon.lambda.powertools.sqs.internal.SqsLargeMessageAspect;
+import software.amazon.lambda.powertools.testsuite.handler.LoggingOrderMessageHandler;
+import software.amazon.lambda.powertools.testsuite.handler.TracingLoggingStreamMessageHandler;
+
+import static java.util.Collections.emptyMap;
+import static java.util.Collections.singletonList;
+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;
+import static org.mockito.MockitoAnnotations.openMocks;
+
+public class LoggingOrderTest {
+
+    private static final String BUCKET_NAME = "ms-extended-sqs-client";
+    private static final String BUCKET_KEY = "c71eb2ae-37e0-4265-8909-32f4153faddf";
+
+    @Mock
+    private Context context;
+
+    @Mock
+    private AmazonS3 amazonS3;
+
+    @BeforeEach
+    void setUp() throws IllegalAccessException, IOException, NoSuchMethodException, InvocationTargetException {
+        openMocks(this);
+        writeStaticField(SqsLargeMessageAspect.class, "amazonS3", amazonS3, true);
+        ThreadContext.clearAll();
+        writeStaticField(LambdaHandlerProcessor.class, "IS_COLD_START", null, true);
+        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();
+        resetLogLevel(Level.INFO);
+        AWSXRay.beginSegment(LoggingOrderTest.class.getName());
+    }
+
+    @AfterEach
+    void tearDown() {
+        AWSXRay.endSegment();
+    }
+
+    /**
+     * The SQSEvent payload will be altered by the @SqsLargeMessage annotation. Logging of the event should happen
+     * after the event has been altered
+     */
+    @Test
+    public void testThatLoggingAnnotationActsLast()  throws IOException {
+        S3Object s3Response = new S3Object();
+        s3Response.setObjectContent(new ByteArrayInputStream("A big message".getBytes()));
+
+        when(amazonS3.getObject(BUCKET_NAME, BUCKET_KEY)).thenReturn(s3Response);
+        SQSEvent sqsEvent = messageWithBody("[\"software.amazon.payloadoffloading.PayloadS3Pointer\",{\"s3BucketName\":\"" + BUCKET_NAME + "\",\"s3Key\":\"" + BUCKET_KEY + "\"}]");
+
+        LoggingOrderMessageHandler requestHandler = new LoggingOrderMessageHandler();
+        requestHandler.handleRequest(sqsEvent, context);
+
+        assertThat(Files.lines(Paths.get("target/logfile.json")))
+                .hasSize(2)
+                .satisfies(line -> {
+                    Map<String, Object> actual = parseToMap(line.get(0));
+
+                    String message = actual.get("message").toString();
+
+                    assertThat(message)
+                            .contains("A big message");
+                });
+    }
+
+    @Test
+    public void testLoggingAnnotationActsAfterTracingForStreamingHandler() throws IOException {
+
+        ByteArrayOutputStream output = new ByteArrayOutputStream();
+        S3EventNotification s3EventNotification = s3EventNotification();
+
+        TracingLoggingStreamMessageHandler handler = new TracingLoggingStreamMessageHandler();
+        handler.handleRequest(new ByteArrayInputStream(new ObjectMapper().writeValueAsBytes(s3EventNotification)), output, context);
+
+        assertThat(new String(output.toByteArray(), StandardCharsets.UTF_8))
+                .isNotEmpty();
+    }
+
+    private void setupContext() {
+        when(context.getFunctionName()).thenReturn("testFunction");
+        when(context.getInvokedFunctionArn()).thenReturn("testArn");
+        when(context.getFunctionVersion()).thenReturn("1");
+        when(context.getMemoryLimitInMB()).thenReturn(10);
+        when(context.getAwsRequestId()).thenReturn("RequestId");
+    }
+
+    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 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();
+        }
+    }
+
+    private S3EventNotification s3EventNotification() {
+        S3EventNotification.S3EventNotificationRecord record = new S3EventNotification.S3EventNotificationRecord("us-west-2",
+                "ObjectCreated:Put",
+                "aws:s3",
+                null,
+                "2.1",
+                new S3EventNotification.RequestParametersEntity("127.0.0.1"),
+                new S3EventNotification.ResponseElementsEntity("C3D13FE58DE4C810", "FMyUVURIY8/IgAtTv8xRjskZQpcIZ9KG4V5Wp6S7S/JRWeUWerMUE5JgHvANOjpD"),
+                new S3EventNotification.S3Entity("testConfigRule",
+                        new S3EventNotification.S3BucketEntity("mybucket",
+                                new S3EventNotification.UserIdentityEntity("A3NL1KOZZKExample"),
+                                "arn:aws:s3:::mybucket"),
+                        new S3EventNotification.S3ObjectEntity("HappyFace.jpg",
+                                1024L,
+                                "d41d8cd98f00b204e9800998ecf8427e",
+                                "096fKKXTRTtl3on89fVO.nfljtsv6qko",
+                                "0055AED6DCD90281E5"),
+                        "1.0"),
+                new S3EventNotification.UserIdentityEntity("AIDAJDPLRKLG7UEXAMPLE")
+        );
+
+        return new S3EventNotification(singletonList(record));
+    }
+
+    private SQSEvent messageWithBody(String messageBody) {
+        SQSEvent.SQSMessage sqsMessage = new SQSEvent.SQSMessage();
+        sqsMessage.setBody(messageBody);
+        SQSEvent sqsEvent = new SQSEvent();
+        sqsEvent.setRecords(singletonList(sqsMessage));
+        return sqsEvent;
+    }
+}