Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

TimerTest started to fail consistently #1230

Open
ana-vinogradova-camunda opened this issue Aug 23, 2024 · 11 comments
Open

TimerTest started to fail consistently #1230

ana-vinogradova-camunda opened this issue Aug 23, 2024 · 11 comments
Labels
kind/bug Categorizes issue or PR as related to a bug.

Comments

@ana-vinogradova-camunda
Copy link
Contributor

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)
@ana-vinogradova-camunda ana-vinogradova-camunda added kind/feature Categorizes an issue or PR as a feature, i.e. new behavior kind/bug Categorizes issue or PR as related to a bug. and removed kind/feature Categorizes an issue or PR as a feature, i.e. new behavior labels Aug 23, 2024
@mustafadagher
Copy link

ZPA Triage:

  • Need to resolve it ASAP because it will block release (next week)
  • It might be related to the clock changes by @camunda/zeebe-distributed-platform , but can't be proven.
  • @koevskinikola will follow up with @lenaschoenburg

@remcowesterhoud
Copy link
Contributor

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

@megglos
Copy link
Contributor

megglos commented Aug 27, 2024

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

@koevskinikola
Copy link
Member

I'm looking into this right now.

@lenaschoenburg
Copy link
Member

@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
Copy link
Member

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
Copy link
Member

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

@koevskinikola
Copy link
Member

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

@koevskinikola
Copy link
Member

koevskinikola commented Aug 29, 2024

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
Copy link
Member

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

camunda/camunda#21738

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

@megglos
Copy link
Contributor

megglos commented Sep 9, 2024

ZPA Planning:

  • no time for it this iteration
  • the test sets dates to specific dates (in the past) which is not something we consider a usual use case => not high prio

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
kind/bug Categorizes issue or PR as related to a bug.
Projects
None yet
Development

No branches or pull requests

6 participants