search

camunda / zeebe-process-test

Testing project for Camunda Platform 8
40 stars 15 forks source link

TimerTest started to fail consistently #1230

Open ana-vinogradova-camunda opened 3 weeks ago

ana-vinogradova-camunda commented 3 weeks ago

Description

AbstractTimerTest was introduced in this PR as a result of solving this issue. The root cause of the issue was in Bytes class compareTo(final Bytes other) method.

Before we used to compare byte arrays tin the following way:

if (ourByte < otherByte) {
        return SMALLER;
    } else if (ourByte > otherByte) {
        return BIGGER;
    } // else { // = equals -> continue }

This was leading to incorrect date comparison as we were comparing signed bytes and sometimes the date that was supposed to come after some other date had a negative byte (ex. -97).

For example: 2023.10.10 15:50:00 date will look as follows when converted to bytes array: [0, 0, 1, -117, 25...] 2023.11.5 15:50:00 date will look as follows when converted to bytes array: [0, 0, 1, -117, -97...]

When comparing these 2 dates we would previously get 2023.11.5 15:50:00 as a smaller date that would result in 2023.10.10 15:50:00 timer event to not be activated. The fix to use Guava UnsignedBytes.compare(ourByte, otherByte).

TimerTest failures were reported this week (19 August) and the test is failing consistently now. I can reproduce the failure every time when running the test:

stack trace ``` [zb-actors-7] INFO io.camunda.zeebe.logstreams - Recovered state of partition 1 from snapshot at position -1 [zb-actors-7] INFO org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@2d4b22a0)), function-provider: io.camunda.zeebe.feel.impl.FeelFunctionProvider@b981460, clock: io.camunda.zeebe.engine.processing.bpmn.clock.ZeebeFeelEngineClock@6e32ce2c, configuration: {externalFunctionsEnabled: false}] [zb-actors-7] INFO org.camunda.dmn.DmnEngine - DMN-Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@3efe5dec)), function-provider: org.camunda.feel.context.FunctionProvider$EmptyFunctionProvider$@59fb543a, audit-loggers: List(), configuration: Configuration(false,false,false)] [zb-actors-7] INFO org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(org.camunda.dmn.NoUnpackValueMapper@39464d1c)), function-provider: org.camunda.feel.context.FunctionProvider$EmptyFunctionProvider$@59fb543a, clock: SystemClock, configuration: {externalFunctionsEnabled: false}] [zb-actors-7] INFO org.camunda.dmn.DmnEngine - DMN-Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@50236c94)), function-provider: org.camunda.feel.context.FunctionProvider$EmptyFunctionProvider$@59fb543a, audit-loggers: List(), configuration: Configuration(false,false,false)] [zb-actors-7] INFO org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(org.camunda.dmn.NoUnpackValueMapper@168c26ab)), function-provider: org.camunda.feel.context.FunctionProvider$EmptyFunctionProvider$@59fb543a, clock: SystemClock, configuration: {externalFunctionsEnabled: false}] [zb-actors-7] INFO org.camunda.dmn.DmnEngine - DMN-Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@3abd96fe)), function-provider: org.camunda.feel.context.FunctionProvider$EmptyFunctionProvider$@59fb543a, audit-loggers: List(), configuration: Configuration(false,false,false)] [zb-actors-7] INFO org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(org.camunda.dmn.NoUnpackValueMapper@3df678fb)), function-provider: org.camunda.feel.context.FunctionProvider$EmptyFunctionProvider$@59fb543a, clock: SystemClock, configuration: {externalFunctionsEnabled: false}] [zb-actors-7] INFO org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@712913f4)), function-provider: io.camunda.zeebe.feel.impl.FeelFunctionProvider@4803da2d, clock: io.camunda.zeebe.engine.processing.bpmn.clock.ZeebeFeelEngineClock@1b4ac28d, configuration: {externalFunctionsEnabled: false}] [zb-actors-7] INFO org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@4f834d7c)), function-provider: io.camunda.zeebe.feel.impl.FeelFunctionProvider@bc57032, clock: io.camunda.zeebe.engine.processing.bpmn.clock.ZeebeFeelEngineClock@561885e8, configuration: {externalFunctionsEnabled: false}] [zb-actors-7] INFO org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@5f2c72fa)), function-provider: io.camunda.zeebe.feel.impl.FeelFunctionProvider@3c48d200, clock: io.camunda.zeebe.engine.processing.bpmn.clock.ZeebeFeelEngineClock@62d78cdb, configuration: {externalFunctionsEnabled: false}] [zb-actors-7] INFO org.camunda.dmn.DmnEngine - DMN-Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@3395f936)), function-provider: org.camunda.feel.context.FunctionProvider$EmptyFunctionProvider$@59fb543a, audit-loggers: List(), configuration: Configuration(false,false,false)] [zb-actors-7] INFO org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(org.camunda.dmn.NoUnpackValueMapper@13839911)), function-provider: org.camunda.feel.context.FunctionProvider$EmptyFunctionProvider$@59fb543a, clock: SystemClock, configuration: {externalFunctionsEnabled: false}] [zb-actors-7] INFO io.camunda.zeebe.processor - Processor starts replay of events. [snapshot-position: -1, replay-mode: PROCESSING] [zb-actors-7] INFO io.camunda.zeebe.processor - Processor finished replay, with [lastProcessedPosition: -1, lastWrittenPosition: -1] [main] WARN io.camunda.zeebe.process.test.qa.abstracts.util.Utilities - Timeout reached while waiting for busy state after time increase java.util.concurrent.TimeoutException at java.base/java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1960) at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:2095) at io.camunda.zeebe.process.test.engine.InMemoryEngine.waitForBusyState(InMemoryEngine.java:149) at io.camunda.zeebe.process.test.qa.abstracts.util.Utilities.waitForBusyState(Utilities.java:122) at io.camunda.zeebe.process.test.qa.abstracts.util.Utilities.increaseTime(Utilities.java:207) at io.camunda.zeebe.process.test.qa.abstracts.jobs.AbstractTimerTest.shouldCompareTimersDueDatesCorrectlyForDifferentNowDates(AbstractTimerTest.java:80) at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103) at java.base/java.lang.reflect.Method.invoke(Method.java:580) at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:728) at org.junit.jupiter.engine.execution.MethodInvocation.proceed(MethodInvocation.java:60) at org.junit.jupiter.engine.execution.InvocationInterceptorChain$ValidatingInvocation.proceed(InvocationInterceptorChain.java:131) at org.junit.jupiter.engine.extension.TimeoutExtension.intercept(TimeoutExtension.java:156) at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestableMethod(TimeoutExtension.java:147) at org.junit.jupiter.engine.extension.TimeoutExtension.interceptTestTemplateMethod(TimeoutExtension.java:94) at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker$ReflectiveInterceptorCall.lambda$ofVoidMethod$0(InterceptingExecutableInvoker.java:103) at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.lambda$invoke$0(InterceptingExecutableInvoker.java:93) at org.junit.jupiter.engine.execution.InvocationInterceptorChain$InterceptedInvocation.proceed(InvocationInterceptorChain.java:106) at org.junit.jupiter.engine.execution.InvocationInterceptorChain.proceed(InvocationInterceptorChain.java:64) at org.junit.jupiter.engine.execution.InvocationInterceptorChain.chainAndInvoke(InvocationInterceptorChain.java:45) at org.junit.jupiter.engine.execution.InvocationInterceptorChain.invoke(InvocationInterceptorChain.java:37) at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:92) at org.junit.jupiter.engine.execution.InterceptingExecutableInvoker.invoke(InterceptingExecutableInvoker.java:86) at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.lambda$invokeTestMethod$7(TestMethodTestDescriptor.java:218) at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:214) at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:139) at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:69) at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:151) at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141) at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137) at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139) at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138) at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95) at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:35) at org.junit.platform.engine.support.hierarchical.NodeTestTask$DefaultDynamicTestExecutor.execute(NodeTestTask.java:226) at org.junit.platform.engine.support.hierarchical.NodeTestTask$DefaultDynamicTestExecutor.execute(NodeTestTask.java:204) at org.junit.jupiter.engine.descriptor.TestTemplateTestDescriptor.execute(TestTemplateTestDescriptor.java:142) at org.junit.jupiter.engine.descriptor.TestTemplateTestDescriptor.lambda$execute$2(TestTemplateTestDescriptor.java:110) at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:179) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.Streams$StreamBuilderImpl.forEachRemaining(Streams.java:411) at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:762) at java.base/java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:276) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:1024) at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509) at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499) at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151) at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174) at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596) at java.base/java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:276) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1708) at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509) at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499) at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151) at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174) at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596) at java.base/java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:276) at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1708) at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509) at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499) at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151) at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174) at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596) at org.junit.jupiter.engine.descriptor.TestTemplateTestDescriptor.execute(TestTemplateTestDescriptor.java:110) at org.junit.jupiter.engine.descriptor.TestTemplateTestDescriptor.execute(TestTemplateTestDescriptor.java:44) at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:151) at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141) at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137) at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139) at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138) at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95) at java.base/java.util.ArrayList.forEach(ArrayList.java:1596) at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41) at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155) at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141) at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137) at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139) at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138) at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95) at java.base/java.util.ArrayList.forEach(ArrayList.java:1596) at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.invokeAll(SameThreadHierarchicalTestExecutorService.java:41) at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$6(NodeTestTask.java:155) at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$8(NodeTestTask.java:141) at org.junit.platform.engine.support.hierarchical.Node.around(Node.java:137) at org.junit.platform.engine.support.hierarchical.NodeTestTask.lambda$executeRecursively$9(NodeTestTask.java:139) at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73) at org.junit.platform.engine.support.hierarchical.NodeTestTask.executeRecursively(NodeTestTask.java:138) at org.junit.platform.engine.support.hierarchical.NodeTestTask.execute(NodeTestTask.java:95) at org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService.submit(SameThreadHierarchicalTestExecutorService.java:35) at org.junit.platform.engine.support.hierarchical.HierarchicalTestExecutor.execute(HierarchicalTestExecutor.java:57) at org.junit.platform.engine.support.hierarchical.HierarchicalTestEngine.execute(HierarchicalTestEngine.java:54) at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:198) at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:169) at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:93) at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:58) at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:141) at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:57) at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:103) at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:85) at org.junit.platform.launcher.core.DelegatingLauncher.execute(DelegatingLauncher.java:47) at org.junit.platform.launcher.core.SessionPerRequestLauncher.execute(SessionPerRequestLauncher.java:63) at com.intellij.junit5.JUnit5IdeaTestRunner.startRunnerWithArgs(JUnit5IdeaTestRunner.java:57) at com.intellij.rt.junit.IdeaTestRunner$Repeater$1.execute(IdeaTestRunner.java:38) at com.intellij.rt.execution.junit.TestsRepeater.repeat(TestsRepeater.java:11) at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:35) at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:232) at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:55) [main] INFO io.camunda.zeebe.logstreams - Closing null with 2 readers [main] ERROR io.camunda.zeebe.process.test.extension.ZeebeProcessTestExtension - ===== Test failed! [main] INFO io.camunda.zeebe.process.test.filters.logger.IncidentLogger - [main] INFO io.camunda.zeebe.process.test.filters.logger.RecordStreamLogger - The following records have been recorded during this test: | COMMAND DEPLOYMENT CREATE | (Processes: [test_timer_events.bpmn]) | EVENT PROCESS CREATED | (Process: test_timer_events.bpmn) | EVENT DEPLOYMENT CREATED | | COMMAND PROCESS_INSTANCE_CREATION CREATE | (Process id: Process_Timer_Test_01), (default start) | COMMAND PROCESS_INSTANCE ACTIVATE_ELEMENT | (Element id: Process_Timer_Test_01), (Element type: PROCESS), (Event type: UNSPECIFIED), (Process id: Process_Timer_Test_01) | EVENT PROCESS_INSTANCE_CREATION CREATED | (Process id: Process_Timer_Test_01), (default start) | EVENT PROCESS_INSTANCE ELEMENT_ACTIVATING | (Element id: Process_Timer_Test_01), (Element type: PROCESS), (Event type: UNSPECIFIED), (Process id: Process_Timer_Test_01) | EVENT PROCESS_INSTANCE ELEMENT_ACTIVATED | (Element id: Process_Timer_Test_01), (Element type: PROCESS), (Event type: UNSPECIFIED), (Process id: Process_Timer_Test_01) | COMMAND PROCESS_INSTANCE ACTIVATE_ELEMENT | (Element id: StartEvent_Main), (Element type: START_EVENT), (Event type: NONE), (Process id: Process_Timer_Test_01) | EVENT PROCESS_INSTANCE ELEMENT_ACTIVATING | (Element id: StartEvent_Main), (Element type: START_EVENT), (Event type: NONE), (Process id: Process_Timer_Test_01) | EVENT PROCESS_INSTANCE ELEMENT_ACTIVATED | (Element id: StartEvent_Main), (Element type: START_EVENT), (Event type: NONE), (Process id: Process_Timer_Test_01) | COMMAND PROCESS_INSTANCE COMPLETE_ELEMENT | (Element id: StartEvent_Main), (Element type: START_EVENT), (Event type: NONE), (Process id: Process_Timer_Test_01) | EVENT PROCESS_INSTANCE ELEMENT_COMPLETING | (Element id: StartEvent_Main), (Element type: START_EVENT), (Event type: NONE), (Process id: Process_Timer_Test_01) | EVENT PROCESS_INSTANCE ELEMENT_COMPLETED | (Element id: StartEvent_Main), (Element type: START_EVENT), (Event type: NONE), (Process id: Process_Timer_Test_01) | EVENT PROCESS_INSTANCE SEQUENCE_FLOW_TAKEN | (Element id: Flow_0yjny2b), (Element type: SEQUENCE_FLOW), (Event type: UNSPECIFIED), (Process id: Process_Timer_Test_01) | COMMAND PROCESS_INSTANCE ACTIVATE_ELEMENT | (Element id: Gateway_SplitParallel), (Element type: PARALLEL_GATEWAY), (Event type: UNSPECIFIED), (Process id: Process_Timer_Test_01) | EVENT PROCESS_INSTANCE ELEMENT_ACTIVATING | (Element id: Gateway_SplitParallel), (Element type: PARALLEL_GATEWAY), (Event type: UNSPECIFIED), (Process id: Process_Timer_Test_01) | EVENT PROCESS_INSTANCE ELEMENT_ACTIVATED | (Element id: Gateway_SplitParallel), (Element type: PARALLEL_GATEWAY), (Event type: UNSPECIFIED), (Process id: Process_Timer_Test_01) | EVENT PROCESS_INSTANCE ELEMENT_COMPLETING | (Element id: Gateway_SplitParallel), (Element type: PARALLEL_GATEWAY), (Event type: UNSPECIFIED), (Process id: Process_Timer_Test_01) | EVENT PROCESS_INSTANCE ELEMENT_COMPLETED | (Element id: Gateway_SplitParallel), (Element type: PARALLEL_GATEWAY), (Event type: UNSPECIFIED), (Process id: Process_Timer_Test_01) | EVENT PROCESS_INSTANCE SEQUENCE_FLOW_TAKEN | (Element id: Flow_0f4xha0), (Element type: SEQUENCE_FLOW), (Event type: UNSPECIFIED), (Process id: Process_Timer_Test_01) | COMMAND PROCESS_INSTANCE ACTIVATE_ELEMENT | (Element id: Activity_InvokeDummyWorker), (Element type: SERVICE_TASK), (Event type: UNSPECIFIED), (Process id: Process_Timer_Test_01) | EVENT PROCESS_INSTANCE SEQUENCE_FLOW_TAKEN | (Element id: Flow_13nx8ki), (Element type: SEQUENCE_FLOW), (Event type: UNSPECIFIED), (Process id: Process_Timer_Test_01) | COMMAND PROCESS_INSTANCE ACTIVATE_ELEMENT | (Element id: TimerEvent_Wait30d), (Element type: INTERMEDIATE_CATCH_EVENT), (Event type: TIMER), (Process id: Process_Timer_Test_01) | EVENT PROCESS_INSTANCE ELEMENT_ACTIVATING | (Element id: Activity_InvokeDummyWorker), (Element type: SERVICE_TASK), (Event type: UNSPECIFIED), (Process id: Process_Timer_Test_01) | EVENT JOB CREATED | (Element id: Activity_InvokeDummyWorker), (Job type: SimpleLog01) | EVENT PROCESS_INSTANCE ELEMENT_ACTIVATED | (Element id: Activity_InvokeDummyWorker), (Element type: SERVICE_TASK), (Event type: UNSPECIFIED), (Process id: Process_Timer_Test_01) | EVENT PROCESS_INSTANCE ELEMENT_ACTIVATING | (Element id: TimerEvent_Wait30d), (Element type: INTERMEDIATE_CATCH_EVENT), (Event type: TIMER), (Process id: Process_Timer_Test_01) | EVENT TIMER CREATED | (Element id: TimerEvent_Wait30d), (Due date: Wed Jan 31 00:00:00 EET 2024) | EVENT PROCESS_INSTANCE ELEMENT_ACTIVATED | (Element id: TimerEvent_Wait30d), (Element type: INTERMEDIATE_CATCH_EVENT), (Event type: TIMER), (Process id: Process_Timer_Test_01) | COMMAND JOB_BATCH ACTIVATE | (Worker: default), (Job type: SimpleLog01) | EVENT JOB_BATCH ACTIVATED | (Worker: default), (Job type: SimpleLog01) | COMMAND JOB COMPLETE | | EVENT JOB COMPLETED | (Element id: Activity_InvokeDummyWorker), (Job type: SimpleLog01) | EVENT PROCESS_EVENT TRIGGERING | (Target element id: Activity_InvokeDummyWorker), | COMMAND PROCESS_INSTANCE COMPLETE_ELEMENT | (Element id: Activity_InvokeDummyWorker), (Element type: SERVICE_TASK), (Event type: UNSPECIFIED), (Process id: Process_Timer_Test_01) | EVENT PROCESS_INSTANCE ELEMENT_COMPLETING | (Element id: Activity_InvokeDummyWorker), (Element type: SERVICE_TASK), (Event type: UNSPECIFIED), (Process id: Process_Timer_Test_01) | EVENT PROCESS_EVENT TRIGGERED | (Target element id: Activity_InvokeDummyWorker), | EVENT PROCESS_INSTANCE ELEMENT_COMPLETED | (Element id: Activity_InvokeDummyWorker), (Element type: SERVICE_TASK), (Event type: UNSPECIFIED), (Process id: Process_Timer_Test_01) | EVENT PROCESS_INSTANCE SEQUENCE_FLOW_TAKEN | (Element id: Flow_1avqbu0), (Element type: SEQUENCE_FLOW), (Event type: UNSPECIFIED), (Process id: Process_Timer_Test_01) | COMMAND PROCESS_INSTANCE ACTIVATE_ELEMENT | (Element id: TimerEvent_Wait1s), (Element type: INTERMEDIATE_CATCH_EVENT), (Event type: TIMER), (Process id: Process_Timer_Test_01) | EVENT PROCESS_INSTANCE ELEMENT_ACTIVATING | (Element id: TimerEvent_Wait1s), (Element type: INTERMEDIATE_CATCH_EVENT), (Event type: TIMER), (Process id: Process_Timer_Test_01) | EVENT TIMER CREATED | (Element id: TimerEvent_Wait1s), (Due date: Mon Jan 01 00:00:01 EET 2024) | EVENT PROCESS_INSTANCE ELEMENT_ACTIVATED | (Element id: TimerEvent_Wait1s), (Element type: INTERMEDIATE_CATCH_EVENT), (Event type: TIMER), (Process id: Process_Timer_Test_01) org.awaitility.core.ConditionTimeoutException: Assertion condition Expecting Optional to contain a value but it was empty within 10 seconds. at org.awaitility.core.ConditionAwaiter.await(ConditionAwaiter.java:167) at org.awaitility.core.AssertionCondition.await(AssertionCondition.java:119) at org.awaitility.core.AssertionCondition.await(AssertionCondition.java:31) at org.awaitility.core.ConditionFactory.until(ConditionFactory.java:985) at org.awaitility.core.ConditionFactory.untilAsserted(ConditionFactory.java:769) at io.camunda.zeebe.process.test.qa.abstracts.jobs.AbstractTimerTest.waitForProcessInstanceCompleted(AbstractTimerTest.java:95) at io.camunda.zeebe.process.test.qa.abstracts.jobs.AbstractTimerTest.shouldCompareTimersDueDatesCorrectlyForDifferentNowDates(AbstractTimerTest.java:89) at java.base/java.lang.reflect.Method.invoke(Method.java:580) at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.ReferencePipeline$2$1.accept(ReferencePipeline.java:179) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.accept(ForEachOps.java:184) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.Streams$StreamBuilderImpl.forEachRemaining(Streams.java:411) at java.base/java.util.stream.ReferencePipeline$Head.forEach(ReferencePipeline.java:762) at java.base/java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:276) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:1024) at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509) at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499) at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151) at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174) at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596) at java.base/java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:276) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:197) at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1708) at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509) at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499) at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151) at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174) at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596) at java.base/java.util.stream.ReferencePipeline$7$1.accept(ReferencePipeline.java:276) at java.base/java.util.ArrayList$ArrayListSpliterator.forEachRemaining(ArrayList.java:1708) at java.base/java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:509) at java.base/java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:499) at java.base/java.util.stream.ForEachOps$ForEachOp.evaluateSequential(ForEachOps.java:151) at java.base/java.util.stream.ForEachOps$ForEachOp$OfRef.evaluateSequential(ForEachOps.java:174) at java.base/java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234) at java.base/java.util.stream.ReferencePipeline.forEach(ReferencePipeline.java:596) at java.base/java.util.ArrayList.forEach(ArrayList.java:1596) at java.base/java.util.ArrayList.forEach(ArrayList.java:1596) Caused by: java.lang.AssertionError: Expecting Optional to contain a value but it was empty. at io.camunda.zeebe.process.test.qa.abstracts.jobs.AbstractTimerTest.lambda$waitForProcessInstanceCompleted$3(AbstractTimerTest.java:108) at org.awaitility.core.AssertionCondition.lambda$new$0(AssertionCondition.java:53) at org.awaitility.core.ConditionAwaiter$ConditionPoller.call(ConditionAwaiter.java:248) at org.awaitility.core.ConditionAwaiter$ConditionPoller.call(ConditionAwaiter.java:235) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) at java.base/java.lang.Thread.run(Thread.java:1583) ```
mustafadagher commented 2 weeks ago

ZPA Triage:

remcowesterhoud commented 2 weeks ago

When we have a fix we should merge it together with #1231 to have a succeeding CI

megglos commented 2 weeks ago

@koevskinikola are you on that already? we want to build RC1 today for the release.

koevskinikola commented 2 weeks ago

I'm looking into this right now.

lenaschoenburg commented 2 weeks ago

@koevskinikola asked me to look into this urgently because it's a release blocker for today and he suspected that the recent controllable clock changes may be the root cause.

Indeed, if we add a debug log to ProcessingScheduleServiceImpl#processScheduledTasks, we can observe the following:

Checking scheduled tasks at 2024-08-27T10:47:23.231Z
Checking scheduled tasks at 2024-08-27T10:47:23.231Z
Checking scheduled tasks at 2024-08-27T10:47:23.251Z
Checking scheduled tasks at 2024-08-27T10:47:23.260Z
Checking scheduled tasks at 2024-08-27T10:47:24.221Z
Checking scheduled tasks at 2024-08-27T10:47:28.069Z
Checking scheduled tasks at 2024-08-27T10:47:28.069Z

These are from before the test travels backwards in time to 2023. Afterwards, we see that the schedule service is not called again. This is a bug in Zeebe where traveling backwards in time prevents further calls to the schedule service, thus never triggering tasks scheduled by the engine.

As a workaround, you can change the tests to instead travel forwards in time but this still needs to be fixed properly in Zeebe.

koevskinikola commented 2 weeks ago

PR #1232 introduces only a temporary fix to this issue, so I decided not to close the issue with it.

I'll create a separate camunda/camunda issue to improve the scheduling service in Zeebe properly.

lenaschoenburg commented 2 weeks ago

@koevskinikola did you get a chance to create the issue in camunda/camunda? I don't see it linked here.

koevskinikola commented 2 weeks ago

@lenaschoenburg I didn't. I'm writing in right now.

koevskinikola commented 2 weeks ago

Note: The workaround from PR #1232 seems to only fix the embedded engine test. However, the containerized engine test (i.e. Testcontainers-based) continues to fail. It's still not clear why, but the engine implementations for these two tests are different, InMemoryEngine for the former, and ContainerizedEngine for the latter.

PR #1233 disables the AbstractTimerTest test cases to unblock the 8.6.0-alpha5 release.

koevskinikola commented 2 weeks ago

@lenaschoenburg here is the Zeebe issue related to this one:

https://github.com/camunda/camunda/issues/21738

I used the explanation you provided here to flesh out the description.

megglos commented 5 days ago

ZPA Planning: