Triggering of timer events produces inconsistent results.

[KristofferHogberg]

Description

I am writing unit tests for BPMN process models using the Zeebe Process Test library. In two of my tests, I am using the increaseTime() method followed by waitForBusyState() (as recommended in the README) to wait for a timer event to trigger. However, I am experiencing inconsistent test results, as the timer event is not triggering consistently.

Expected behaviour

Call engine.increaseTime(Duration.ofSeconds(70)); to trigger a interruptive timer boundary event, set to trigger after 1 minute - PT1M

Reproduction steps

@Test
void propProductionImageRenderingTimeout() throws InterruptedException, TimeoutException {
  
    // When
    final PublishMessageResponse publishMessageResponse =
            sendMessage(START_PROP_PROD_MSG, "", singletonMap(MSG_VARIABLE, MSG_VARIABLE_VALUE));

    sendMessage(START_IMAGE_RENDERING_MSG, CORR_KEY_INSTANCE_ID, singletonMap(MSG_VARIABLE, MSG_VARIABLE_VALUE));

    engine.increaseTime(Duration.ofSeconds(70));
    engine.waitForBusyState(Duration.ofSeconds());

    completeUserTask(TASK_CLEAN_UP_1_ID);

    BpmnAssert.assertThat(publishMessageResponse)
            .hasCreatedProcessInstance()
            .extractingProcessInstance()
            .hasPassedElement(PROP_PROD_START_EVENT_ID)
            .hasPassedElement(IMAGE_RENDERING_RECEIVE_TASK_ID)
            .hasPassedElement(TASK_CLEAN_UP_1_ID)

            .hasPassedElementsInOrder(PROP_PROD_START_EVENT_ID, IMAGE_RENDERING_RECEIVE_TASK_ID, TASK_CLEAN_UP_1_ID)

            .hasNotPassedElement(COMPLETE_IMAGE_RENDERING_ID)
            .hasNotPassedElement(IMAGE_RENDERING_END_EVENT_ID)

            .hasVariableWithValue(MSG_VARIABLE, MSG_VARIABLE_VALUE)
            .isCompleted();
}

As you can see, I am using the increaseTime() method to simulate the passage of time and the waitForBusyState() method to wait for the timer event to trigger.

However, the timer (interruptive timer boundary event, set to trigger after 1 minute - PT1M) event is not triggering consistently, which is causing the test to fail intermittently. I have tried increasing the timeout value in the waitForBusyState() method, but this has not resolved the issue. Any feedback or suggestions on how to resolve this issue would be greatly appreciated.

Environment

• OS: Windows 10 Pro
• Version:
  22H2
  OS build 19045.3324
  Experiene: Windows Feature Experience Pack 1000.19041.1000.0

[remcowesterhoud]

@KristofferHogberg Could you try waiting for idle state before increasing the engine time?

[remcowesterhoud]

I should also explain why. Increasing the time of the engine is pretty fast. It could be that the engine at that point is still processing records (it's busy). So when you wait for busy state it might not have reached the timer yet. By waiting for idle state we know (on best effort) that the engine is no longer processing so it's likely waiting for something to trigger processing again. In this case that would be the timer.

[KristofferHogberg]

I should have mentioned that I have tried waitForIdleState before increaseTime()

I have tried various durations in said methods but I still experince inconsistent behaviour in the tests.

If I run the same test multiple times, the timer sometime triggers and other times it does not.

[remcowesterhoud]

Could you share the output of a failed run? The logged records should have an indication on what is happening.

[KristofferHogberg]

Exported log as xml.

I should also mention that the point of failure has also been inconsistent.

Thank you very much for the help!

Test Results - BpmnUnitTestingDemoApplicationTests_propProductionImageRenderingTimeout.zip

[KristofferHogberg]

Here are the logs from a successful test run:

Test Results - Success-BpmnUnitTestingDemoApplicationTests_propProductionImageRenderingTimeout.zip

[remcowesterhoud]

Thanks @KristofferHogberg! I had a look and you're running into #876 🙂

java.lang.IllegalStateException: Expected the child count to be positive but was -1
	at io.camunda.zeebe.engine.state.instance.ElementInstance.decrementChildCount(ElementInstance.java:111)
	at io.camunda.zeebe.engine.state.instance.DbElementInstanceState.removeInstance(DbElementInstanceState.java:163)
	at io.camunda.zeebe.engine.state.appliers.ProcessInstanceElementTerminatedApplier.applyState(ProcessInstanceElementTerminatedApplier.java:41)
	at io.camunda.zeebe.engine.state.appliers.ProcessInstanceElementTerminatedApplier.applyState(ProcessInstanceElementTerminatedApplier.java:19)
	at io.camunda.zeebe.engine.state.appliers.EventAppliers.applyState(EventAppliers.java:302)
	at io.camunda.zeebe.engine.processing.streamprocessor.writers.ResultBuilderBackedEventApplyingStateWriter.appendFollowUpEvent(ResultBuilderBackedEventApplyingStateWriter.java:41)
	at io.camunda.zeebe.engine.processing.bpmn.behavior.BpmnStateTransitionBehavior.transitionTo(BpmnStateTransitionBehavior.java:220)
	at io.camunda.zeebe.engine.processing.bpmn.behavior.BpmnStateTransitionBehavior.transitionToTerminated(BpmnStateTransitionBehavior.java:210)
	at io.camunda.zeebe.engine.processing.bpmn.task.JobWorkerTaskProcessor.lambda$onTerminate$10(JobWorkerTaskProcessor.java:96)
	at java.base/java.util.Optional.ifPresentOrElse(Optional.java:198)
	at io.camunda.zeebe.engine.processing.bpmn.task.JobWorkerTaskProcessor.onTerminate(JobWorkerTaskProcessor.java:86)
	at io.camunda.zeebe.engine.processing.bpmn.task.JobWorkerTaskProcessor.onTerminate(JobWorkerTaskProcessor.java:25)
	at io.camunda.zeebe.engine.processing.bpmn.BpmnStreamProcessor.processEvent(BpmnStreamProcessor.java:111)
	at io.camunda.zeebe.engine.processing.bpmn.BpmnStreamProcessor.lambda$processRecord$0(BpmnStreamProcessor.java:84)
	at io.camunda.zeebe.util.Either$Right.ifRightOrLeft(Either.java:381)
	at io.camunda.zeebe.engine.processing.bpmn.BpmnStreamProcessor.processRecord(BpmnStreamProcessor.java:81)
	at io.camunda.zeebe.engine.Engine.process(Engine.java:142)
	at io.camunda.zeebe.stream.impl.ProcessingStateMachine.batchProcessing(ProcessingStateMachine.java:346)
	at io.camunda.zeebe.stream.impl.ProcessingStateMachine.lambda$processCommand$2(ProcessingStateMachine.java:268)
	at io.camunda.zeebe.process.test.engine.db.InMemoryDbTransaction.run(InMemoryDbTransaction.java:47)
	at io.camunda.zeebe.stream.impl.ProcessingStateMachine.processCommand(ProcessingStateMachine.java:268)
	at io.camunda.zeebe.stream.impl.ProcessingStateMachine.tryToReadNextRecord(ProcessingStateMachine.java:227)
	at io.camunda.zeebe.stream.impl.ProcessingStateMachine.readNextRecord(ProcessingStateMachine.java:203)
	at io.camunda.zeebe.scheduler.ActorJob.invoke(ActorJob.java:92)
	at io.camunda.zeebe.scheduler.ActorJob.execute(ActorJob.java:45)
	at io.camunda.zeebe.scheduler.ActorTask.execute(ActorTask.java:119)
	at io.camunda.zeebe.scheduler.ActorThread.executeCurrentTask(ActorThread.java:106)
	at io.camunda.zeebe.scheduler.ActorThread.doWork(ActorThread.java:87)
	at io.camunda.zeebe.scheduler.ActorThread.run(ActorThread.java:198)

I fixed this yesterday and it will be part of the next patch release. Sorry for the inconvenience this causes you!

[remcowesterhoud]

Closing as dupe of #876. Please reopen if you think this is incorrect!

[KristofferHogberg]

Thank you for the assistance!