Fix timed case completion

A stupid bug was introduced during approval processing separation.
Now it's fixed. TestEscalation.test220Reject no longer fails.

model/cases-impl/src/main/java/com/evolveum/midpoint/cases/impl/TimedActionTriggerHandler.java

@@ -125,6 +125,8 @@ private class TriggersExecution {
         }
 
         Collection<TriggerType> execute(OperationResult result) {
+            LOGGER.trace("Going to process {} trigger(s) on {}", triggers.size(), aCase);
+
             List<TriggerType> processedTriggers = new ArrayList<>();
             for (TriggerType trigger : triggers) {
                 CaseWorkItemType workItem = getWorkItem(trigger);
@@ -149,6 +151,7 @@ private CaseWorkItemType getWorkItem(TriggerType trigger) {
             if (workItem == null) {
                 LOGGER.warn("Work item {} couldn't be found; ignoring the trigger: {}", workItemId, trigger);
             }
+            LOGGER.trace("Found work item {}", workItem);
             return workItem;
         }
 
@@ -168,6 +171,8 @@ private class TriggerExecution {
             }
 
             private boolean process(OperationResult parentResult) {
+                LOGGER.trace("Going to process trigger {}", trigger);
+
                 OperationResult result = parentResult.createSubresult(OP_HANDLE_TRIGGER);
                 try {
                     Duration timeBeforeAction = getExtValue(SchemaConstants.MODEL_EXTENSION_TIME_BEFORE_ACTION);
@@ -205,6 +210,8 @@ private void sendNotifications(
                     return;
                 }
                 WorkItemOperationKindType operationKind = ApprovalContextUtil.getOperationKind(action);
+                LOGGER.trace("Processing notification about '{}' with time before action: {}", operationKind, timeBeforeAction);
+
                 WorkItemEventCauseInformationType cause = ApprovalContextUtil.createCause(action);
                 List<ObjectReferenceType> assigneesAndDeputies = miscHelper.getAssigneesAndDeputies(workItem, task, result);
                 WorkItemAllocationChangeOperationInfo operationInfo =
@@ -237,19 +244,22 @@ private void executeActions(
                 }
                 CompleteWorkItemActionType complete = actions.getComplete();
                 if (complete != null) {
-                    completionActions.add(
-                            new SingleCompletion(
-                                    workItem.getId(),
-                                    new AbstractWorkItemOutputType(prismContext)
-                                            .outcome( // TODO remove dependency on approvals
-                                                    requireNonNullElse(complete.getOutcome(), MODEL_APPROVAL_OUTCOME_REJECT))));
+                    SingleCompletion completion = new SingleCompletion(
+                            workItem.getId(),
+                            new AbstractWorkItemOutputType(prismContext)
+                                    .outcome( // TODO remove dependency on approvals
+                                            requireNonNullElse(complete.getOutcome(), MODEL_APPROVAL_OUTCOME_REJECT)));
+
+                    LOGGER.trace("Postponing completion: {}", completion);
+                    completionActions.add(completion);
                     cause = ApprovalContextUtil.createCause(complete);
                 }
             }
 
             private void executeNotificationAction(
                     @NotNull WorkItemNotificationActionType notificationAction,
                     @NotNull OperationResult result) throws SchemaException {
+                LOGGER.trace("Executing notification action: {}", notificationAction);
                 WorkItemTypeUtil.assertHasCaseOid(workItem);
                 WorkItemEventCauseInformationType cause = ApprovalContextUtil.createCause(notificationAction);
                 if (Boolean.FALSE.equals(notificationAction.isPerAssignee())) {
@@ -270,6 +280,7 @@ private void executeDelegateAction(
                     @NotNull OperationResult result)
                     throws SecurityViolationException, ObjectNotFoundException, SchemaException,
                     ExpressionEvaluationException, CommunicationException, ConfigurationException {
+                LOGGER.trace("Executing delegation/escalation action: {}", delegateAction);
                 WorkItemDelegationRequestType request = new WorkItemDelegationRequestType(prismContext);
                 request.getDelegate().addAll(
                         computeDelegateTo(delegateAction, result));
@@ -310,6 +321,8 @@ private void processCompletionActions(OperationResult parentResult) {
             try {
                 CompleteWorkItemsRequest request = new CompleteWorkItemsRequest(aCase.getOid(), cause);
                 request.getCompletions().addAll(completionActions);
+
+                LOGGER.trace("Going to process {} completion action(s) in a request:\n{}", completionActions.size(), request);
                 workItemManager.completeWorkItems(request, task, result);
             } catch (Throwable t) {
                 LoggingUtils.logUnexpectedException(LOGGER, "Couldn't handler work item completion", t);

model/cases-impl/src/main/java/com/evolveum/midpoint/cases/impl/engine/actions/CompleteWorkItemsAction.java

@@ -70,7 +70,9 @@ public CompleteWorkItemsAction(CaseEngineOperationImpl ctx, @NotNull CompleteWor
 
         boolean cancelRemainingWorkItems = false; // Should we auto-close other open work items?
         for (SingleCompletion completion : request.getCompletions()) {
-            cancelRemainingWorkItems = cancelRemainingWorkItems || completeSingleWorkItem(completion, result);
+            if (completeSingleWorkItem(completion, result)) {
+                cancelRemainingWorkItems = true;
+            }
         }
 
         if (cancelRemainingWorkItems) {
@@ -143,7 +145,8 @@ private void completeOrCancelWorkItem(
         WorkItemOperationKindType operationKind = output != null ?
                 WorkItemOperationKindType.COMPLETE : WorkItemOperationKindType.CANCEL;
 
-        LOGGER.trace("+++ processWorkItemClosure ENTER: workItem={}, op={}, operationKind={}", workItem, operation, operationKind);
+        LOGGER.trace("+++ completeOrCancelWorkItem ENTER: op={}, operationKind={}, workItem:\n{}",
+                operation, operationKind, workItem.debugDumpLazily());
 
         updateWorkItemAsClosed(workItem, output);
 
@@ -158,7 +161,7 @@ private void completeOrCancelWorkItem(
 
         beans.triggerHelper.removeTriggersForWorkItem(getCurrentCase(), workItem.getId());
 
-        LOGGER.trace("--- processWorkItemClosure EXIT: workItem={}, op={}, operationKind={}", workItem, operation, operationKind);
+        LOGGER.trace("--- completeOrCancelWorkItem EXIT: workItem={}, op={}, operationKind={}", workItem, operation, operationKind);
     }
 
     private void prepareAuditRecord(@NotNull CaseWorkItemType workItem, @NotNull OperationResult result) {

model/model-test/src/main/java/com/evolveum/midpoint/model/test/AbstractModelIntegrationTest.java

@@ -4071,6 +4071,17 @@ protected void assertHasDummyTransportMessage(String name, String expectedBody)
         fail("Notifier " + name + " message body " + expectedBody + " not found");
     }
 
+    protected void assertHasDummyTransportMessageContaining(String name, String expectedBodySubstring) {
+        List<Message> messages = dummyTransport.getMessages("dummy:" + name);
+        assertNotNull("No messages recorded in dummy transport '" + name + "'", messages);
+        for (Message message : messages) {
+            if (message.getBody() != null && message.getBody().contains(expectedBodySubstring)) {
+                return;
+            }
+        }
+        fail("Notifier " + name + " message body containing '" + expectedBodySubstring + "' not found");
+    }
+
     protected void displayAllNotifications() {
         for (java.util.Map.Entry<String, List<Message>> entry : dummyTransport.getMessages().entrySet()) {
             List<Message> messages = entry.getValue();

model/workflow-impl/src/main/java/com/evolveum/midpoint/wf/impl/ApprovalsCaseEngineExtension.java

@@ -10,7 +10,7 @@
 import javax.annotation.PostConstruct;
 
 import com.evolveum.midpoint.cases.api.extensions.WorkItemCompletionResult;
-import com.evolveum.midpoint.wf.impl.processors.primary.WorkItemCompletion;
+import com.evolveum.midpoint.wf.impl.processors.primary.cases.WorkItemCompletion;
 import com.evolveum.midpoint.xml.ns._public.common.common_3.CaseWorkItemType;
 
 import org.jetbrains.annotations.NotNull;
@@ -29,8 +29,8 @@
 import com.evolveum.midpoint.util.logging.Trace;
 import com.evolveum.midpoint.util.logging.TraceManager;
 import com.evolveum.midpoint.wf.impl.processors.primary.PrimaryChangeProcessor;
-import com.evolveum.midpoint.wf.impl.processors.primary.StageClosing;
-import com.evolveum.midpoint.wf.impl.processors.primary.StageOpening;
+import com.evolveum.midpoint.wf.impl.processors.primary.cases.CaseStageClosing;
+import com.evolveum.midpoint.wf.impl.processors.primary.cases.CaseStageOpening;
 import com.evolveum.midpoint.xml.ns._public.common.common_3.ApprovalContextType;
 import com.evolveum.midpoint.xml.ns._public.common.common_3.SystemObjectsType;
 
@@ -77,13 +77,13 @@ public boolean doesUseStages() {
     @Override
     public @NotNull StageOpeningResult processStageOpening(CaseEngineOperation operation, OperationResult result)
             throws SchemaException {
-        return new StageOpening(operation, beans)
+        return new CaseStageOpening(operation, beans)
                 .process(result);
     }
 
     @Override
     public @NotNull StageClosingResult processStageClosing(CaseEngineOperation operation, OperationResult result) {
-        return new StageClosing(operation, beans)
+        return new CaseStageClosing(operation, beans)
                 .process();
     }
 

model/workflow-impl/src/main/java/com/evolveum/midpoint/wf/impl/hook/WfHook.java

@@ -171,9 +171,11 @@ private HookOperationMode processModelInvocation(@NotNull ModelContext<? extends
                     if (hookOperationMode != null) {
                         return hookOperationMode;
                     }
-                } catch (ObjectNotFoundException|SchemaException|RuntimeException|ExpressionEvaluationException | CommunicationException | ConfigurationException | SecurityViolationException e) {
-                    LoggingUtils.logUnexpectedException(LOGGER, "Exception while running change processor {}: {}", e, changeProcessor.getClass().getName(), e.getMessage());
-                    result.recordFatalError("Exception while running change processor " + changeProcessor.getClass().getSimpleName() + ": " + e.getMessage(), e);
+                } catch (Exception e) {
+                    LoggingUtils.logUnexpectedException(LOGGER, "Exception while running change processor {}: {}", e,
+                            changeProcessor.getClass().getName(), e.getMessage());
+                    result.recordFatalError("Exception while running change processor "
+                            + changeProcessor.getClass().getSimpleName() + ": " + e.getMessage(), e);
                     return HookOperationMode.ERROR;
                 }
             }

model/workflow-impl/src/main/java/com/evolveum/midpoint/wf/impl/processors/ChangeProcessor.java

@@ -9,9 +9,8 @@
 
 import com.evolveum.midpoint.cases.api.CaseEngineOperation;
 import com.evolveum.midpoint.model.api.hooks.HookOperationMode;
-import com.evolveum.midpoint.prism.PrismContext;
 import com.evolveum.midpoint.repo.api.PreconditionViolationException;
-import com.evolveum.midpoint.schema.RelationRegistry;
+import com.evolveum.midpoint.schema.constants.SchemaConstants;
 import com.evolveum.midpoint.schema.result.OperationResult;
 import com.evolveum.midpoint.util.exception.CommunicationException;
 import com.evolveum.midpoint.util.exception.ConfigurationException;
@@ -20,59 +19,65 @@
 import com.evolveum.midpoint.util.exception.ObjectNotFoundException;
 import com.evolveum.midpoint.util.exception.SchemaException;
 import com.evolveum.midpoint.util.exception.SecurityViolationException;
+import com.evolveum.midpoint.wf.impl.processors.primary.PrimaryChangeProcessor;
 import com.evolveum.midpoint.wf.impl.util.MiscHelper;
 
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.Nullable;
 
 /**
  * A change processor can be viewed as a kind of framework supporting customer-specific
- * workflow code. Individual change processors are specialized in their areas, allowing
+ * approvals code. Individual change processors are specialized in their areas, allowing
  * customer code to focus on business logic with minimal effort.
  *
- * The name "change processor" is derived from the fact that primary purpose of this
+ * The name "change processor" is derived from the fact that main purpose of this
  * framework is to process change requests coming from the model.
  *
- * TODO find a better name
- *
  * However, a change processor has many more duties, e.g.
  *
- * (1) recognizes the instance (instances) of given kind of change within model operation context,
- * (2) processes the result of the workflow process instances when they are finished,
- * (3) presents (externalizes) the content of process instances to outside world: to the GUI, auditing, and notifications.
+ * 1. recognizes the instance (instances) of given kind of change within model operation context,
+ * 2. processes the result of the approval case objects when they are finished,
+ * 3. presents (externalizes) the content of approval cases to outside world: to the GUI, auditing, and notifications.
+ *
+ * Currently, there is only a single change processor implemented. It is {@link PrimaryChangeProcessor} that manages
+ * approvals of changes of objects that are captured during `primary` model state processing. They may deal with focus
+ * or with a projection, but they must be entered by the user - i.e. _not_ determined by the projector.
  *
- * Currently, there are the following change processors implemented or planned:
- * - PrimaryChangeProcessor: manages approvals of changes of objects (in model's primary stage)
- * - GeneralChangeProcessor: manages any change, as configured by the system engineer/administrator
+ * NOTE: Because the {@link PrimaryChangeProcessor} is the only one that is currently available, the code is not very
+ * clean in this respect. Some parts of existing code assume that this is the only processor, while others are more
+ * universal. Because we simply do not know for sure, we - for now - leave the code in this state: we neither do not
+ * generalize it to multiple processors, nor we simplify it to concentrate on this single processor.
  */
 public interface ChangeProcessor {
 
     /**
-     * Processes workflow-related aspect of a model operation. Namely, tries to find whether user interaction is necessary,
-     * and arranges everything to carry out that interaction.
+     * Processes approval-related aspect of a model operation.
+     *
+     * Namely, it tries to find whether user interaction is necessary, and arranges everything to carry out that interaction.
      *
-     * @param context Model context of the operation.
-     * @param wfConfigurationType Current workflow configuration (part of the system configuration).
-     * @param task Task in context of which the operation is carried out.
+     * @param ctx All information about the model operation, including e.g. model context.
      * @param result Where to put information on operation execution.
      * @return non-null value if it processed the request;
-     *              BACKGROUND = the process was "caught" by the processor, and continues in background,
-     *              FOREGROUND = nothing was left on background, the model operation should continue in foreground,
-     *              ERROR = something wrong has happened, there's no point in continuing with this operation.
-     *         null if the request is not relevant to this processor
+     *   {@link HookOperationMode#BACKGROUND} = the process was "caught" by the processor, and continues in background,
+     *   {@link HookOperationMode#FOREGROUND} = nothing was left on background, the model operation should continue in foreground,
+     *   {@link HookOperationMode#ERROR} = something wrong has happened, there's no point in continuing with this operation,
+     *   `null` if the request is not relevant to this processor.
      *
      * Actually, the FOREGROUND return value is quite unusual, because the change processor cannot
      * know in advance whether other processors would not want to process the invocation from the model.
      */
     @Nullable
     HookOperationMode processModelInvocation(@NotNull ModelInvocationContext<?> ctx, @NotNull OperationResult result)
-            throws SchemaException, ObjectNotFoundException, ExpressionEvaluationException, CommunicationException, ConfigurationException, SecurityViolationException;
+            throws SchemaException, ObjectNotFoundException, ExpressionEvaluationException, CommunicationException,
+            ConfigurationException, SecurityViolationException;
 
     /**
-     * Handles an event from WfMS that indicates finishing of the workflow process instance.
-     * Usually, at this point we see what was approved (and what was not) and continue with model operation(s).
+     * Handles the result of case processing. The case manager calls us when it finished its work on an approval case.
+     * (With the state of {@link SchemaConstants#CASE_STATE_CLOSING}.) At this point we see what was approved
+     * (and what was not) and we may start the real execution - or wait until all approval cases are resolved.
      *
-     * @param result Here should be stored information about whether the finalization was successful or not
+     * Note that this method is called OUTSIDE the workflow engine computation - i.e. changes
+     * are already committed into repository.
      */
     void finishCaseClosing(CaseEngineOperation operation, OperationResult result)
             throws SchemaException, ObjectAlreadyExistsException, ObjectNotFoundException, PreconditionViolationException,
@@ -100,9 +105,4 @@ void finishCaseClosing(CaseEngineOperation operation, OperationResult result)
 //            CaseType aCase, OperationResult result);
 
     MiscHelper getMiscHelper();
-
-    PrismContext getPrismContext();
-
-    RelationRegistry getRelationRegistry();
 }
-