From d37e0b92503e9113902bc0d13b4912f46290d9f0 Mon Sep 17 00:00:00 2001 From: IvanBorislavovDimitrov Date: Mon, 3 Aug 2026 15:48:44 +0300 Subject: [PATCH] Log async upload job details correlated with operation id At operation start, resolve the operation's file ids and log any associated async upload job (deploy-from-URL) with a credential-free summary that includes queue wait time, upload duration and total time. Adds timing derivations and a log-safe summary to AsyncUploadJobEntry. --- .../model/AsyncUploadJobEntry.java | 43 +++++++ .../model/AsyncUploadJobEntryTest.java | 110 ++++++++++++++++++ .../controller/process/Messages.java | 3 + .../listeners/StartProcessListener.java | 26 ++++- .../listeners/StartProcessListenerTest.java | 13 ++- 5 files changed, 193 insertions(+), 2 deletions(-) create mode 100644 multiapps-controller-persistence/src/test/java/org/cloudfoundry/multiapps/controller/persistence/model/AsyncUploadJobEntryTest.java diff --git a/multiapps-controller-persistence/src/main/java/org/cloudfoundry/multiapps/controller/persistence/model/AsyncUploadJobEntry.java b/multiapps-controller-persistence/src/main/java/org/cloudfoundry/multiapps/controller/persistence/model/AsyncUploadJobEntry.java index a74c152602..325f2572b6 100644 --- a/multiapps-controller-persistence/src/main/java/org/cloudfoundry/multiapps/controller/persistence/model/AsyncUploadJobEntry.java +++ b/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"; + } } diff --git a/multiapps-controller-persistence/src/test/java/org/cloudfoundry/multiapps/controller/persistence/model/AsyncUploadJobEntryTest.java b/multiapps-controller-persistence/src/test/java/org/cloudfoundry/multiapps/controller/persistence/model/AsyncUploadJobEntryTest.java new file mode 100644 index 0000000000..a90bc99402 --- /dev/null +++ b/multiapps-controller-persistence/src/test/java/org/cloudfoundry/multiapps/controller/persistence/model/AsyncUploadJobEntryTest.java @@ -0,0 +1,110 @@ +package org.cloudfoundry.multiapps.controller.persistence.model; + +import java.time.Duration; +import java.time.LocalDateTime; + +import org.junit.jupiter.api.Assertions; +import org.junit.jupiter.api.Test; + +class AsyncUploadJobEntryTest { + + private static final String JOB_ID = "job-id"; + private static final String FILE_ID = "file-id"; + private static final String SPACE_GUID = "space-guid"; + private static final String USER = "user"; + private static final String URL = "https://user:secret@example.com/my.mtar"; + private static final LocalDateTime ADDED_AT = LocalDateTime.of(2026, 8, 3, 10, 0, 0); + private static final LocalDateTime STARTED_AT = ADDED_AT.plusSeconds(30); + private static final LocalDateTime FINISHED_AT = STARTED_AT.plusSeconds(90); + + @Test + void testTimingsForFinishedJob() { + AsyncUploadJobEntry job = baseBuilder().state(AsyncUploadJobEntry.State.FINISHED) + .addedAt(ADDED_AT) + .startedAt(STARTED_AT) + .finishedAt(FINISHED_AT) + .build(); + + Assertions.assertEquals(Duration.ofSeconds(30), job.getQueueWaitTime()); + Assertions.assertEquals(Duration.ofSeconds(90), job.getUploadDuration()); + Assertions.assertEquals(Duration.ofSeconds(120), job.getTotalTime()); + } + + @Test + void testTimingsAreNullWhenTimestampsMissing() { + AsyncUploadJobEntry runningJob = baseBuilder().state(AsyncUploadJobEntry.State.RUNNING) + .addedAt(ADDED_AT) + .startedAt(STARTED_AT) + .build(); + + Assertions.assertEquals(Duration.ofSeconds(30), runningJob.getQueueWaitTime()); + Assertions.assertNull(runningJob.getUploadDuration()); + Assertions.assertNull(runningJob.getTotalTime()); + + AsyncUploadJobEntry initialJob = baseBuilder().state(AsyncUploadJobEntry.State.INITIAL) + .addedAt(ADDED_AT) + .build(); + + Assertions.assertNull(initialJob.getQueueWaitTime()); + Assertions.assertNull(initialJob.getUploadDuration()); + Assertions.assertNull(initialJob.getTotalTime()); + } + + @Test + void testLogSafeSummaryContainsTimingsAndFileId() { + AsyncUploadJobEntry job = baseBuilder().state(AsyncUploadJobEntry.State.FINISHED) + .mtaId("my-mta") + .bytesRead(2048L) + .addedAt(ADDED_AT) + .startedAt(STARTED_AT) + .finishedAt(FINISHED_AT) + .build(); + + String summary = job.buildLogSummary(); + + Assertions.assertTrue(summary.contains(JOB_ID), summary); + Assertions.assertTrue(summary.contains(FILE_ID), summary); + Assertions.assertTrue(summary.contains("my-mta"), summary); + Assertions.assertTrue(summary.contains("queueWaitTime: 30000 ms"), summary); + Assertions.assertTrue(summary.contains("uploadDuration: 90000 ms"), summary); + Assertions.assertTrue(summary.contains("totalTime: 120000 ms"), summary); + } + + @Test + void testLogSafeSummaryHidesSensitiveData() { + AsyncUploadJobEntry job = baseBuilder().state(AsyncUploadJobEntry.State.RUNNING) + .addedAt(ADDED_AT) + .startedAt(STARTED_AT) + .build(); + + String summary = job.buildLogSummary(); + + Assertions.assertFalse(summary.contains(URL), summary); + Assertions.assertFalse(summary.contains("secret"), summary); + Assertions.assertFalse(summary.contains(USER), summary); + Assertions.assertFalse(summary.contains(SPACE_GUID), summary); + } + + @Test + void testLogSafeSummaryRendersMissingTimingsAsNotAvailable() { + AsyncUploadJobEntry job = baseBuilder().state(AsyncUploadJobEntry.State.INITIAL) + .addedAt(ADDED_AT) + .build(); + + String summary = job.buildLogSummary(); + + Assertions.assertTrue(summary.contains("queueWaitTime: " + AsyncUploadJobEntry.NOT_AVAILABLE), summary); + Assertions.assertTrue(summary.contains("uploadDuration: " + AsyncUploadJobEntry.NOT_AVAILABLE), summary); + Assertions.assertTrue(summary.contains("totalTime: " + AsyncUploadJobEntry.NOT_AVAILABLE), summary); + } + + private ImmutableAsyncUploadJobEntry.Builder baseBuilder() { + return ImmutableAsyncUploadJobEntry.builder() + .id(JOB_ID) + .fileId(FILE_ID) + .user(USER) + .url(URL) + .spaceGuid(SPACE_GUID) + .instanceIndex(0); + } +} diff --git a/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/Messages.java b/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/Messages.java index 6549708ff4..071dece894 100755 --- a/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/Messages.java +++ b/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/Messages.java @@ -820,6 +820,9 @@ public class Messages { public static final String IGNORING_NOT_FOUND_OPTIONAL_SERVICE = "Service {0} not found but is optional"; public static final String IGNORING_NOT_FOUND_INACTIVE_SERVICE = "Service {0} not found but is inactive"; + public static final String ASYNC_UPLOAD_JOB_FOR_OPERATION_0_IS_1 = "Async upload job for operation \"{0}\" - {1}"; + public static final String COULD_NOT_LOG_ASYNC_UPLOAD_JOBS_FOR_OPERATION_0 = "Could not log async upload jobs for operation \"{0}\""; + // Not log messages public static final String SERVICE_TYPE = "{0}/{1}"; public static final String PARSE_NULL_STRING_ERROR = "Cannot parse null string"; diff --git a/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/listeners/StartProcessListener.java b/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/listeners/StartProcessListener.java index fbca97c731..58dc7c2c22 100644 --- a/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/listeners/StartProcessListener.java +++ b/multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/listeners/StartProcessListener.java @@ -19,8 +19,10 @@ import org.cloudfoundry.multiapps.controller.api.model.ProcessType; import org.cloudfoundry.multiapps.controller.core.util.ApplicationConfiguration; import org.cloudfoundry.multiapps.controller.core.util.LoggingUtil; +import org.cloudfoundry.multiapps.controller.persistence.model.AsyncUploadJobEntry; import org.cloudfoundry.multiapps.controller.persistence.model.HistoricOperationEvent; import org.cloudfoundry.multiapps.controller.persistence.model.ImmutableHistoricOperationEvent; +import org.cloudfoundry.multiapps.controller.persistence.services.AsyncUploadJobService; import org.cloudfoundry.multiapps.controller.persistence.services.FileService; import org.cloudfoundry.multiapps.controller.persistence.services.FileStorageException; import org.cloudfoundry.multiapps.controller.persistence.services.HistoricOperationEventService; @@ -56,6 +58,7 @@ public class StartProcessListener extends AbstractProcessExecutionListener { private final ProcessTypeToOperationMetadataMapper operationMetadataMapper; private final DynatracePublisher dynatracePublisher; private final FileService fileService; + private final AsyncUploadJobService asyncUploadJobService; @Inject public StartProcessListener(ProgressMessageService progressMessageService, StepLogger.Factory stepLoggerFactory, @@ -63,7 +66,8 @@ public StartProcessListener(ProgressMessageService progressMessageService, StepL HistoricOperationEventService historicOperationEventService, FlowableFacade flowableFacade, ApplicationConfiguration configuration, ProcessTypeParser processTypeParser, OperationService operationService, ProcessTypeToOperationMetadataMapper operationMetadataMapper, - DynatracePublisher dynatracePublisher, FileService fileService) { + DynatracePublisher dynatracePublisher, FileService fileService, + AsyncUploadJobService asyncUploadJobService) { super(progressMessageService, stepLoggerFactory, processLoggerProvider, @@ -76,6 +80,7 @@ public StartProcessListener(ProgressMessageService progressMessageService, StepL this.operationMetadataMapper = operationMetadataMapper; this.dynatracePublisher = dynatracePublisher; this.fileService = fileService; + this.asyncUploadJobService = asyncUploadJobService; } @Override @@ -92,6 +97,7 @@ protected void notifyInternal(DelegateExecution execution) { } updateOperationFiles(execution, correlationId); + logAsyncUploadJobs(execution, correlationId); getHistoricOperationEventService().add(ImmutableHistoricOperationEvent.of(correlationId, HistoricOperationEvent.EventType.STARTED)); logProcessEnvironment(); logProcessVariables(execution, processType, correlationId); @@ -158,6 +164,24 @@ private void updateOperationFiles(DelegateExecution execution, String correlatio } } + private void logAsyncUploadJobs(DelegateExecution execution, String correlationId) { + List operationFileIds = OperationFileIdsUtil.getOperationFileIds(execution); + if (operationFileIds.isEmpty()) { + return; + } + try { + List asyncUploadJobs = asyncUploadJobService.createQuery() + .withFileIds(operationFileIds) + .list(); + for (AsyncUploadJobEntry asyncUploadJob : asyncUploadJobs) { + LOGGER.info(MessageFormat.format(Messages.ASYNC_UPLOAD_JOB_FOR_OPERATION_0_IS_1, correlationId, + asyncUploadJob.buildLogSummary())); + } + } catch (Exception e) { + LOGGER.warn(MessageFormat.format(Messages.COULD_NOT_LOG_ASYNC_UPLOAD_JOBS_FOR_OPERATION_0, correlationId), e); + } + } + private void publishDynatraceEvent(DelegateExecution execution, ProcessType processType, String correlationId) { DynatraceProcessEvent startEvent = ImmutableDynatraceProcessEvent.builder() .processId(correlationId) diff --git a/multiapps-controller-process/src/test/java/org/cloudfoundry/multiapps/controller/process/listeners/StartProcessListenerTest.java b/multiapps-controller-process/src/test/java/org/cloudfoundry/multiapps/controller/process/listeners/StartProcessListenerTest.java index bd4c656ab0..06b308e0ca 100644 --- a/multiapps-controller-process/src/test/java/org/cloudfoundry/multiapps/controller/process/listeners/StartProcessListenerTest.java +++ b/multiapps-controller-process/src/test/java/org/cloudfoundry/multiapps/controller/process/listeners/StartProcessListenerTest.java @@ -18,6 +18,8 @@ import org.cloudfoundry.multiapps.controller.api.model.ProcessType; import org.cloudfoundry.multiapps.controller.core.util.ApplicationConfiguration; import org.cloudfoundry.multiapps.controller.persistence.query.OperationQuery; +import org.cloudfoundry.multiapps.controller.persistence.query.AsyncUploadJobsQuery; +import org.cloudfoundry.multiapps.controller.persistence.services.AsyncUploadJobService; import org.cloudfoundry.multiapps.controller.persistence.services.FileService; import org.cloudfoundry.multiapps.controller.persistence.services.FileStorageException; import org.cloudfoundry.multiapps.controller.persistence.services.HistoricOperationEventService; @@ -78,6 +80,10 @@ class StartProcessListenerTest { private HistoricOperationEventService historicOperationEventService; @Mock private FileService fileService; + @Mock(answer = Answers.RETURNS_SELF) + private AsyncUploadJobService asyncUploadJobService; + @Mock(answer = Answers.RETURNS_SELF) + private AsyncUploadJobsQuery asyncUploadJobsQuery; @Spy private ProcessTypeToOperationMetadataMapper operationMetadataMapper; @Mock @@ -114,7 +120,8 @@ void setUp() throws Exception { operationService, operationMetadataMapper, dynatracePublisher, - fileService); + fileService, + asyncUploadJobService); } @ParameterizedTest @@ -139,6 +146,10 @@ private void prepare() { Mockito.doReturn(null) .when(operationQuery) .singleResult(); + Mockito.when(asyncUploadJobService.createQuery()) + .thenReturn(asyncUploadJobsQuery); + Mockito.when(asyncUploadJobsQuery.list()) + .thenReturn(Collections.emptyList()); } private void prepareContext() {