Log async upload job details correlated with operation id

multiapps-controller-persistence/src/main/java/module-info.java

@@ -9,6 +9,7 @@
     exports org.cloudfoundry.multiapps.controller.persistence.model;
     exports org.cloudfoundry.multiapps.controller.persistence.model.adapter;
     exports org.cloudfoundry.multiapps.controller.persistence.model.filters;
+    exports org.cloudfoundry.multiapps.controller.persistence.monitoring;
     exports org.cloudfoundry.multiapps.controller.persistence.query;
     exports org.cloudfoundry.multiapps.controller.persistence.query.criteria;
     exports org.cloudfoundry.multiapps.controller.persistence.query.impl;
@@ -73,4 +74,5 @@
     requires software.amazon.awssdk.retries.api;
     requires static java.compiler;
     requires static org.immutables.value;
+    requires io.netty.handler;
 }

multiapps-controller-persistence/src/main/java/org/cloudfoundry/multiapps/controller/persistence/Messages.java

@@ -67,6 +67,10 @@ public final class Messages {
 
     // INFO log messages:
     public static final String DELETING_FILES_WITHOUT_CONTENT_WITH_IDS_0 = "Deleting files without content with ids: {0}";
+    public static final String TIME_ELAPSED_FOR_JCLOUDS_OS_UPLOAD_0_IN_MILLIS = "Time elapsed for JClouds object store upload: {0} in millis";
+    public static final String TIME_ELAPSED_FOR_GCP_OS_UPLOAD_0_IN_MILLIS = "Time elapsed for GCP object store upload: {0} in millis";
+    public static final String TIME_ELAPSED_FOR_AZURE_OS_UPLOAD_0_IN_MILLIS = "Time elapsed for Azure object store upload: {0} in millis";
+    public static final String TIME_ELAPSED_FOR_AWS_OS_UPLOAD_0_IN_MILLIS = "Time elapsed for AWS object store upload: {0} in millis";
 
     // DEBUG log messages:
     public static final String STORED_FILE_0 = "Stored file: \"{0}\"";

multiapps-controller-persistence/src/main/java/org/cloudfoundry/multiapps/controller/persistence/model/AsyncUploadJobEntry.java

@@ -1,6 +1,7 @@
 package org.cloudfoundry.multiapps.controller.persistence.model;
 
 import java.text.MessageFormat;
+import java.time.Duration;
 import java.time.LocalDateTime;
 
 import org.cloudfoundry.multiapps.common.Nullable;
@@ -11,6 +12,10 @@ public interface AsyncUploadJobEntry {
 
     String STALE_JOB_DETAILS_FORMAT = "Stale job details - id: {0}, state: {1}, updatedAt: {2}, addedAt: {3}, startedAt: {4}, bytesRead: {5}, url: {6}, space: {7}, namespace: {8}, user: {9}, instance: {10}";
 
+    String ASYNC_UPLOAD_JOB_SUMMARY_FORMAT = "id: {0}, state: {1}, fileId: {2}, mtaId: {3}, schemaVersion: {4}, instanceIndex: {5}, bytesRead: {6}, addedAt: {7}, startedAt: {8}, finishedAt: {9}, updatedAt: {10}, queueWaitTime: {11}, uploadDuration: {12}, totalTime: {13}, error: {14}";
+
+    String NOT_AVAILABLE = "N/A";
+
     enum State {
         INITIAL, RUNNING, FINISHED, ERROR
     }
@@ -61,4 +66,42 @@ default String buildStaleDetailsLogMessage() {
         return MessageFormat.format(STALE_JOB_DETAILS_FORMAT, getId(), getState(), getUpdatedAt(), getAddedAt(), getStartedAt(),
                                     getBytesRead(), getUrl(), getSpaceGuid(), getNamespace(), getUser(), getInstanceIndex());
     }
+
+    default String buildLogSummary() {
+        return MessageFormat.format(ASYNC_UPLOAD_JOB_SUMMARY_FORMAT, getId(), getState(), getFileId(), getMtaId(), getSchemaVersion(),
+                                    getInstanceIndex(), getBytesRead(), getAddedAt(), getStartedAt(), getFinishedAt(), getUpdatedAt(),
+                                    formatDuration(getQueueWaitTime()), formatDuration(getUploadDuration()), formatDuration(getTotalTime()),
+                                    getError());
+    }
+
+    @Nullable
+    default Duration getQueueWaitTime() {
+        if (getAddedAt() == null || getStartedAt() == null) {
+            return null;
+        }
+        return Duration.between(getAddedAt(), getStartedAt());
+    }
+
+    @Nullable
+    default Duration getUploadDuration() {
+        if (getStartedAt() == null || getFinishedAt() == null) {
+            return null;
+        }
+        return Duration.between(getStartedAt(), getFinishedAt());
+    }
+
+    @Nullable
+    default Duration getTotalTime() {
+        if (getAddedAt() == null || getFinishedAt() == null) {
+            return null;
+        }
+        return Duration.between(getAddedAt(), getFinishedAt());
+    }
+
+    private static String formatDuration(Duration duration) {
+        if (duration == null) {
+            return NOT_AVAILABLE;
+        }
+        return duration.toMillis() + " ms";
+    }
 }

multiapps-controller-persistence/src/main/java/org/cloudfoundry/multiapps/controller/persistence/monitoring/UploadDurationTracker.java

@@ -0,0 +1,99 @@
+package org.cloudfoundry.multiapps.controller.persistence.monitoring;
+
+import jakarta.inject.Named;
+
+import java.util.concurrent.atomic.AtomicLong;
+import java.util.concurrent.atomic.LongAdder;
+
+@Named
+public class UploadDurationTracker {
+
+    private final UploadPathStatistics appBinaryStatistics = new UploadPathStatistics();
+
+    private final UploadPathStatistics objectStoreStatistics = new UploadPathStatistics();
+
+    public void recordAppBinaryUpload(long durationMillis, boolean timedOut) {
+        appBinaryStatistics.record(durationMillis, timedOut);
+    }
+
+    public void recordObjectStoreUpload(long durationMillis, boolean timedOut) {
+        objectStoreStatistics.record(durationMillis, timedOut);
+    }
+
+    public void recordAppBinaryUploadRejection() {
+        appBinaryStatistics.recordRejection();
+    }
+
+    public UploadPathStatistics getAppBinaryStatistics() {
+        return this.appBinaryStatistics;
+    }
+
+    public UploadPathStatistics getObjectStoreStatistics() {
+        return this.objectStoreStatistics;
+    }
+
+    public static final class UploadPathStatistics {
+
+        private final LongAdder total = new LongAdder();
+
+        private final LongAdder timeouts = new LongAdder();
+
+        private final LongAdder sumDuration = new LongAdder();
+
+        private final LongAdder rejections = new LongAdder();
+
+        private final AtomicLong rejectionsInWindow = new AtomicLong(0);
+
+        private final AtomicLong maxDuration = new AtomicLong(0);
+
+        private final AtomicLong timeoutsInWindow = new AtomicLong(0);
+
+        public void record(long durationMillis, boolean timedOut) {
+            long duration = Math.max(0, durationMillis);
+            total.increment();
+
+            if (timedOut) {
+                timeouts.increment();
+                timeoutsInWindow.incrementAndGet();
+            }
+
+            sumDuration.add(duration);
+            maxDuration.accumulateAndGet(duration, Math::max);
+        }
+
+        public void recordRejection() {
+            rejections.increment();
+            rejectionsInWindow.incrementAndGet();
+        }
+
+        public long totalCount() {
+            return total.sum();
+        }
+
+        public long timeoutCount() {
+            return timeouts.sum();
+        }
+
+        public long maxDurationMs() {
+            return maxDuration.getAndSet(0);
+        }
+
+        public long sumDurationMs() {
+            return sumDuration.sum();
+        }
+
+        public long timeoutsInWindow() {
+            return timeoutsInWindow.getAndSet(0);
+        }
+
+        public long rejectionCount() {
+            return rejections.sum();
+        }
+
+        public long rejectionsInWindow() {
+            return rejectionsInWindow.getAndSet(0);
+        }
+
+    }
+
+}

multiapps-controller-persistence/src/main/java/org/cloudfoundry/multiapps/controller/persistence/monitoring/UploadTimeoutMatcher.java

@@ -0,0 +1,31 @@
+package org.cloudfoundry.multiapps.controller.persistence.monitoring;
+
+import com.google.cloud.storage.StorageException;
+import io.netty.handler.timeout.ReadTimeoutException;
+
+import java.net.SocketTimeoutException;
+import java.util.concurrent.TimeoutException;
+
+public class UploadTimeoutMatcher {
+
+    private UploadTimeoutMatcher() {
+
+    }
+
+    public static boolean isUploadTimeoutException(Throwable throwable) {
+        if (throwable == null) {
+            return false;
+        }
+
+        Throwable cause = throwable.getCause();
+        while (cause != null) {
+            if (cause instanceof SocketTimeoutException || cause instanceof TimeoutException || cause instanceof ReadTimeoutException || (
+                cause instanceof StorageException
+                    && ((StorageException) cause).getCode() == 504)) {
+                return true;
+            }
+            cause = cause.getCause();
+        }
+        return false;
+    }
+}

multiapps-controller-persistence/src/main/java/org/cloudfoundry/multiapps/controller/persistence/services/AwsS3ObjectStoreFileStorage.java

@@ -4,6 +4,7 @@
 import java.io.InputStream;
 import java.net.URI;
 import java.text.MessageFormat;
+import java.time.Duration;
 import java.time.LocalDateTime;
 import java.util.ArrayList;
 import java.util.HashSet;
@@ -16,8 +17,11 @@
 import java.util.concurrent.Executors;
 import java.util.function.BiPredicate;
 import java.util.function.Consumer;
+
 import org.cloudfoundry.multiapps.controller.persistence.Messages;
 import org.cloudfoundry.multiapps.controller.persistence.model.FileEntry;
+import org.cloudfoundry.multiapps.controller.persistence.monitoring.UploadDurationTracker;
+import org.cloudfoundry.multiapps.controller.persistence.monitoring.UploadTimeoutMatcher;
 import org.cloudfoundry.multiapps.controller.persistence.util.ObjectStoreConstants;
 import org.cloudfoundry.multiapps.controller.persistence.util.ObjectStoreFilter;
 import org.cloudfoundry.multiapps.controller.persistence.util.ObjectStoreMapper;
@@ -57,10 +61,12 @@ public class AwsS3ObjectStoreFileStorage extends ObjectStoreFileStorage {
 
     private final S3Client s3Client;
     private final String bucketName;
+    private final UploadDurationTracker uploadDurationTracker;
 
-    public AwsS3ObjectStoreFileStorage(Map<String, Object> credentials) {
+    public AwsS3ObjectStoreFileStorage(Map<String, Object> credentials, UploadDurationTracker uploadDurationTracker) {
         this.bucketName = (String) credentials.get(CredentialKeys.BUCKET);
         this.s3Client = createS3Client(credentials);
+        this.uploadDurationTracker = uploadDurationTracker;
     }
 
     protected S3Client createS3Client(Map<String, Object> credentials) {
@@ -103,6 +109,7 @@ protected ClientOverrideConfiguration buildClientOverrideConfig() {
 
     @Override
     public void addFile(FileEntry fileEntry, InputStream content) throws FileStorageException {
+        LocalDateTime startTime = LocalDateTime.now();
         long fileSize = fileEntry.getSize()
                                  .longValue();
         PutObjectRequest request = PutObjectRequest.builder()
@@ -115,8 +122,12 @@ public void addFile(FileEntry fileEntry, InputStream content) throws FileStorage
         try {
             s3Client.putObject(request, RequestBody.fromInputStream(new BufferedInputStream(content), fileSize));
             LOGGER.debug(MessageFormat.format(Messages.STORED_FILE_0_WITH_SIZE_1, fileEntry.getId(), fileSize));
+            uploadDurationTracker.recordObjectStoreUpload(getElapsedTimeInMillis(startTime), false);
+            LOGGER.info(MessageFormat.format(Messages.TIME_ELAPSED_FOR_AWS_OS_UPLOAD_0_IN_MILLIS, getElapsedTimeInMillis(startTime)));
         } catch (Exception e) {
             LOGGER.error(MessageFormat.format(Messages.S3_UPLOAD_FAILED_FILE_0_SIZE_1, fileEntry.getName(), fileSize, e));
+            uploadDurationTracker.recordObjectStoreUpload(getElapsedTimeInMillis(startTime),
+                                                          UploadTimeoutMatcher.isUploadTimeoutException(e));
             throw new FileStorageException(MessageFormat.format(Messages.UPLOAD_OF_FILE_WITH_NAMESPACE_FAILED, fileEntry.getName(),
                                                                 fileEntry.getNamespace()), e);
         }
@@ -183,14 +194,15 @@ public void deleteFilesBySpaceIds(List<String> spaceIds) {
 
     @Override
     public void deleteFilesBySpaceAndNamespace(String space, String namespace) {
-        int deletedFiles = deleteByFilterAndCount((key, metadata) -> ObjectStoreFilter.filterBySpaceAndNamespace(metadata, space, namespace));
+        int deletedFiles = deleteByFilterAndCount(
+            (key, metadata) -> ObjectStoreFilter.filterBySpaceAndNamespace(metadata, space, namespace));
         LOGGER.debug(MessageFormat.format(Messages.DELETED_0_FILES_WITH_SPACE_1_AND_NAMESPACE_2, deletedFiles, space, namespace));
     }
 
     @Override
     public int deleteFilesModifiedBefore(LocalDateTime modificationTime) {
         int deletedFiles = deleteByFilterAndCount((key, metadata) -> ObjectStoreFilter.filterByModificationTime(metadata, key,
-                                                                                                               modificationTime));
+                                                                                                                modificationTime));
         LOGGER.debug(MessageFormat.format(Messages.DELETED_0_FILES_MODIFIED_BEFORE_1, deletedFiles, modificationTime));
         return deletedFiles;
     }
@@ -319,6 +331,11 @@ public void destroy() {
         s3Client.close();
     }
 
+    private long getElapsedTimeInMillis(LocalDateTime startTime) {
+        return Duration.between(startTime, LocalDateTime.now())
+                       .toMillis();
+    }
+
     private static final class CredentialKeys {
         static final String ACCESS_KEY_ID = "access_key_id";
         static final String SECRET_ACCESS_KEY = "secret_access_key";

multiapps-controller-persistence/src/main/java/org/cloudfoundry/multiapps/controller/persistence/services/AzureObjectStoreFileStorage.java

@@ -5,6 +5,7 @@
 import java.net.MalformedURLException;
 import java.net.URL;
 import java.text.MessageFormat;
+import java.time.Duration;
 import java.time.LocalDateTime;
 import java.util.List;
 import java.util.Map;
@@ -29,6 +30,8 @@
 import com.azure.storage.blob.options.BlobParallelUploadOptions;
 import org.cloudfoundry.multiapps.controller.persistence.Messages;
 import org.cloudfoundry.multiapps.controller.persistence.model.FileEntry;
+import org.cloudfoundry.multiapps.controller.persistence.monitoring.UploadDurationTracker;
+import org.cloudfoundry.multiapps.controller.persistence.monitoring.UploadTimeoutMatcher;
 import org.cloudfoundry.multiapps.controller.persistence.util.ObjectStoreConstants;
 import org.cloudfoundry.multiapps.controller.persistence.util.ObjectStoreFilter;
 import org.cloudfoundry.multiapps.controller.persistence.util.ObjectStoreMapper;
@@ -46,15 +49,18 @@ public class AzureObjectStoreFileStorage extends ObjectStoreFileStorage {
     private static final int MAX_CONCURRENCY = 5;
     private final HttpClient httpClient;
     private final BlobContainerClient containerClient;
+    private final UploadDurationTracker uploadDurationTracker;
 
-    public AzureObjectStoreFileStorage(Map<String, Object> credentials) {
+    public AzureObjectStoreFileStorage(Map<String, Object> credentials, UploadDurationTracker uploadDurationTracker) {
         this.httpClient = new JdkHttpClientBuilder().build();
         this.containerClient = createContainerClient(credentials);
+        this.uploadDurationTracker = uploadDurationTracker;
     }
 
     @Override
     public void addFile(FileEntry fileEntry, InputStream content) throws FileStorageException {
         BlobClient blobClient = containerClient.getBlobClient(fileEntry.getId());
+        LocalDateTime startTime = LocalDateTime.now();
         try {
             ParallelTransferOptions pto = new ParallelTransferOptions().setMaxSingleUploadSizeLong(MAX_SINGLE_UPLOAD_SIZE)
                                                                        .setMaxConcurrency(MAX_CONCURRENCY)
@@ -67,10 +73,14 @@ public void addFile(FileEntry fileEntry, InputStream content) throws FileStorage
             blobClient.uploadWithResponse(blobParallelUploadOptions,
                                           ObjectStoreConstants.AZURE_OBJECT_STORE_TOTAL_TIMEOUT_CONFIG_IN_MINUTES, null);
             LOGGER.debug(MessageFormat.format(Messages.STORED_FILE_0_WITH_SIZE_1, fileEntry.getId(), fileEntry.getSize()
-                                                                                                             .longValue()));
+                                                                                                              .longValue()));
         } catch (BlobStorageException e) {
+            uploadDurationTracker.recordObjectStoreUpload(getElapsedTimeInMillis(startTime),
+                                                          UploadTimeoutMatcher.isUploadTimeoutException(e));
             throw new FileStorageException(e);
         }
+        uploadDurationTracker.recordObjectStoreUpload(getElapsedTimeInMillis(startTime), false);
+        LOGGER.info(MessageFormat.format(Messages.TIME_ELAPSED_FOR_AZURE_OS_UPLOAD_0_IN_MILLIS, getElapsedTimeInMillis(startTime)));
     }
 
     @Override
@@ -218,6 +228,11 @@ private int removeBlobsByFilter(Predicate<? super BlobItem> filter) {
         return deletedBlobsResult;
     }
 
+    private long getElapsedTimeInMillis(LocalDateTime startTime) {
+        return Duration.between(startTime, LocalDateTime.now())
+                       .toMillis();
+    }
+
     protected Set<String> getEntryNames(Predicate<? super BlobItem> filter) {
         BlobListDetails blobListDetails = new BlobListDetails().setRetrieveMetadata(true);
         ListBlobsOptions listBlobsOptions = new ListBlobsOptions().setDetails(blobListDetails);