Process variables lost during Camunda async CompleteTaskOperation

Hello,

We have enabled asynchronous mode for Workflows.

It seems that some data are lost when calling the CompleteTaskOperation.

We get the Camunda ProcessEngineException:

2024-04-18T15:02:59.998+02:00 ERROR 6464 --- [aTaskExecutor-3] org.camunda.bpm.engine.context           : ENGINE-16004 Exception while closing command context: ENGINE-02004 No outgoing sequence flow for the element with id 'Gateway_UpdateOnboardFormSentDecision' could be selected for continuing the process.

org.camunda.bpm.engine.ProcessEngineException: ENGINE-02004 No outgoing sequence flow for the element with id 'Gateway_UpdateOnboardFormSentDecision' could be selected for continuing the process.
	at org.camunda.bpm.engine.impl.bpmn.behavior.BpmnBehaviorLogger.stuckExecutionException(BpmnBehaviorLogger.java:51) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.bpmn.behavior.ExclusiveGatewayActivityBehavior.doLeave(ExclusiveGatewayActivityBehavior.java:84) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.operation.PvmAtomicOperationActivityLeave.execute(PvmAtomicOperationActivityLeave.java:56) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.operation.PvmAtomicOperationActivityLeave.execute(PvmAtomicOperationActivityLeave.java:32) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.AtomicOperationInvocation.execute(AtomicOperationInvocation.java:99) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.invokeNext(CommandInvocationContext.java:130) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.performNext(CommandInvocationContext.java:110) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.performOperation(CommandInvocationContext.java:85) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:622) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:596) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.PvmExecutionImpl$6.callback(PvmExecutionImpl.java:2021) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.PvmExecutionImpl$6.callback(PvmExecutionImpl.java:2018) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.PvmExecutionImpl.continueExecutionIfNotCanceled(PvmExecutionImpl.java:2088) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.PvmExecutionImpl.dispatchDelayedEventsAndPerformOperation(PvmExecutionImpl.java:2037) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.PvmExecutionImpl.dispatchDelayedEventsAndPerformOperation(PvmExecutionImpl.java:2018) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.bpmn.behavior.FlowNodeActivityBehavior.leave(FlowNodeActivityBehavior.java:52) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.bpmn.behavior.FlowNodeActivityBehavior.execute(FlowNodeActivityBehavior.java:44) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.operation.PvmAtomicOperationActivityExecute$2.callback(PvmAtomicOperationActivityExecute.java:61) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.operation.PvmAtomicOperationActivityExecute$2.callback(PvmAtomicOperationActivityExecute.java:50) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.PvmExecutionImpl.continueIfExecutionDoesNotAffectNextOperation(PvmExecutionImpl.java:2082) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.operation.PvmAtomicOperationActivityExecute.execute(PvmAtomicOperationActivityExecute.java:42) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.operation.PvmAtomicOperationActivityExecute.execute(PvmAtomicOperationActivityExecute.java:31) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.AtomicOperationInvocation.execute(AtomicOperationInvocation.java:99) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.invokeNext(CommandInvocationContext.java:130) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.performNext(CommandInvocationContext.java:110) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.performOperation(CommandInvocationContext.java:85) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:622) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:596) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.PvmExecutionImpl$6.callback(PvmExecutionImpl.java:2021) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.PvmExecutionImpl$6.callback(PvmExecutionImpl.java:2018) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.PvmExecutionImpl.continueExecutionIfNotCanceled(PvmExecutionImpl.java:2088) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.PvmExecutionImpl.dispatchDelayedEventsAndPerformOperation(PvmExecutionImpl.java:2037) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.PvmExecutionImpl.dispatchDelayedEventsAndPerformOperation(PvmExecutionImpl.java:2018) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.operation.PvmAtomicOperationTransitionNotifyListenerStart.eventNotificationsCompleted(PvmAtomicOperationTransitionNotifyListenerStart.java:61) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.operation.PvmAtomicOperationTransitionNotifyListenerStart.eventNotificationsCompleted(PvmAtomicOperationTransitionNotifyListenerStart.java:30) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.core.operation.AbstractEventAtomicOperation.execute(AbstractEventAtomicOperation.java:70) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.AtomicOperationInvocation.execute(AtomicOperationInvocation.java:99) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.invokeNext(CommandInvocationContext.java:130) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.performNext(CommandInvocationContext.java:110) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.performOperation(CommandInvocationContext.java:85) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.performOperation(CommandInvocationContext.java:75) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:631) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:606) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.core.operation.AbstractEventAtomicOperation.execute(AbstractEventAtomicOperation.java:66) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.AtomicOperationInvocation.execute(AtomicOperationInvocation.java:99) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.invokeNext(CommandInvocationContext.java:130) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.performNext(CommandInvocationContext.java:110) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.performOperation(CommandInvocationContext.java:85) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.performOperation(CommandInvocationContext.java:75) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:631) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:606) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.core.operation.AbstractEventAtomicOperation.execute(AbstractEventAtomicOperation.java:66) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.AtomicOperationInvocation.execute(AtomicOperationInvocation.java:99) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.invokeNext(CommandInvocationContext.java:130) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.performNext(CommandInvocationContext.java:110) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.performOperation(CommandInvocationContext.java:85) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.performOperation(CommandInvocationContext.java:75) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:631) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.persistence.entity.ExecutionEntity.performOperationSync(ExecutionEntity.java:606) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.core.operation.AbstractEventAtomicOperation.execute(AbstractEventAtomicOperation.java:66) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.AtomicOperationInvocation.execute(AtomicOperationInvocation.java:99) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.invokeNext(CommandInvocationContext.java:130) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.performNext(CommandInvocationContext.java:110) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.performOperation(CommandInvocationContext.java:85) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:622) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.persistence.entity.ExecutionEntity.performOperation(ExecutionEntity.java:596) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.operation.PvmAtomicOperationTransitionCreateScope.scopeCreated(PvmAtomicOperationTransitionCreateScope.java:38) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.operation.PvmAtomicOperationCreateScope.execute(PvmAtomicOperationCreateScope.java:53) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.pvm.runtime.operation.PvmAtomicOperationCreateScope.execute(PvmAtomicOperationCreateScope.java:27) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.AtomicOperationInvocation.execute(AtomicOperationInvocation.java:99) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.invokeNext(CommandInvocationContext.java:130) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.performNext(CommandInvocationContext.java:117) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.performOperation(CommandInvocationContext.java:85) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandInvocationContext.performOperation(CommandInvocationContext.java:75) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.jobexecutor.AsyncContinuationJobHandler.execute(AsyncContinuationJobHandler.java:81) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.jobexecutor.AsyncContinuationJobHandler.execute(AsyncContinuationJobHandler.java:40) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.persistence.entity.JobEntity.execute(JobEntity.java:133) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.cmd.ExecuteJobsCmd.execute(ExecuteJobsCmd.java:110) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.cmd.ExecuteJobsCmd.execute(ExecuteJobsCmd.java:43) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandExecutorImpl.execute(CommandExecutorImpl.java:28) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandContextInterceptor.execute(CommandContextInterceptor.java:110) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.spring.SpringTransactionInterceptor.lambda$execute$0(SpringTransactionInterceptor.java:71) ~[camunda-engine-spring-6-7.20.0.jar:7.20.0]
	at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:140) ~[spring-tx-6.0.16.jar:6.0.16]
	at org.camunda.bpm.engine.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:71) ~[camunda-engine-spring-6-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.ProcessApplicationContextInterceptor.execute(ProcessApplicationContextInterceptor.java:70) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.CommandCounterInterceptor.execute(CommandCounterInterceptor.java:35) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:33) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.interceptor.ExceptionCodeInterceptor.execute(ExceptionCodeInterceptor.java:55) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.jobexecutor.ExecuteJobHelper.executeJob(ExecuteJobHelper.java:57) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.jobexecutor.ExecuteJobsRunnable.executeJob(ExecuteJobsRunnable.java:110) ~[camunda-engine-7.20.0.jar:7.20.0]
	at org.camunda.bpm.engine.impl.jobexecutor.ExecuteJobsRunnable.run(ExecuteJobsRunnable.java:71) ~[camunda-engine-7.20.0.jar:7.20.0]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na]
	at java.base/java.lang.Thread.run(Thread.java:840) ~[na:na]

The weird behaviour is that this error is random. Sometimes it happens, sometimes not, and we couldn’t identify why. Of course I checked the workflows bpmn but everything was fine, the workflow was supposed to continue at this point.

Then I saw that the GetProcessVariableUpdatesOperation is called as well in the logs. So I debugged it and saw that some process variables were wrong.

I added this snippet of code in our AfterUpdateDocumentHandler:

private void checkGetCamundaProcessVariablesUpdates(DocumentReference docRef) {

	runAsUserService.runAsSystemAdmin(() -> {
		FieldUpdatesDto updates = getProcessVariableUpdatesOperation.rpc(List.of(docRef));
		log.info(updates.getModificationMap().toString());
	});
}

and in the same way added a debugging log of the allModifications variable in this method:

private fun getProcessVariableUpdatesByDocRefs(documentReferences: List<DocumentReference>): FieldUpdatesDto {
    val allModifications = mutableMapOf<String, Any?>()

    for (docRef in documentReferences) {

        val documentModel = insecureDocumentModelResolver.getDocumentModelById(docRef.documentModelName)
        val document = documentService.load(docRef).get().kernelDocument
        val docSearch = DocumentServiceFactory(insecureDocumentModelResolver).createDocumentSearchService(document)
        val (modifications) = WorkflowsDocumentModelWalker().collectSyncAnnotatedFields(
            documentModel,
            docSearch
        )
        allModifications += modifications.mapValues { it.value.value }
    }

    return FieldUpdatesDto(allModifications)
    }

Here are the logs of when the bug happened after a few try:

2024-04-18 15:02:59,235 [ttp-nio-9091-exec-10][INFO ][handler.process.CandidateDocumentHandler][u:timUsr-ccrazy] - Customize document with action [PROCEED] and taskKey [Task_UpdateOnboardFormSentFeedback]
2024-04-18 15:02:59,235 [ttp-nio-9091-exec-10][INFO ][ocument.service.CandidateDocumentService][u:timUsr-ccrazy] - Add new status history with status = InOnboarding and index = 2
2024-04-18 15:02:59,236 [ttp-nio-9091-exec-10][INFO ][ndler.process.onboarding.OnboardFormSent][u:timUsr-ccrazy] - The document status has been changed from [OnboardFormSent] to [InOnboarding]
Breakpoint reached at com.mgmtp.mba.<PROJECT_NAME>.document.handler.process.CandidateDocumentHandler.afterUpdateDocumentHandler(CandidateDocumentHandler.java:68)
Breakpoint reached at com.mgmtp.a12.workflows.extension.internal.operation.GetProcessVariableUpdatesOperation.getProcessVariableUpdatesByDocRefs(GetProcessVariableUpdatesOperation.kt:64)
{countryEmploy=GER, status=InOnboarding, reviewType=INTERNAL_REVIEW, peerReviewerId=timUsr-ccrazy, peerReviewerName=Cai Crazy, defaultTaskAssigneeId=timUsr-ccrazy, defaultTaskAssigneeName=Cai Crazy, reviewResult=Correct, offerDecision=Accepted, offerLetterReviewResult=null, offerLetterDecision=null, needsReedit=false, needsArchive=false, onboardFormSentDecision=Correct}
2024-04-18 15:02:59,465 [ttp-nio-9091-exec-10][INFO ][handler.process.CandidateDocumentHandler][u:timUsr-ccrazy] - Handle after document updated with action [PROCEED] and taskKey [Task_UpdateOnboardFormSentFeedback]
2024-04-18 15:02:59,468 [ttp-nio-9091-exec-10][INFO ][ation.GetProcessVariableUpdatesOperation][u:timUsr-ccrazy] - GET_PROCESS_VARIABLE_UPDATES called with parameters [documentReferences=[CandidateDMProcess/11]]
2024-04-18 15:02:59,524 [ttp-nio-9091-exec-10][INFO ][handler.process.CandidateDocumentHandler][u:timUsr-ccrazy] - {countryEmploy=GER, status=InOnboarding, reviewType=INTERNAL_REVIEW, peerReviewerId=timUsr-ccrazy, peerReviewerName=Cai Crazy, defaultTaskAssigneeId=timUsr-ccrazy, defaultTaskAssigneeName=Cai Crazy, reviewResult=Correct, offerDecision=Accepted, offerLetterReviewResult=null, offerLetterDecision=null, needsReedit=false, needsArchive=false, onboardFormSentDecision=Correct}
2024-04-18 15:02:59,524 [ttp-nio-9091-exec-10][INFO ][og.service.DefaultChangelogCreateService][u:timUsr-ccrazy] - Create changelog for update document CandidateDMProcess
2024-04-18 15:02:59,549 [ttp-nio-9091-exec-10][INFO ][internal.operation.CompleteTaskOperation][u:timUsr-ccrazy] - COMPLETE_TASK called with parameters [taskDocRef=CandidateDMProcess/11,locale=en_US]
2024-04-18 15:02:59,873 [ttp-nio-9091-exec-10][INFO ][og.service.DefaultChangelogCreateService][u:timUsr-ccrazy] - Create changelog for update document CandidateDMProcess
2024-04-18 15:02:59,892 [rverImpl$6@1937637b)][INFO ][org.apache.activemq.audit.message       ][u:] - AMQ601500: User anonymous@invm:0 sent a message CoreMessage[messageID=4905, durable=true, userID=fb9bd18a-fd83-11ee-a684-047bcb62fbad, priority=4, timestamp=Thu Apr 18 15:02:59 CEST 2024, expiration=0, durable=true, address=WORKFLOWS_OUTBOX_QUEUE, size=550, properties=TypedProperties[_AMQ_GROUP_ID=CandidateBusiness, __AMQ_CID=3b42e39f-fd7e-11ee-a684-047bcb62fbad, timestamp=1713445379890667600, _AMQ_ROUTING_TYPE=1]]@893281217, context: RoutingContextImpl(Address=WORKFLOWS_OUTBOX_QUEUE, routingType=ANYCAST, PreviousAddress=WORKFLOWS_OUTBOX_QUEUE previousRoute:ANYCAST, reusable=true, version=-2147483644)
..................................................
***** durable queues WORKFLOWS_OUTBOX_QUEUE:
- queueID=14 address:WORKFLOWS_OUTBOX_QUEUE name:WORKFLOWS_OUTBOX_QUEUE filter:null
***** non durable for WORKFLOWS_OUTBOX_QUEUE:
..................................................
, transaction: null
2024-04-18 15:02:59,892 [rverImpl$6@1937637b)][INFO ][org.apache.activemq.audit.message       ][u:] - AMQ601501: User anonymous@invm:0 is consuming a message from WORKFLOWS_OUTBOX_QUEUE: Reference[4905]:RELIABLE:CoreMessage[messageID=4905, durable=true, userID=fb9bd18a-fd83-11ee-a684-047bcb62fbad, priority=4, timestamp=Thu Apr 18 15:02:59 CEST 2024, expiration=0, durable=true, address=WORKFLOWS_OUTBOX_QUEUE, size=550, properties=TypedProperties[_AMQ_GROUP_ID=CandidateBusiness, __AMQ_CID=3b42e39f-fd7e-11ee-a684-047bcb62fbad, timestamp=1713445379890667600, _AMQ_ROUTING_TYPE=1]]@893281217
2024-04-18 15:02:59,910 [http-nio-9091-exec-1][INFO ][ation.GetProcessVariableUpdatesOperation][u:systemAdmin] - GET_PROCESS_VARIABLE_UPDATES called with parameters [documentReferences=[CandidateDMProcess/11]]
Breakpoint reached at com.mgmtp.a12.workflows.extension.internal.operation.GetProcessVariableUpdatesOperation.getProcessVariableUpdatesByDocRefs(GetProcessVariableUpdatesOperation.kt:64)
{countryEmploy=GER, status=OnboardFormSent, reviewType=INTERNAL_REVIEW, peerReviewerId=timUsr-ccrazy, peerReviewerName=Cai Crazy, defaultTaskAssigneeId=timUsr-ccrazy, defaultTaskAssigneeName=Cai Crazy, reviewResult=Correct, offerDecision=Accepted, offerLetterReviewResult=null, offerLetterDecision=null, needsReedit=false, needsArchive=false, onboardFormSentDecision=null}
2024-04-18 15:02:59,985 [rverImpl$6@1937637b)][INFO ][org.apache.activemq.audit.message       ][u:] - AMQ601759: User anonymous@invm:0 added acknowledgement of a message from WORKFLOWS_OUTBOX_QUEUE: CoreMessage[messageID=4905, durable=true, userID=fb9bd18a-fd83-11ee-a684-047bcb62fbad, priority=4, timestamp=Thu Apr 18 15:02:59 CEST 2024, expiration=0, durable=true, address=WORKFLOWS_OUTBOX_QUEUE, size=550, properties=TypedProperties[_AMQ_GROUP_ID=CandidateBusiness, __AMQ_CID=3b42e39f-fd7e-11ee-a684-047bcb62fbad, timestamp=1713445379890667600, _AMQ_ROUTING_TYPE=1]]@893281217 to transaction: TransactionImpl [xid=null, txID=4904, xid=null, state=ACTIVE, createTime=1713445379527(Thu Apr 18 15:02:59 CEST 2024), timeoutSeconds=300, nr operations = 1]@7cf270d7
2024-04-18 15:02:59,985 [rverImpl$6@1937637b)][INFO ][org.apache.activemq.audit.message       ][u:] - AMQ601502: User anonymous@invm:0 acknowledged message from WORKFLOWS_OUTBOX_QUEUE: CoreMessage[messageID=4905, durable=true, userID=fb9bd18a-fd83-11ee-a684-047bcb62fbad, priority=4, timestamp=Thu Apr 18 15:02:59 CEST 2024, expiration=0, durable=true, address=WORKFLOWS_OUTBOX_QUEUE, size=550, properties=TypedProperties[_AMQ_GROUP_ID=CandidateBusiness, __AMQ_CID=3b42e39f-fd7e-11ee-a684-047bcb62fbad, timestamp=1713445379890667600, _AMQ_ROUTING_TYPE=1]]@893281217, transaction: TransactionImpl [xid=null, txID=4904, xid=null, state=COMMITTED, createTime=1713445379527(Thu Apr 18 15:02:59 CEST 2024), timeoutSeconds=300, nr operations = 0]@7cf270d7

We can see that the onboardFormSentDecision value is “Correct” in the AfterUpdateDocumentHandler but null the second time.

Is it something that you are aware of? We need to fix this quickly because we will have user tests very soon and the application is unstable because of that, should we revert disable the async mode?

Hi @alexis-raw-iron,

Could you please try to provide similar debug output containing the document value and relevant properties in the WorkflowsDocumentModelWalker?

If we cannot figure out a root cause this way, we’ll try to reproduce it on our side.

Thanks,
Peter

Hi @peter-smooth-cursor ,

Here are the log lines that are of interest for us:

Breakpoint reached at com.mgmtp.a12.workflows.extension.internal.sync.WorkflowsDocumentModelWalker$collectSyncAnnotatedFields$1.visitField(WorkflowsDocumentModelWalker.kt:58)
DEBUG - field: Field(super=Element(id=include_98a02_field_0bb75, name=OnboardFormSentDecision, internalDescription={en=Candidate fills in onboarding form}, externalDescription={}, annotations={availableInProcessAs=onboardFormSentDecision}), label={en=Onboarding form review, de=Review Onboarding-Formular}, isRequired=false, isGlobal=false, isTransient=false, variantFilter=Optional.empty, fieldType=EnumerationType(values=[EnumerationType.EnumValue(value=Correct, label={en=onboarding form is correct, de=Onboarding-Formular korrekt}), EnumerationType.EnumValue(value=Reedit, label={en=back to candidate for re-edit, de=zurück an Kandidat*in zur Korrektur})], categories=[], errorMessage={}, alphabeticalSorting=false, sValue=Optional.empty), helperText={}, additionalInfo=Optional.empty) - fieldList: [/Candidate[1]/MetaData[1]/Process[1]/Decisions[1]/OnboardFormSentDecision[1]=Correct]
Breakpoint reached at com.mgmtp.a12.workflows.extension.internal.sync.WorkflowsDocumentModelWalkerKt.getFieldValueAsCamundaVariable(WorkflowsDocumentModelWalker.kt:98)
DEBUG - syncValue: Correct
Breakpoint reached at com.mgmtp.a12.workflows.extension.internal.operation.GetProcessVariableUpdatesOperation.getProcessVariableUpdatesByDocRefs(GetProcessVariableUpdatesOperation.kt:64)
DEBUG - allModifications: {countryEmploy=GER, status=InOnboarding, reviewType=INTERNAL_REVIEW, peerReviewerId=timUsr-ccrazy, peerReviewerName=Cai Crazy, defaultTaskAssigneeId=timUsr-ccrazy, defaultTaskAssigneeName=Cai Crazy, reviewResult=Correct, offerDecision=Accepted, offerLetterReviewResult=null, offerLetterDecision=null, needsReedit=false, needsArchive=false, onboardFormSentDecision=Correct}

DEBUG - field: Field(super=Element(id=include_98a02_field_0bb75, name=OnboardFormSentDecision, internalDescription={en=Candidate fills in onboarding form}, externalDescription={}, annotations={availableInProcessAs=onboardFormSentDecision}), label={en=Onboarding form review, de=Review Onboarding-Formular}, isRequired=false, isGlobal=false, isTransient=false, variantFilter=Optional.empty, fieldType=EnumerationType(values=[EnumerationType.EnumValue(value=Correct, label={en=onboarding form is correct, de=Onboarding-Formular korrekt}), EnumerationType.EnumValue(value=Reedit, label={en=back to candidate for re-edit, de=zurück an Kandidat*in zur Korrektur})], categories=[], errorMessage={}, alphabeticalSorting=false, sValue=Optional.empty), helperText={}, additionalInfo=Optional.empty) - fieldList: []
Breakpoint reached at com.mgmtp.a12.workflows.extension.internal.sync.WorkflowsDocumentModelWalkerKt.getFieldValueAsCamundaVariable(WorkflowsDocumentModelWalker.kt:98)
DEBUG - syncValue: null

Breakpoint reached at com.mgmtp.a12.workflows.extension.internal.operation.GetProcessVariableUpdatesOperation.getProcessVariableUpdatesByDocRefs(GetProcessVariableUpdatesOperation.kt:64)
DEBUG - allModifications: {countryEmploy=GER, status=OnboardFormSent, reviewType=INTERNAL_REVIEW, peerReviewerId=timUsr-ccrazy, peerReviewerName=Cai Crazy, defaultTaskAssigneeId=timUsr-ccrazy, defaultTaskAssigneeName=Cai Crazy, reviewResult=Correct, offerDecision=Accepted, offerLetterReviewResult=null, offerLetterDecision=null, needsReedit=false, needsArchive=false, onboardFormSentDecision=null}

We can indeed see that the second time the fieldList is empty for our field…

Whole log:
workflows-bug.txt (46.0 KB)

Hello,
I did another test by adding some DEBUG logs to see what was in the document beofre and after calling the CompleteTaskOperation.
We can indeed see that the field OnboardFormSentDecision is missing in the second log (the case After the COMPLETE_TASK).

I couldn’t say why.
workflows-bug2.txt (163.3 KB)

Moin,
we arranged a separate meeting with the project to tackle the reported issues.

When these are solved we will follow-up with explanations on what caused them and was necessary to fix them.

issue will be addressed within A12-15849