Added debug log around entire request and prevent random log leaking into transfer manager logging test

Author: L-Applin

services-custom/s3-transfer-manager/src/test/java/software/amazon/awssdk/transfer/s3/internal/TransferManagerLoggingTest.java

@@ -18,6 +18,7 @@
 import static org.assertj.core.api.Assertions.assertThat;
 
 import java.util.List;
+import java.util.function.Predicate;
 import org.apache.logging.log4j.Level;
 import org.apache.logging.log4j.core.LogEvent;
 import org.junit.jupiter.api.Test;
@@ -48,14 +49,15 @@ void transferManager_withCrtClient_shouldNotLogWarnMessages() {
              LogCaptor logCaptor = LogCaptor.create(Level.WARN);
              S3TransferManager tm = S3TransferManager.builder().s3Client(s3Crt).build()) {
             List<LogEvent> events = logCaptor.loggedEvents();
-            assertThat(events).isEmpty();
+            assertThat(events)
+                .withFailMessage("A message from S3TransferManager was logged at DEBUG level when none was expected")
+                .noneMatch(loggedFromS3TransferManager());
         }
     }
 
     @Test
     void transferManager_withJavaClientMultiPartNotSet_shouldLogDebugMessage() {
 
-
         try (S3AsyncClient s3Crt = S3AsyncClient.builder()
                                                 .region(Region.US_WEST_2)
                                                 .credentialsProvider(() -> AwsBasicCredentials.create("foo", "bar"))
@@ -70,7 +72,6 @@ void transferManager_withJavaClientMultiPartNotSet_shouldLogDebugMessage() {
     @Test
     void transferManager_withJavaClientMultiPartEqualsFalse_shouldLogDebugMessage() {
 
-
         try (S3AsyncClient s3Crt = S3AsyncClient.builder()
                                                 .region(Region.US_WEST_2)
                                                 .credentialsProvider(() -> AwsBasicCredentials.create("foo", "bar"))
@@ -90,7 +91,9 @@ void transferManager_withDefaultClient_shouldNotLogDebugMessage() {
         try (LogCaptor logCaptor = LogCaptor.create(Level.DEBUG);
              S3TransferManager tm = S3TransferManager.builder().build()) {
             List<LogEvent> events = logCaptor.loggedEvents();
-            assertThat(events).isEmpty();
+            assertThat(events)
+                .withFailMessage("A message from S3TransferManager was logged at DEBUG level when none was expected")
+                .noneMatch(loggedFromS3TransferManager());
         }
         SystemSettingUtilsTestBackdoor.clearEnvironmentVariableOverrides();
     }
@@ -106,7 +109,9 @@ void transferManager_withMultiPartEnabledJavaClient_shouldNotLogDebugMessage() {
              LogCaptor logCaptor = LogCaptor.create(Level.DEBUG);
              S3TransferManager tm = S3TransferManager.builder().s3Client(s3Crt).build()) {
             List<LogEvent> events = logCaptor.loggedEvents();
-            assertThat(events).isEmpty();
+            assertThat(events)
+                .withFailMessage("A message from S3TransferManager was logged at DEBUG level when none was expected")
+                .noneMatch(loggedFromS3TransferManager());
         }
     }
 
@@ -122,7 +127,9 @@ void transferManager_withMultiPartEnabledAndCrossRegionEnabledJavaClient_shouldN
              LogCaptor logCaptor = LogCaptor.create(Level.DEBUG);
              S3TransferManager tm = S3TransferManager.builder().s3Client(s3Crt).build()) {
             List<LogEvent> events = logCaptor.loggedEvents();
-            assertThat(events).isEmpty();
+            assertThat(events)
+                .withFailMessage("A message from S3TransferManager was logged at DEBUG level when none was expected")
+                .noneMatch(loggedFromS3TransferManager());
         }
     }
 
@@ -133,4 +140,9 @@ private static void assertLogged(List<LogEvent> events, org.apache.logging.log4j
         assertThat(msg).isEqualTo(message);
         assertThat(event.getLevel()).isEqualTo(level);
     }
+
+    private static Predicate<LogEvent> loggedFromS3TransferManager() {
+        String tmLoggerName = "software.amazon.awssdk.transfer.s3.S3TransferManager";
+        return logEvent -> tmLoggerName.equals(logEvent.getLoggerName());
+    }
 }

services/s3/src/main/java/software/amazon/awssdk/services/s3/internal/multipart/MultipartDownloaderSubscriber.java

@@ -88,6 +88,7 @@ public MultipartDownloaderSubscriber(S3AsyncClient s3, GetObjectRequest getObjec
 
     @Override
     public void onSubscribe(Subscription s) {
+        log.trace(() -> "onSubscribe");
         if (this.subscription != null) {
             s.cancel();
             return;
@@ -98,7 +99,7 @@ public void onSubscribe(Subscription s) {
 
     @Override
     public void onNext(AsyncResponseTransformer<GetObjectResponse, GetObjectResponse> asyncResponseTransformer) {
-        log.trace(() -> "onNext " + completedParts.get());
+        log.trace(() -> String.format("onNext, completed part = %d", completedParts.get()));
         if (asyncResponseTransformer == null) {
             throw new NullPointerException("onNext must not be called with null asyncResponseTransformer");
         }
@@ -107,21 +108,28 @@ public void onNext(AsyncResponseTransformer<GetObjectResponse, GetObjectResponse
 
         if (totalParts != null && nextPartToGet > totalParts) {
             synchronized (lock) {
+                logMulitpartComplete(totalParts);
                 subscription.cancel();
             }
         }
 
         GetObjectRequest actualRequest = nextRequest(nextPartToGet);
+        log.debug(() -> "Sending GetObjectRequest for next part with partNumber=" + nextPartToGet);
         CompletableFuture<GetObjectResponse> getObjectFuture = s3.getObject(actualRequest, asyncResponseTransformer);
         getObjectFuture.whenComplete((response, error) -> {
             if (error != null) {
+                log.debug(() -> "Error encountered during GetObjectRequest with partNumber=" + nextPartToGet);
                 onError(error);
                 return;
             }
             requestMoreIfNeeded(response);
         });
     }
 
+    private void logMulitpartComplete(int totalParts) {
+        log.debug(() -> String.format("Completing multipart download after a total of %d parts downloaded.", totalParts));
+    }
+
     private void requestMoreIfNeeded(GetObjectResponse response) {
         int totalComplete = completedParts.incrementAndGet();
         MultipartDownloadUtils.multipartDownloadResumeContext(getObjectRequest)
@@ -132,16 +140,16 @@ private void requestMoreIfNeeded(GetObjectResponse response) {
                                       ctx.response(response);
                                   }
                               });
-        log.trace(() -> String.format("completed part: %d", totalComplete));
+        log.debug(() -> String.format("Completed part %d", totalComplete));
 
         if (eTag == null) {
             this.eTag = response.eTag();
-            log.trace(() -> String.format("Multipart object ETag: %s", this.eTag));
+            log.debug(() -> String.format("Multipart object ETag: %s", this.eTag));
         }
 
         Integer partCount = response.partsCount();
         if (partCount != null && totalParts == null) {
-            log.trace(() -> String.format("total parts: %d", partCount));
+            log.debug(() -> String.format("Total amount of parts of the object to download: %d", partCount));
             MultipartDownloadUtils.multipartDownloadResumeContext(getObjectRequest)
                 .ifPresent(ctx -> ctx.totalParts(partCount));
             totalParts = partCount;
@@ -150,6 +158,7 @@ private void requestMoreIfNeeded(GetObjectResponse response) {
             if (totalParts != null && totalParts > 1 && totalComplete < totalParts) {
                 subscription.request(1);
             } else {
+                logMulitpartComplete(totalParts);
                 subscription.cancel();
             }
         }