Adding user info related information regarding deployment process actions

multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/Constants.java

@@ -36,6 +36,7 @@ public class Constants {
     public static final String TRIPLE_APPENDED_STRING = "%s%s%s";
     public static final String SECURE_EXTENSION_DESCRIPTOR_ID = "__mta.secure";
     public static final String STRING_SEPARATOR = "-";
+    public static final String AUTH_TOKEN_ORIGIN_FIELD = "origin";
 
     public static final Long UNSET_LAST_LOG_TIMESTAMP_MS = 0L;
     public static final int LOG_STALLED_TASK_MINUTE_INTERVAL = 5;

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

@@ -295,7 +295,8 @@ public class Messages {
     public static final String UNBINDING_SERVICE_INSTANCE_FROM_APP = "Unbinding service instance \"{0}\" from application \"{1}\"...";
     public static final String UNBINDING_SERVICE_INSTANCE_FROM_APP_FINISHED = "Unbinding service instance \"{0}\" from application \"{1}\" finished";
     public static final String POLLING_SERVICE_OPERATIONS = "Polling service operations...";
-    public static final String AUTO_ABORTING_PROCESS_0 = "Auto-aborting process \"{0}\"...";
+    public static final String AUTO_ABORTING_PROCESS_0 = "Auto-aborting process with processId: \"{0}\", action: ABORT, actor: system ...";
+    public static final String DEPLOYMENT_PROCESS_ACTION_EXECUTED_FOR_PROCESS_0_ACTION_1_USER_2_ORIGIN_3 = "MTA deployment process action executed - processId: \"{0}\", action: \"{1}\", userGUID: \"{2}\", origin: \"{3}\"";
     public static final String SOME_INSTANCES_ARE_DOWN = "Some instances are down. Check the application logs of your application for details.";
     public static final String SOME_INSTANCES_HAVE_CRASHED = "Some instances have crashed. Check the application logs of your application for details.";
     public static final String CLEAN_UP_JOB_STARTED_BY_APPLICATION_INSTANCE_0_AT_1 = "Clean-up job started by application instance {0} at: {1}";

multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/flowable/AbortProcessAction.java

@@ -90,7 +90,8 @@ public Action getAction() {
         return Action.ABORT;
     }
 
-    private Logger getLogger() {
+    @Override
+    protected Logger getLogger() {
         return LOGGER;
     }
 

multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/flowable/ProcessAction.java

@@ -1,5 +1,6 @@
 package org.cloudfoundry.multiapps.controller.process.flowable;
 
+import java.text.MessageFormat;
 import java.util.List;
 import java.util.stream.Collectors;
 
@@ -9,11 +10,14 @@
 import org.cloudfoundry.multiapps.controller.core.cf.CloudControllerClientProvider;
 import org.cloudfoundry.multiapps.controller.core.util.UserInfo;
 import org.cloudfoundry.multiapps.controller.persistence.services.OperationService;
+import org.cloudfoundry.multiapps.controller.process.Constants;
+import org.cloudfoundry.multiapps.controller.process.Messages;
 import org.cloudfoundry.multiapps.controller.process.util.ClientReleaser;
 import org.cloudfoundry.multiapps.controller.process.util.HistoryUtil;
 import org.cloudfoundry.multiapps.controller.process.variables.Variables;
 import org.flowable.engine.HistoryService;
 import org.flowable.engine.RuntimeService;
+import org.slf4j.Logger;
 
 public abstract class ProcessAction {
 
@@ -38,6 +42,10 @@
     }
 
     public void execute(UserInfo userInfo, String superProcessInstanceId) {
+        if (userInfo != null) {
+            logLifecycle(userInfo, superProcessInstanceId);
+        }
+
         for (AdditionalProcessAction additionalProcessAction : filterAdditionalActionsForThisAction()) {
             additionalProcessAction.executeAdditionalProcessAction(superProcessInstanceId);
         }
@@ -86,4 +94,15 @@
                                       .build();
         operationService.update(operation, operation);
     }
+
+    protected abstract Logger getLogger();
+
+    protected void logLifecycle(UserInfo userInfo, String processId) {
+        getLogger().info(MessageFormat.format(
+            Messages.DEPLOYMENT_PROCESS_ACTION_EXECUTED_FOR_PROCESS_0_ACTION_1_USER_2_ORIGIN_3,
+            processId, getAction().toString(), userInfo.getId(), userInfo.getToken()
+                                                                         .getAdditionalInfo()
+                                                                         .get(Constants.AUTH_TOKEN_ORIGIN_FIELD)));
+    }
+
 }

multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/flowable/ResumeProcessAction.java

@@ -53,6 +53,11 @@ private void triggerProcessInstance(UserInfo userInfo, String processId) {
         }
     }
 
+    @Override
+    protected Logger getLogger() {
+        return LOGGER;
+    }
+
     @Override
     public Action getAction() {
         return Action.RESUME;

multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/flowable/RetryProcessAction.java

@@ -60,4 +60,9 @@ public Action getAction() {
         return Action.RETRY;
     }
 
+    @Override
+    protected Logger getLogger() {
+        return LOGGER;
+    }
+
 }

multiapps-controller-process/src/main/java/org/cloudfoundry/multiapps/controller/process/jobs/OperationsCleaner.java

@@ -1,14 +1,11 @@
 package org.cloudfoundry.multiapps.controller.process.jobs;
 
-import static java.text.MessageFormat.format;
-
 import java.time.LocalDateTime;
 import java.time.ZonedDateTime;
 import java.util.List;
 
 import jakarta.inject.Inject;
 import jakarta.inject.Named;
-
 import org.cloudfoundry.multiapps.controller.api.model.ImmutableOperation;
 import org.cloudfoundry.multiapps.controller.api.model.Operation;
 import org.cloudfoundry.multiapps.controller.persistence.OrderDirection;
@@ -18,11 +15,12 @@
 import org.cloudfoundry.multiapps.controller.process.flowable.ProcessAction;
 import org.cloudfoundry.multiapps.controller.process.flowable.ProcessActionRegistry;
 import org.flowable.common.engine.api.FlowableObjectNotFoundException;
-
 import org.slf4j.Logger;
 import org.slf4j.LoggerFactory;
 import org.springframework.core.annotation.Order;
 
+import static java.text.MessageFormat.format;
+
 @Named
 @Order(10)
 public class OperationsCleaner implements Cleaner {
@@ -59,7 +57,7 @@
 
     private int abortActiveOperations(LocalDateTime expirationTime) {
         int abortedOperations = 0;
-        for (int pageIndex = 0;; pageIndex++) {
+        for (int pageIndex = 0; ; pageIndex++) {
             List<Operation> operationsPage = getOperationsPage(expirationTime, pageIndex);
             for (Operation operation : operationsPage) {
                 if (inFinalState(operation)) {
@@ -106,7 +104,7 @@
     private void abort(Operation operation) {
         ProcessAction abortAction = processActionRegistry.getAction(Action.ABORT);
         String processId = operation.getProcessId();
-        LOGGER.debug(CleanUpJob.LOG_MARKER, format(Messages.ABORTING_OPERATION_0, processId));
+        LOGGER.info(CleanUpJob.LOG_MARKER, format(Messages.AUTO_ABORTING_PROCESS_0, processId));
         abortAction.execute(null, processId);
     }
 

multiapps-controller-process/src/test/java/org/cloudfoundry/multiapps/controller/process/flowable/AbortProcessActionTest.java

@@ -23,6 +23,7 @@
 import org.mockito.ArgumentCaptor;
 import org.mockito.Mock;
 import org.mockito.Mockito;
+import org.slf4j.Logger;
 
 class AbortProcessActionTest extends ProcessActionTest {
 
@@ -46,6 +47,7 @@
                                                                  .processType(ProcessType.DEPLOY)
                                                                  .state(Operation.State.RUNNING)
                                                                  .build();
+
     @BeforeEach
     void setUp() {
         prepareOperationService();
@@ -55,7 +57,7 @@
     @Test
     void testAbortExecution() {
         processAction.execute(null, PROCESS_GUID);
         Mockito.verify(historicOperationEventService)
                .add(ImmutableHistoricOperationEvent.of(PROCESS_GUID, HistoricOperationEvent.EventType.ABORTED));
         Mockito.verify(historicOperationEventService)
                .add(ImmutableHistoricOperationEvent.of(PROCESS_GUID, HistoricOperationEvent.EventType.ABORT_EXECUTED));
@@ -64,7 +66,7 @@
     @Test
     void testAbortActionAndPublishingDynatraceEvent() {
         ProcessType processType = ProcessType.DEPLOY;
         Mockito.when(progressMessageQuery.list())
                .thenReturn(List.of(progressMessage));
         processAction.execute(null, PROCESS_GUID);
         ArgumentCaptor<DynatraceProcessEvent> argumentCaptor = ArgumentCaptor.forClass(DynatraceProcessEvent.class);
@@ -79,15 +81,32 @@
 
     @Test
     void testAbortActionNoPublishingDynatraceEvent() {
         Mockito.when(progressMessageQuery.list())
                .thenReturn(Collections.emptyList());
         processAction.execute(null, PROCESS_GUID);
         Mockito.verify(dynatracePublisher, Mockito.never())
                .publishProcessEvent(Mockito.any(), Mockito.any());
     }
 
+    @Test
+    void testAbortActionWithUserGuidAndOriginButNotUsername() {
+        Logger logger = Mockito.mock(Logger.class);
+        ProcessAction abortAction = new AbortProcessAction(flowableFacade, Collections.emptyList(),
+                                                           historicOperationEventService, operationService,
+                                                           cloudControllerClientProvider, progressMessageService,
+                                                           dynatracePublisher) {
+            @Override
+            protected Logger getLogger() {
+                return logger;
+            }
+        };
+
+        abortAction.execute(USER_INFO, PROCESS_GUID);
+        assertUserInfoLogContent(logger, Action.ABORT);
+    }
+
     private void prepareOperationService() {
         OperationQuery mockedOperationQuery = Mockito.mock(OperationQuery.class);
         Mockito.when(mockedOperationQuery.processId(PROCESS_GUID))
                .thenReturn(mockedOperationQuery);
         Mockito.when(mockedOperationQuery.singleResult())
@@ -99,9 +118,9 @@
     private void prepareProgressMessageService() {
         Mockito.when(progressMessageService.createQuery())
                .thenReturn(progressMessageQuery);
         Mockito.when(progressMessageQuery.processId(PROCESS_GUID))
                .thenReturn(progressMessageQuery);
         Mockito.when(progressMessageQuery.type(ProgressMessageType.ERROR))
                .thenReturn(progressMessageQuery);
     }
 

multiapps-controller-process/src/test/java/org/cloudfoundry/multiapps/controller/process/flowable/ProcessActionTest.java

@@ -2,11 +2,13 @@
 
 import java.util.ArrayList;
 import java.util.List;
+import java.util.Map;
 import java.util.UUID;
 import java.util.function.Supplier;
 
 import org.cloudfoundry.multiapps.controller.api.model.ImmutableOperation;
 import org.cloudfoundry.multiapps.controller.api.model.Operation;
+import org.cloudfoundry.multiapps.controller.client.facade.oauth2.OAuth2AccessTokenWithAdditionalInfo;
 import org.cloudfoundry.multiapps.controller.core.cf.CloudControllerClientProvider;
 import org.cloudfoundry.multiapps.controller.core.util.UserInfo;
 import org.cloudfoundry.multiapps.controller.persistence.query.impl.OperationQueryImpl;
@@ -17,10 +19,14 @@
 import org.flowable.engine.runtime.Execution;
 import org.flowable.variable.api.history.HistoricVariableInstanceQuery;
 import org.junit.jupiter.api.BeforeEach;
+import org.mockito.ArgumentCaptor;
 import org.mockito.Mock;
 import org.mockito.Mockito;
 import org.mockito.MockitoAnnotations;
+import org.slf4j.Logger;
 
+import static org.junit.jupiter.api.Assertions.assertFalse;
+import static org.junit.jupiter.api.Assertions.assertTrue;
 import static org.mockito.ArgumentMatchers.anyString;
 
 abstract class ProcessActionTest {
@@ -31,7 +37,8 @@
     static final String PROCESS_GUID = RANDOM_UUID_SUPPLIER.get();
     static final String SUBPROCESS_1_ID = RANDOM_UUID_SUPPLIER.get();
     static final String SUBPROCESS_2_ID = RANDOM_UUID_SUPPLIER.get();
-    static final UserInfo USER_INFO = new UserInfo("fake-user-guid", "fake-user", null);
+    static final OAuth2AccessTokenWithAdditionalInfo token = mockToken();
+    static final UserInfo USER_INFO = new UserInfo("fake-user-guid", "fake-user", token);
 
     protected ProcessAction processAction;
     @Mock
@@ -67,21 +74,21 @@
         List<Execution> mockedExecutions = getMockedExecutions();
         Mockito.when(flowableFacade.findExecutionsAtReceiveTask(PROCESS_GUID))
                .thenReturn(mockedExecutions);
         Mockito.when(flowableFacade.findExecutionsAtReceiveTask(SUBPROCESS_1_ID))
                .thenReturn(mockedExecutions);
         Mockito.when(flowableFacade.getProcessEngine())
                .thenReturn(processEngine);
     }
 
     private void prepareProcessEngine() {
         Mockito.when(processEngine.getHistoryService())
                .thenReturn(historyService);
         Mockito.when(processEngine.getRuntimeService())
                .thenReturn(runtimeService);
     }
 
     protected List<Execution> getMockedExecutions() {
         Execution execution = Mockito.mock(Execution.class);
         Mockito.when(execution.getId())
                .thenReturn(EXECUTION_ID);
         return List.of(execution);
@@ -95,12 +102,12 @@
     }
 
     private void prepareHistoryService() {
         HistoricVariableInstanceQuery historicVariableInstanceQuery = Mockito.mock(HistoricVariableInstanceQuery.class);
         Mockito.when(historicVariableInstanceQuery.processInstanceId(anyString()))
                .thenReturn(historicVariableInstanceQuery);
         Mockito.when(historicVariableInstanceQuery.variableName(anyString()))
                .thenReturn(historicVariableInstanceQuery);
         Mockito.when(historyService.createHistoricVariableInstanceQuery())
                .thenReturn(historicVariableInstanceQuery);
     }
 
@@ -120,9 +127,40 @@
         Operation operation = ImmutableOperation.builder()
                                                 .state(state)
                                                 .build();
         Mockito.verify(operationService)
                .update(operation, operation);
     }
 
+    protected void assertUserInfoLogContent(Logger logger, Action expectedAction) {
+        ArgumentCaptor<String> argumentCaptor = ArgumentCaptor.forClass(String.class);
+        Mockito.verify(logger, Mockito.atLeastOnce())
+               .info(argumentCaptor.capture());
+        String logMessageToVerify = argumentCaptor.getAllValues()
+                                                  .stream()
+                                                  .filter(message -> message != null && message.contains(
+                                                      "MTA deployment process action executed"))
+                                                  .findFirst()
+                                                  .orElseThrow(
+                                                      () -> new AssertionError("No log line was printed. Captured logs: "
+                                                                                   + argumentCaptor.getAllValues()));
+        assertTrue(logMessageToVerify.contains("processId: \"" + PROCESS_GUID + "\""),
+                   "Must contain the processId. Actual: " + logMessageToVerify);
+        assertTrue(logMessageToVerify.contains("action: \"" + expectedAction + "\""),
+                   "Must contain the action. Actual: " + logMessageToVerify);
+        assertTrue(logMessageToVerify.contains("userGUID: \"fake-user-guid\""),
+                   "Must contain the userGUID. Actual: " + logMessageToVerify);
+        assertTrue(logMessageToVerify.contains("origin: \"test-origin\""),
+                   "Must contain the origin. Actual: " + logMessageToVerify);
+        assertFalse(logMessageToVerify.contains("fake-user\""),
+                    "Must NOT contain the username. Actual: " + logMessageToVerify);
+    }
+
     protected abstract ProcessAction createProcessAction();
+
+    private static OAuth2AccessTokenWithAdditionalInfo mockToken() {
+        OAuth2AccessTokenWithAdditionalInfo token = Mockito.mock(OAuth2AccessTokenWithAdditionalInfo.class);
+        Mockito.when(token.getAdditionalInfo())
+               .thenReturn(Map.of("origin", "test-origin"));
+        return token;
+    }
 }

multiapps-controller-process/src/test/java/org/cloudfoundry/multiapps/controller/process/flowable/ResumeProcessActionTest.java

@@ -9,6 +9,7 @@
 import org.flowable.engine.runtime.Execution;
 import org.junit.jupiter.api.Test;
 import org.mockito.Mockito;
+import org.slf4j.Logger;
 
 import static org.mockito.Mockito.times;
 
@@ -25,7 +26,7 @@
     @Test
     void testResumeExecutionWithoutExecutionsAtReceiveTask() {
         List<Execution> mockedExecutions = getMockedExecutions();
         Mockito.when(flowableFacade.findExecutionsAtReceiveTask(PROCESS_GUID))
                .thenReturn(mockedExecutions)
                .thenReturn(Collections.emptyList());
         processAction.execute(USER_INFO, PROCESS_GUID);
@@ -38,4 +39,18 @@
     protected ProcessAction createProcessAction() {
         return new ResumeProcessAction(flowableFacade, Collections.emptyList(), operationService, cloudControllerClientProvider);
     }
+
+    @Test
+    void testResumeActionWithUserGuidAndOriginButNotUsername() {
+        Logger logger = Mockito.mock(Logger.class);
+        ProcessAction resumeAction = new ResumeProcessAction(flowableFacade, Collections.emptyList(), operationService,
+                                                             cloudControllerClientProvider) {
+            @Override
+            protected Logger getLogger() {
+                return logger;
+            }
+        };
+        resumeAction.execute(USER_INFO, PROCESS_GUID);
+        assertUserInfoLogContent(logger, Action.RESUME);
+    }
 }

multiapps-controller-process/src/test/java/org/cloudfoundry/multiapps/controller/process/flowable/RetryProcessActionTest.java

@@ -10,6 +10,7 @@
 import org.junit.jupiter.api.Test;
 import org.mockito.Mock;
 import org.mockito.Mockito;
+import org.slf4j.Logger;
 
 class RetryProcessActionTest extends ProcessActionTest {
 
@@ -31,12 +32,12 @@
 
     @Test
     void testRetryActionWithExceptionForRootProcess() {
         Mockito.doThrow(new RuntimeException())
                .when(flowableFacade)
                .executeJob(PROCESS_GUID);
         processAction.execute(USER_INFO, PROCESS_GUID);
         verifySubprocessesAreExecuted();
         Mockito.verify(historicOperationEventService)
                .add(ImmutableHistoricOperationEvent.of(PROCESS_GUID, HistoricOperationEvent.EventType.RETRIED));
         assertStateUpdated(Operation.State.RUNNING);
     }
@@ -48,6 +49,21 @@
                .executeJob(SUBPROCESS_2_ID);
     }
 
+    @Test
+    void testRetryActionWithUserGuidAndOriginButNotUsername() {
+        Logger logger = Mockito.mock(Logger.class);
+        ProcessAction retryAction = new RetryProcessAction(flowableFacade, List.of(), historicOperationEventService,
+                                                           operationService, cloudControllerClientProvider) {
+            @Override
+            protected Logger getLogger() {
+                return logger;
+            }
+        };
+
+        retryAction.execute(USER_INFO, PROCESS_GUID);
+        assertUserInfoLogContent(logger, Action.RETRY);
+    }
+
     @Override
     protected ProcessAction createProcessAction() {
         return new RetryProcessAction(flowableFacade,

multiapps-controller-process/src/test/java/org/cloudfoundry/multiapps/controller/process/flowable/StartProcessActionTest.java

@@ -7,6 +7,7 @@
 import org.cloudfoundry.multiapps.controller.process.variables.Variables;
 import org.junit.jupiter.api.Test;
 import org.mockito.Mockito;
+import org.slf4j.Logger;
 
 import static org.mockito.Mockito.times;
 
@@ -24,4 +25,19 @@ void testResumeExecution() {
     protected ProcessAction createProcessAction() {
         return new StartProcessAction(flowableFacade, Collections.emptyList(), operationService, cloudControllerClientProvider);
     }
+
+    @Test
+    void testStartActionWithUserGuidAndOriginButNotUsername() {
+        Logger logger = Mockito.mock(Logger.class);
+        ProcessAction startAction = new StartProcessAction(flowableFacade, Collections.emptyList(), operationService,
+                                                           cloudControllerClientProvider) {
+            @Override
+            protected Logger getLogger() {
+                return logger;
+            }
+        };
+
+        startAction.execute(USER_INFO, PROCESS_GUID);
+        assertUserInfoLogContent(logger, Action.START);
+    }
 }

multiapps-controller-web/src/main/java/org/cloudfoundry/multiapps/controller/web/Constants.java

@@ -21,6 +21,7 @@ private Constants() {
     public static final String CSRF_PARAM_NAME = "X-CSRF-PARAM";
     public static final String CSRF_HEADER_NAME = "X-CSRF-HEADER";
     public static final String CONTENT_LENGTH = "Content-Length";
+    public static final String AUTH_TOKEN_ORIGIN_FIELD = "origin";
 
     public static final long OAUTH_TOKEN_RETENTION_TIME_IN_SECONDS = TimeUnit.MINUTES.toSeconds(2);
     public static final long BASIC_TOKEN_RETENTION_TIME_IN_SECONDS = TimeUnit.MINUTES.toSeconds(6);

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

@@ -71,6 +71,7 @@ public final class Messages {
     public static final String OBJECT_STORE_WITH_PROVIDER_0_CREATED = "Object store with provider: {0} created";
     public static final String JOB_WITH_ID_WAS_NOT_UPDATED_WITHIN_SECONDS = "Job with ID: {} was not updated within: {} seconds";
     public static final String CLEARING_OLD_ENTRY = "Clearing old entry with id: {0}";
+    public static final String STARTED_OPERATION_0_BY_USER_1_AND_ORIGIN_OF_2 = "Started operation \"{0}\" by user \"{1}\" and origin of \"{2}\".";
 
     // DEBUG log messages
     public static final String RECEIVED_UPLOAD_REQUEST = "Received upload request on URI: {}";