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.

Sign up for GitHub

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

Jump to bottom

Flaky TimerStartEventTest (multiple cases) #10272

Closed
korthout opened this issue Sep 5, 2022 · 17 comments · Fixed by #10867 or #11033
Closed

Flaky TimerStartEventTest (multiple cases) #10272

korthout opened this issue Sep 5, 2022 · 17 comments · Fixed by #10867 or #11033
Assignees
@korthout @saig0 @remcowesterhoud
Labels
kind/flake Categorizes issue or PR as related to a flaky test version:8.1.4 Marks an issue as being completely or in parts released in 8.1.4 version:8.2.0-alpha2 Marks an issue as being completely or in parts released in 8.2.0-alpha2 version:8.2.0 Marks an issue as being completely or in parts released in 8.2.0

Comments

@korthout
Copy link
Member

korthout commented Sep 5, 2022 •
edited by saig0
Loading

Summary

Try to answer the following as best as possible

  • How often does the test fail? Multiple times a week
  • Does it block your work? yes, CI is failing
  • Do we suspect that it is a real failure? No

Failures

Outline known failure cases, e.g. a failed assertion and its stacktrace obtained from Jenkins

Example assertion failure 
io.camunda.zeebe.test.util.stream.StreamWrapperException: No event found matching the criteria
	at java.base/java.util.Optional.orElseThrow(Optional.java:403)
	at io.camunda.zeebe.test.util.stream.StreamWrapper.getFirst(StreamWrapper.java:77)
	at io.camunda.zeebe.engine.processing.timer.TimerStartEventTest.shouldTriggerAtSpecifiedTimeDate(TimerStartEventTest.java:806)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
	at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:61)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
	at org.junit.vintage.engine.execution.RunnerExecutor.execute(RunnerExecutor.java:42)
	at org.junit.vintage.engine.VintageTestEngine.executeAllChildren(VintageTestEngine.java:80)
	at org.junit.vintage.engine.VintageTestEngine.execute(VintageTestEngine.java:72)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:147)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:127)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:90)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:55)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:102)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:54)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:114)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:86)
	at org.junit.platform.launcher.core.DefaultLauncherSession$DelegatingLauncher.execute(DefaultLauncherSession.java:86)
	at org.apache.maven.surefire.junitplatform.LazyLauncher.execute(LazyLauncher.java:55)
	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.lambda$execute$1(JUnitPlatformProvider.java:234)
	at java.base/java.util.Iterator.forEachRemaining(Iterator.java:133)
	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.execute(JUnitPlatformProvider.java:228)
	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invokeAllTests(JUnitPlatformProvider.java:175)
	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invoke(JUnitPlatformProvider.java:131)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:456)
	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:169)
	at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:595)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:581)

Hypotheses

List any hypotheses if you have one; can be omitted

Logs

If possible, provide more context here, e.g. standard output logs, link to build, etc.

Logs 
[2022-09-05T12:36:18.344Z] [INFO] Running io.camunda.zeebe.engine.processing.timer.TimerStartEventTest
[2022-09-05T12:36:19.723Z] [INFO] Tests run: 44, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.525 s - in io.camunda.zeebe.engine.processing.message.MessageCatchElementTest
[2022-09-05T12:36:19.723Z] [INFO] Running io.camunda.zeebe.engine.processing.timer.ConcurrentTimerEventTest
[2022-09-05T12:36:20.292Z] [INFO] Tests run: 9, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.69 s - in io.camunda.zeebe.engine.processing.message.MessageStartEventSubscriptionTest
[2022-09-05T12:36:20.292Z] [INFO] Running io.camunda.zeebe.engine.processing.timer.TimerCatchEventTest
[2022-09-05T12:36:20.860Z] [INFO] Tests run: 4, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.098 s - in io.camunda.zeebe.engine.processing.timer.ConcurrentTimerEventTest
[2022-09-05T12:36:20.860Z] [INFO] Running io.camunda.zeebe.engine.processing.timer.DueDateTimerCheckerTest
[2022-09-05T12:36:20.860Z] [INFO] Running io.camunda.zeebe.engine.processing.timer.DueDateTimerCheckerTest$YieldingDecoratorTest
[2022-09-05T12:36:21.121Z] [INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.287 s - in io.camunda.zeebe.engine.processing.timer.DueDateTimerCheckerTest$YieldingDecoratorTest
[2022-09-05T12:36:21.121Z] [INFO] Running io.camunda.zeebe.engine.processing.timer.DueDateTimerCheckerTest$TriggerTimersSideEffectTest
[2022-09-05T12:36:21.692Z] [INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.34 s - in io.camunda.zeebe.engine.processing.timer.DueDateTimerCheckerTest$TriggerTimersSideEffectTest
[2022-09-05T12:36:21.692Z] [INFO] Tests run: 0, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.63 s - in io.camunda.zeebe.engine.processing.timer.DueDateTimerCheckerTest
[2022-09-05T12:36:21.692Z] [INFO] Running io.camunda.zeebe.engine.processing.timer.CronTimerTest
[2022-09-05T12:36:21.692Z] [INFO] Tests run: 17, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.247 s - in io.camunda.zeebe.engine.processing.timer.CronTimerTest
[2022-09-05T12:36:21.692Z] [INFO] Running io.camunda.zeebe.engine.processing.processinstance.CancelProcessInstanceTest
[2022-09-05T12:36:21.952Z] [INFO] Tests run: 24, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 8.201 s - in io.camunda.zeebe.engine.processing.message.MessageCorrelationTest
[2022-09-05T12:36:21.952Z] [INFO] Running io.camunda.zeebe.engine.processing.processinstance.ModifyProcessInstanceTerminationTest
[2022-09-05T12:36:21.952Z] [INFO] Tests run: 6, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 16.15 s - in io.camunda.zeebe.engine.processing.bpmn.gateway.InclusiveGatewayTest
[2022-09-05T12:36:21.952Z] [INFO] Running io.camunda.zeebe.engine.processing.processinstance.ProcessInstanceCommandRejectionTest
[2022-09-05T12:36:22.225Z] [INFO] Tests run: 15, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.838 s - in io.camunda.zeebe.engine.processing.timer.TimerCatchEventTest
[2022-09-05T12:36:22.225Z] [INFO] Running io.camunda.zeebe.engine.processing.processinstance.CreateProcessInstanceWithResultTest
[2022-09-05T12:36:22.795Z] [INFO] Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.6 s - in io.camunda.zeebe.engine.processing.processinstance.CreateProcessInstanceWithResultTest
[2022-09-05T12:36:22.795Z] [INFO] Running io.camunda.zeebe.engine.processing.processinstance.CreateProcessInstanceAnywhereTest
[2022-09-05T12:36:22.795Z] [INFO] Tests run: 12, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.919 s - in io.camunda.zeebe.engine.processing.processinstance.CancelProcessInstanceTest
[2022-09-05T12:36:22.795Z] [INFO] Running io.camunda.zeebe.engine.processing.processinstance.CreateProcessInstanceRejectionTest
[2022-09-05T12:36:23.055Z] [INFO] Tests run: 12, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.147 s - in io.camunda.zeebe.engine.processing.processinstance.ModifyProcessInstanceTerminationTest
[2022-09-05T12:36:23.055Z] [INFO] Running io.camunda.zeebe.engine.processing.processinstance.CreateProcessInstanceTest
[2022-09-05T12:36:23.623Z] [INFO] Tests run: 23, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 7.458 s - in io.camunda.zeebe.engine.processing.message.MessageStartEventTest
[2022-09-05T12:36:23.623Z] [INFO] Running io.camunda.zeebe.engine.processing.processinstance.CancelProcessInstanceConcurrentlyTest
[2022-09-05T12:36:23.623Z] [INFO] Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.428 s - in io.camunda.zeebe.engine.processing.processinstance.CreateProcessInstanceTest
[2022-09-05T12:36:23.623Z] [INFO] Running io.camunda.zeebe.engine.processing.processinstance.ModifyProcessInstanceRejectionTest
[2022-09-05T12:36:23.623Z] [INFO] Tests run: 13, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.894 s - in io.camunda.zeebe.engine.processing.processinstance.CreateProcessInstanceAnywhereTest
[2022-09-05T12:36:23.623Z] [INFO] Running io.camunda.zeebe.engine.processing.processinstance.ModifyProcessInstanceUnsupportedElementsTest
[2022-09-05T12:36:23.883Z] [INFO] Tests run: 4, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.092 s - in io.camunda.zeebe.engine.processing.processinstance.CreateProcessInstanceRejectionTest
[2022-09-05T12:36:23.883Z] [INFO] Running io.camunda.zeebe.engine.processing.processinstance.CreateProcessInstanceUnsupportedElementTypeTest
[2022-09-05T12:36:24.143Z] [INFO] Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.534 s - in io.camunda.zeebe.engine.processing.processinstance.ModifyProcessInstanceRejectionTest
[2022-09-05T12:36:24.143Z] [INFO] Tests run: 6, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.413 s - in io.camunda.zeebe.engine.processing.processinstance.ModifyProcessInstanceUnsupportedElementsTest
[2022-09-05T12:36:24.143Z] [INFO] Running io.camunda.zeebe.engine.processing.processinstance.ProcessInstanceTokenTest
[2022-09-05T12:36:24.143Z] [INFO] Running io.camunda.zeebe.engine.processing.processinstance.ModifyProcessInstanceVariablesTest
[2022-09-05T12:36:24.713Z] [INFO] Tests run: 8, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.613 s - in io.camunda.zeebe.engine.processing.processinstance.ModifyProcessInstanceVariablesTest
[2022-09-05T12:36:24.713Z] [INFO] Running io.camunda.zeebe.engine.processing.processinstance.ModifyProcessInstanceTest
[2022-09-05T12:36:24.972Z] [INFO] Tests run: 4, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.137 s - in io.camunda.zeebe.engine.processing.processinstance.CreateProcessInstanceUnsupportedElementTypeTest
[2022-09-05T12:36:24.972Z] [INFO] Running io.camunda.zeebe.engine.processing.processinstance.CreateProcessInstanceSupportedElementTest
[2022-09-05T12:36:25.232Z] [INFO] Tests run: 14, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.152 s - in io.camunda.zeebe.engine.processing.processinstance.ProcessInstanceTokenTest
[2022-09-05T12:36:25.232Z] [INFO] Running io.camunda.zeebe.engine.state.variable.VariableStateTest
[2022-09-05T12:36:25.491Z] [INFO] Tests run: 11, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.859 s - in io.camunda.zeebe.engine.processing.processinstance.ModifyProcessInstanceTest
[2022-09-05T12:36:25.491Z] [INFO] Running io.camunda.zeebe.engine.state.variable.IndexedDocumentTest
[2022-09-05T12:36:25.750Z] [INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.013 s - in io.camunda.zeebe.engine.state.variable.IndexedDocumentTest
[2022-09-05T12:36:25.750Z] [INFO] Running io.camunda.zeebe.engine.state.deployment.DeploymentStateTest
[2022-09-05T12:36:25.750Z] [INFO] Tests run: 20, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.413 s - in io.camunda.zeebe.engine.state.variable.VariableStateTest
[2022-09-05T12:36:25.750Z] [INFO] Running io.camunda.zeebe.engine.state.deployment.ProcessStateTest
[2022-09-05T12:36:25.750Z] [INFO] Tests run: 17, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.714 s - in io.camunda.zeebe.engine.processing.processinstance.CreateProcessInstanceSupportedElementTest
[2022-09-05T12:36:25.750Z] [INFO] Running io.camunda.zeebe.engine.state.deployment.DecisionStateTest
[2022-09-05T12:36:26.318Z] [INFO] Tests run: 14, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 4.288 s - in io.camunda.zeebe.engine.processing.processinstance.ProcessInstanceCommandRejectionTest
[2022-09-05T12:36:26.318Z] [INFO] Running io.camunda.zeebe.engine.state.query.StateQueryServiceTest
[2022-09-05T12:36:26.885Z] [INFO] Running io.camunda.zeebe.engine.state.query.StateQueryServiceTest$GetBpmnProcessIdForJob
[2022-09-05T12:36:26.885Z] [INFO] Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.232 s - in io.camunda.zeebe.engine.state.query.StateQueryServiceTest$GetBpmnProcessIdForJob
[2022-09-05T12:36:26.885Z] [INFO] Running io.camunda.zeebe.engine.state.query.StateQueryServiceTest$GetBpmnProcessIdForProcessInstance
[2022-09-05T12:36:27.145Z] [INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.237 s - in io.camunda.zeebe.engine.state.query.StateQueryServiceTest$GetBpmnProcessIdForProcessInstance
[2022-09-05T12:36:27.145Z] [INFO] Running io.camunda.zeebe.engine.state.query.StateQueryServiceTest$GetBpmnProcessIdForProcess
[2022-09-05T12:36:27.145Z] [INFO] Tests run: 12, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.47 s - in io.camunda.zeebe.engine.state.deployment.DecisionStateTest
[2022-09-05T12:36:27.404Z] [INFO] Running io.camunda.zeebe.engine.state.ProcessExecutionCleanStateTest
[2022-09-05T12:36:27.404Z] [INFO] Tests run: 13, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.721 s - in io.camunda.zeebe.engine.state.deployment.DeploymentStateTest
[2022-09-05T12:36:27.404Z] [INFO] Running io.camunda.zeebe.engine.state.migration.DbMigratorImplTest
[2022-09-05T12:36:27.404Z] [INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.256 s - in io.camunda.zeebe.engine.state.query.StateQueryServiceTest$GetBpmnProcessIdForProcess
[2022-09-05T12:36:27.404Z] [INFO] Tests run: 0, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.113 s - in io.camunda.zeebe.engine.state.query.StateQueryServiceTest
[2022-09-05T12:36:27.404Z] [INFO] Running io.camunda.zeebe.engine.state.migration.to_1_3.TemporaryVariableMigrationTest
[2022-09-05T12:36:27.404Z] [INFO] Running io.camunda.zeebe.engine.state.migration.to_1_3.TemporaryVariableMigrationTest$BlackboxTest
[2022-09-05T12:36:27.663Z] [INFO] Tests run: 5, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.248 s - in io.camunda.zeebe.engine.state.migration.DbMigratorImplTest
[2022-09-05T12:36:27.663Z] [INFO] Running io.camunda.zeebe.engine.state.migration.DbMigrationControllerTest
[2022-09-05T12:36:27.663Z] [WARNING] Tests run: 12, Failures: 0, Errors: 0, Skipped: 2, Time elapsed: 85.098 s - in io.atomix.raft.zeebe.ZeebeTest
[2022-09-05T12:36:27.923Z] [INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.225 s - in io.camunda.zeebe.engine.state.migration.DbMigrationControllerTest
[2022-09-05T12:36:27.923Z] [INFO] Running io.camunda.zeebe.engine.state.migration.to_1_1.MessageSubscriptionSentTimeMigrationTest
[2022-09-05T12:36:27.923Z] [INFO] Running io.camunda.zeebe.engine.state.migration.to_1_1.MessageSubscriptionSentTimeMigrationTest$BlackboxTest
[2022-09-05T12:36:27.923Z] [INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.369 s - in io.camunda.zeebe.engine.state.migration.to_1_3.TemporaryVariableMigrationTest$BlackboxTest
[2022-09-05T12:36:27.923Z] [INFO] Running io.camunda.zeebe.engine.state.migration.to_1_3.TemporaryVariableMigrationTest$MockBasedTests
[2022-09-05T12:36:28.183Z] [INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.307 s - in io.camunda.zeebe.engine.state.migration.to_1_1.MessageSubscriptionSentTimeMigrationTest$BlackboxTest
[2022-09-05T12:36:28.183Z] [INFO] Running io.camunda.zeebe.engine.state.migration.to_1_1.MessageSubscriptionSentTimeMigrationTest$MockBasedTests
[2022-09-05T12:36:28.183Z] [INFO] Tests run: 16, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 4.74 s - in io.camunda.zeebe.engine.processing.processinstance.CancelProcessInstanceConcurrentlyTest
[2022-09-05T12:36:28.183Z] [INFO] Running io.camunda.zeebe.engine.state.migration.to_1_1.ProcessMessageSubscriptionSentTimeMigrationTest
[2022-09-05T12:36:28.183Z] [INFO] Running io.camunda.zeebe.engine.state.migration.to_1_1.ProcessMessageSubscriptionSentTimeMigrationTest$BlackboxTest
[2022-09-05T12:36:28.442Z] [INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.479 s - in io.camunda.zeebe.engine.state.migration.to_1_3.TemporaryVariableMigrationTest$MockBasedTests
[2022-09-05T12:36:28.442Z] [INFO] Tests run: 0, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.852 s - in io.camunda.zeebe.engine.state.migration.to_1_3.TemporaryVariableMigrationTest
[2022-09-05T12:36:28.442Z] [INFO] Running io.camunda.zeebe.engine.state.migration.to_1_1.DbMigrationStateTest
[2022-09-05T12:36:28.442Z] [INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.277 s - in io.camunda.zeebe.engine.state.migration.to_1_1.MessageSubscriptionSentTimeMigrationTest$MockBasedTests
[2022-09-05T12:36:28.442Z] [INFO] Tests run: 0, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.589 s - in io.camunda.zeebe.engine.state.migration.to_1_1.MessageSubscriptionSentTimeMigrationTest
[2022-09-05T12:36:28.442Z] [INFO] Running io.camunda.zeebe.engine.state.message.PendingMessageSubscriptionStateTest
[2022-09-05T12:36:28.701Z] [INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.31 s - in io.camunda.zeebe.engine.state.migration.to_1_1.ProcessMessageSubscriptionSentTimeMigrationTest$BlackboxTest
[2022-09-05T12:36:28.701Z] [INFO] Running io.camunda.zeebe.engine.state.migration.to_1_1.ProcessMessageSubscriptionSentTimeMigrationTest$MockBasedTests
[2022-09-05T12:36:28.701Z] [INFO] Tests run: 2, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.247 s - in io.camunda.zeebe.engine.state.migration.to_1_1.DbMigrationStateTest
[2022-09-05T12:36:28.701Z] [INFO] Running io.camunda.zeebe.engine.state.message.MessageStateTest
[2022-09-05T12:36:28.960Z] [INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.459 s - in io.camunda.zeebe.engine.state.migration.to_1_1.ProcessMessageSubscriptionSentTimeMigrationTest$MockBasedTests
[2022-09-05T12:36:28.960Z] [INFO] Tests run: 0, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.772 s - in io.camunda.zeebe.engine.state.migration.to_1_1.ProcessMessageSubscriptionSentTimeMigrationTest
[2022-09-05T12:36:28.960Z] [INFO] Running io.camunda.zeebe.engine.state.message.PendingProcessMessageSubscriptionStateTest
[2022-09-05T12:36:28.960Z] [INFO] Tests run: 25, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 3.375 s - in io.camunda.zeebe.engine.state.deployment.ProcessStateTest
[2022-09-05T12:36:28.960Z] [INFO] Running io.camunda.zeebe.engine.state.message.TransientSubscriptionCommandStateTest
[2022-09-05T12:36:29.219Z] [INFO] Tests run: 9, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.013 s - in io.camunda.zeebe.engine.state.message.TransientSubscriptionCommandStateTest
[2022-09-05T12:36:29.219Z] [INFO] Running io.camunda.zeebe.engine.state.message.MessageSubscriptionStateTest
[2022-09-05T12:36:29.477Z] [INFO] Tests run: 7, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.852 s - in io.camunda.zeebe.engine.state.message.PendingMessageSubscriptionStateTest
[2022-09-05T12:36:29.477Z] [INFO] Running io.camunda.zeebe.engine.state.message.ProcessMessageSubscriptionStateTest
[2022-09-05T12:36:29.735Z] [INFO] Tests run: 7, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.782 s - in io.camunda.zeebe.engine.state.message.PendingProcessMessageSubscriptionStateTest
[2022-09-05T12:36:29.735Z] [INFO] Running io.camunda.zeebe.engine.state.message.MessageStartEventSubscriptionStateTest
[2022-09-05T12:36:29.994Z] [INFO] Tests run: 8, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.962 s - in io.camunda.zeebe.engine.state.message.MessageSubscriptionStateTest
[2022-09-05T12:36:29.994Z] [INFO] Running io.camunda.zeebe.engine.state.KeyGeneratorTest
[2022-09-05T12:36:30.253Z] [INFO] Tests run: 7, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.818 s - in io.camunda.zeebe.engine.state.message.ProcessMessageSubscriptionStateTest
[2022-09-05T12:36:30.253Z] [INFO] Running io.camunda.zeebe.engine.state.instance.JobStateTest
[2022-09-05T12:36:30.513Z] [INFO] Tests run: 3, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.477 s - in io.camunda.zeebe.engine.state.KeyGeneratorTest
[2022-09-05T12:36:30.513Z] [INFO] Running io.camunda.zeebe.engine.state.instance.ElementInstanceStateTest
[2022-09-05T12:36:30.772Z] [INFO] Tests run: 8, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.929 s - in io.camunda.zeebe.engine.state.message.MessageStartEventSubscriptionStateTest
[2022-09-05T12:36:30.772Z] [INFO] Running io.camunda.zeebe.engine.state.instance.IncidentStateTest
[2022-09-05T12:36:31.030Z] [ERROR] Tests run: 22, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 12.826 s <<< FAILURE! - in io.camunda.zeebe.engine.processing.timer.TimerStartEventTest
[2022-09-05T12:36:31.030Z] [ERROR] io.camunda.zeebe.engine.processing.timer.TimerStartEventTest.shouldTriggerAtSpecifiedTimeDate  Time elapsed: 5.255 s  <<< ERROR!
[2022-09-05T12:36:31.031Z] io.camunda.zeebe.test.util.stream.StreamWrapperException: No event found matching the criteria
[2022-09-05T12:36:31.031Z] 	at java.base/java.util.Optional.orElseThrow(Optional.java:403)
[2022-09-05T12:36:31.031Z] 	at io.camunda.zeebe.test.util.stream.StreamWrapper.getFirst(StreamWrapper.java:77)
[2022-09-05T12:36:31.031Z] 	at io.camunda.zeebe.engine.processing.timer.TimerStartEventTest.shouldTriggerAtSpecifiedTimeDate(TimerStartEventTest.java:806)
[2022-09-05T12:36:31.031Z] 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2022-09-05T12:36:31.031Z] 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
[2022-09-05T12:36:31.031Z] 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2022-09-05T12:36:31.031Z] 	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
[2022-09-05T12:36:31.031Z] 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
[2022-09-05T12:36:31.031Z] 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[2022-09-05T12:36:31.031Z] 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
[2022-09-05T12:36:31.031Z] 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[2022-09-05T12:36:31.031Z] 	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
[2022-09-05T12:36:31.031Z] 	at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:61)
[2022-09-05T12:36:31.031Z] 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
[2022-09-05T12:36:31.031Z] 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
[2022-09-05T12:36:31.031Z] 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
[2022-09-05T12:36:31.031Z] 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
[2022-09-05T12:36:31.031Z] 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
[2022-09-05T12:36:31.031Z] 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
[2022-09-05T12:36:31.031Z] 	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
[2022-09-05T12:36:31.031Z] 	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
[2022-09-05T12:36:31.031Z] 	at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
[2022-09-05T12:36:31.031Z] 	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
[2022-09-05T12:36:31.031Z] 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
[2022-09-05T12:36:31.031Z] 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
[2022-09-05T12:36:31.031Z] 	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
[2022-09-05T12:36:31.031Z] 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
[2022-09-05T12:36:31.031Z] 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
[2022-09-05T12:36:31.031Z] 	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
[2022-09-05T12:36:31.031Z] 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
[2022-09-05T12:36:31.031Z] 	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
[2022-09-05T12:36:31.031Z] 	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
[2022-09-05T12:36:31.031Z] 	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
[2022-09-05T12:36:31.031Z] 	at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
[2022-09-05T12:36:31.031Z] 	at org.junit.vintage.engine.execution.RunnerExecutor.execute(RunnerExecutor.java:42)
[2022-09-05T12:36:31.031Z] 	at org.junit.vintage.engine.VintageTestEngine.executeAllChildren(VintageTestEngine.java:80)
[2022-09-05T12:36:31.031Z] 	at org.junit.vintage.engine.VintageTestEngine.execute(VintageTestEngine.java:72)
[2022-09-05T12:36:31.031Z] 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:147)
[2022-09-05T12:36:31.031Z] 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:127)
[2022-09-05T12:36:31.031Z] 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:90)
[2022-09-05T12:36:31.031Z] 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:55)
[2022-09-05T12:36:31.031Z] 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:102)
[2022-09-05T12:36:31.031Z] 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:54)
[2022-09-05T12:36:31.031Z] 	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:114)
[2022-09-05T12:36:31.031Z] 	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:86)
[2022-09-05T12:36:31.031Z] 	at org.junit.platform.launcher.core.DefaultLauncherSession$DelegatingLauncher.execute(DefaultLauncherSession.java:86)
[2022-09-05T12:36:31.031Z] 	at org.apache.maven.surefire.junitplatform.LazyLauncher.execute(LazyLauncher.java:55)
[2022-09-05T12:36:31.031Z] 	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.lambda$execute$1(JUnitPlatformProvider.java:234)
[2022-09-05T12:36:31.031Z] 	at java.base/java.util.Iterator.forEachRemaining(Iterator.java:133)
[2022-09-05T12:36:31.031Z] 	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.execute(JUnitPlatformProvider.java:228)
[2022-09-05T12:36:31.032Z] 	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invokeAllTests(JUnitPlatformProvider.java:175)
[2022-09-05T12:36:31.032Z] 	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invoke(JUnitPlatformProvider.java:131)
[2022-09-05T12:36:31.032Z] 	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:456)
[2022-09-05T12:36:31.032Z] 	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:169)
[2022-09-05T12:36:31.032Z] 	at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:595)
[2022-09-05T12:36:31.032Z] 	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:581)
[2022-09-05T12:36:31.032Z] 
[2022-09-05T12:36:31.290Z] [INFO] Running io.camunda.zeebe.engine.state.instance.TimerInstanceStateTest
[2022-09-05T12:36:31.290Z] [INFO] Tests run: 22, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.57 s - in io.camunda.zeebe.engine.state.message.MessageStateTest
[2022-09-05T12:36:31.290Z] [INFO] Running io.camunda.zeebe.engine.state.instance.EventScopeInstanceStateTest
[2022-09-05T12:36:31.857Z] [INFO] Tests run: 9, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.17 s - in io.camunda.zeebe.engine.state.instance.IncidentStateTest
[2022-09-05T12:36:31.857Z] [INFO] Running io.camunda.zeebe.engine.state.instance.NumberOfTakenSequenceFlowsStateTest
[2022-09-05T12:36:32.115Z] [INFO] Tests run: 13, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.514 s - in io.camunda.zeebe.engine.state.instance.ElementInstanceStateTest
[2022-09-05T12:36:32.115Z] [INFO] Running io.camunda.zeebe.engine.state.instance.BlackListStateTest
[2022-09-05T12:36:32.115Z] [INFO] Tests run: 9, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 1.068 s - in io.camunda.zeebe.engine.state.instance.TimerInstanceStateTest
[2022-09-05T12:36:32.373Z] [INFO] Running io.camunda.zeebe.engine.util.EngineRuleTest
[2022-09-05T12:36:32.632Z] [INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.291 s - in io.camunda.zeebe.engine.util.EngineRuleTest
[2022-09-05T12:36:32.632Z] [INFO] Running io.camunda.zeebe.engine.util.LogStreamPrinterTest
[2022-09-05T12:36:32.632Z] [INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.074 s - in io.camunda.zeebe.engine.util.LogStreamPrinterTest
[2022-09-05T12:36:32.632Z] [INFO] Running io.camunda.zeebe.engine.processing.timer.TimerStartEventTest
[2022-09-05T12:36:32.890Z] [INFO] Tests run: 7, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.802 s - in io.camunda.zeebe.engine.state.instance.NumberOfTakenSequenceFlowsStateTest
[2022-09-05T12:36:32.890Z] [INFO] Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.22 s - in io.camunda.zeebe.engine.processing.timer.TimerStartEventTest
[2022-09-05T12:36:32.890Z] [INFO] Tests run: 6, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.835 s - in io.camunda.zeebe.engine.state.instance.BlackListStateTest
[2022-09-05T12:36:33.825Z] [INFO] Tests run: 32, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 3.694 s - in io.camunda.zeebe.engine.state.instance.JobStateTest
[2022-09-05T12:36:34.392Z] [INFO] Tests run: 25, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 2.97 s - in io.camunda.zeebe.engine.state.instance.EventScopeInstanceStateTest
[2022-09-05T12:36:36.926Z] [INFO] Tests run: 20, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 9.212 s - in io.camunda.zeebe.engine.state.ProcessExecutionCleanStateTest
[2022-09-05T12:36:36.926Z] [INFO] 
[2022-09-05T12:36:36.926Z] [INFO] Results:
[2022-09-05T12:36:36.926Z] [INFO] 
[2022-09-05T12:36:36.926Z] [WARNING] Flakes: 
[2022-09-05T12:36:36.926Z] [WARNING] io.camunda.zeebe.engine.processing.timer.TimerStartEventTest.shouldTriggerAtSpecifiedTimeDate
[2022-09-05T12:36:36.926Z] [ERROR]   Run 1: TimerStartEventTest.shouldTriggerAtSpecifiedTimeDate:806 » StreamWrapper No event found matching the criteria
[2022-09-05T12:36:36.926Z] [INFO]   Run 2: PASS
[2022-09-05T12:36:36.926Z] [INFO] 
[2022-09-05T12:36:36.926Z] [INFO] 
[2022-09-05T12:36:36.926Z] [WARNING] Tests run: 1732, Failures: 0, Errors: 0, Skipped: 2, Flakes: 1
@korthout korthout added the kind/flake Categorizes issue or PR as related to a flaky test label Sep 5, 2022
@korthout korthout changed the title Flaky TimerStartEventTest.shouldTriggerAtSpecifiedTimeDate Flaky TimerStartEventTest (multiple cases) Sep 6, 2022
@korthout
Copy link
Member Author

korthout commented Sep 6, 2022 •
edited
Loading

The following test cases are currently flaky:

  • TimerStartEventTest.shouldTriggerAtSpecifiedTimeDate (again, and again)
  • TimerStartEventTest.shouldUpdateProcess (run, and again)
  • TimerStartEventTest.shouldTriggerIfTimeDatePassedOnDeployment (run)
  • TimerStartEventTest.shouldReplaceTimerStartWithNoneStart (run)
  • TimerStartEventTest.shouldTriggerIfTimeDatePassedOnDeployment (run)

@korthout
Copy link
Member Author

korthout commented Sep 6, 2022

TimerStartEventTest.shouldUpdateProcess assertion failure

(run)

[2022-09-06T00:13:39.475Z] [ERROR] Tests run: 22, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 11.086 s <<< FAILURE! - in io.camunda.zeebe.engine.processing.timer.TimerStartEventTest
[2022-09-06T00:13:39.475Z] [ERROR] io.camunda.zeebe.engine.processing.timer.TimerStartEventTest.shouldUpdateProcess  Time elapsed: 5.283 s  <<< FAILURE!
[2022-09-06T00:13:39.475Z] org.opentest4j.AssertionFailedError: 
[2022-09-06T00:13:39.475Z] 
[2022-09-06T00:13:39.475Z] Expecting value to be true but was false
[2022-09-06T00:13:39.475Z] 	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
[2022-09-06T00:13:39.475Z] 	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77)
[2022-09-06T00:13:39.475Z] 	at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
[2022-09-06T00:13:39.476Z] 	at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499)
[2022-09-06T00:13:39.476Z] 	at io.camunda.zeebe.engine.processing.timer.TimerStartEventTest.shouldUpdateProcess(TimerStartEventTest.java:533)
[2022-09-06T00:13:39.476Z] 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2022-09-06T00:13:39.476Z] 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
[2022-09-06T00:13:39.476Z] 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2022-09-06T00:13:39.476Z] 	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
[2022-09-06T00:13:39.476Z] 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
[2022-09-06T00:13:39.476Z] 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[2022-09-06T00:13:39.476Z] 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
[2022-09-06T00:13:39.476Z] 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[2022-09-06T00:13:39.476Z] 	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
[2022-09-06T00:13:39.476Z] 	at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:61)
[2022-09-06T00:13:39.476Z] 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
[2022-09-06T00:13:39.476Z] 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
[2022-09-06T00:13:39.476Z] 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
[2022-09-06T00:13:39.476Z] 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
[2022-09-06T00:13:39.476Z] 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
[2022-09-06T00:13:39.476Z] 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
[2022-09-06T00:13:39.476Z] 	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
[2022-09-06T00:13:39.476Z] 	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
[2022-09-06T00:13:39.476Z] 	at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
[2022-09-06T00:13:39.476Z] 	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
[2022-09-06T00:13:39.476Z] 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
[2022-09-06T00:13:39.476Z] 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
[2022-09-06T00:13:39.476Z] 	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
[2022-09-06T00:13:39.476Z] 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
[2022-09-06T00:13:39.476Z] 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
[2022-09-06T00:13:39.476Z] 	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
[2022-09-06T00:13:39.476Z] 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
[2022-09-06T00:13:39.476Z] 	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
[2022-09-06T00:13:39.476Z] 	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
[2022-09-06T00:13:39.476Z] 	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
[2022-09-06T00:13:39.476Z] 	at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
[2022-09-06T00:13:39.476Z] 	at org.junit.vintage.engine.execution.RunnerExecutor.execute(RunnerExecutor.java:42)
[2022-09-06T00:13:39.476Z] 	at org.junit.vintage.engine.VintageTestEngine.executeAllChildren(VintageTestEngine.java:80)
[2022-09-06T00:13:39.476Z] 	at org.junit.vintage.engine.VintageTestEngine.execute(VintageTestEngine.java:72)
[2022-09-06T00:13:39.476Z] 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:147)
[2022-09-06T00:13:39.476Z] 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:127)
[2022-09-06T00:13:39.476Z] 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:90)
[2022-09-06T00:13:39.477Z] 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:55)
[2022-09-06T00:13:39.477Z] 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:102)
[2022-09-06T00:13:39.477Z] 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:54)
[2022-09-06T00:13:39.477Z] 	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:114)
[2022-09-06T00:13:39.477Z] 	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:86)
[2022-09-06T00:13:39.477Z] 	at org.junit.platform.launcher.core.DefaultLauncherSession$DelegatingLauncher.execute(DefaultLauncherSession.java:86)
[2022-09-06T00:13:39.477Z] 	at org.apache.maven.surefire.junitplatform.LazyLauncher.execute(LazyLauncher.java:55)
[2022-09-06T00:13:39.477Z] 	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.lambda$execute$1(JUnitPlatformProvider.java:234)
[2022-09-06T00:13:39.477Z] 	at java.base/java.util.Iterator.forEachRemaining(Iterator.java:133)
[2022-09-06T00:13:39.477Z] 	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.execute(JUnitPlatformProvider.java:228)
[2022-09-06T00:13:39.477Z] 	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invokeAllTests(JUnitPlatformProvider.java:175)
[2022-09-06T00:13:39.477Z] 	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invoke(JUnitPlatformProvider.java:131)
[2022-09-06T00:13:39.477Z] 	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:456)
[2022-09-06T00:13:39.477Z] 	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:169)
[2022-09-06T00:13:39.477Z] 	at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:595)
[2022-09-06T00:13:39.477Z] 	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:581)

@megglos
Copy link
Contributor

megglos commented Sep 7, 2022

TimerStartEventTest.shouldUpdateProcess assertion failure

(run)

2022-09-07T09:40:15.843Z] [ERROR] Tests run: 22, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 12.267 s <<< FAILURE! - in io.camunda.zeebe.engine.processing.timer.TimerStartEventTest
[2022-09-07T09:40:15.843Z] [ERROR] io.camunda.zeebe.engine.processing.timer.TimerStartEventTest.shouldUpdateProcess  Time elapsed: 5.344 s  <<< FAILURE!
[2022-09-07T09:40:15.843Z] org.opentest4j.AssertionFailedError: 
[2022-09-07T09:40:15.843Z] 
[2022-09-07T09:40:15.843Z] Expecting value to be true but was false
[2022-09-07T09:40:15.843Z] 	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
[2022-09-07T09:40:15.843Z] 	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:77)
[2022-09-07T09:40:15.844Z] 	at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
[2022-09-07T09:40:15.844Z] 	at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Constructor.java:499)
[2022-09-07T09:40:15.844Z] 	at io.camunda.zeebe.engine.processing.timer.TimerStartEventTest.shouldUpdateProcess(TimerStartEventTest.java:533)
[2022-09-07T09:40:15.844Z] 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
[2022-09-07T09:40:15.844Z] 	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
[2022-09-07T09:40:15.844Z] 	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[2022-09-07T09:40:15.844Z] 	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
[2022-09-07T09:40:15.844Z] 	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
[2022-09-07T09:40:15.844Z] 	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
[2022-09-07T09:40:15.844Z] 	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
[2022-09-07T09:40:15.844Z] 	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
[2022-09-07T09:40:15.844Z] 	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
[2022-09-07T09:40:15.844Z] 	at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:61)
[2022-09-07T09:40:15.844Z] 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
[2022-09-07T09:40:15.844Z] 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
[2022-09-07T09:40:15.844Z] 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
[2022-09-07T09:40:15.844Z] 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
[2022-09-07T09:40:15.844Z] 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
[2022-09-07T09:40:15.844Z] 	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
[2022-09-07T09:40:15.844Z] 	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
[2022-09-07T09:40:15.844Z] 	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
[2022-09-07T09:40:15.844Z] 	at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
[2022-09-07T09:40:15.844Z] 	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
[2022-09-07T09:40:15.844Z] 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
[2022-09-07T09:40:15.844Z] 	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
[2022-09-07T09:40:15.844Z] 	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
[2022-09-07T09:40:15.844Z] 	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
[2022-09-07T09:40:15.844Z] 	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
[2022-09-07T09:40:15.844Z] 	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
[2022-09-07T09:40:15.844Z] 	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
[2022-09-07T09:40:15.844Z] 	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
[2022-09-07T09:40:15.844Z] 	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
[2022-09-07T09:40:15.844Z] 	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
[2022-09-07T09:40:15.844Z] 	at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
[2022-09-07T09:40:15.844Z] 	at org.junit.vintage.engine.execution.RunnerExecutor.execute(RunnerExecutor.java:42)
[2022-09-07T09:40:15.844Z] 	at org.junit.vintage.engine.VintageTestEngine.executeAllChildren(VintageTestEngine.java:80)
[2022-09-07T09:40:15.844Z] 	at org.junit.vintage.engine.VintageTestEngine.execute(VintageTestEngine.java:72)
[2022-09-07T09:40:15.844Z] 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:147)
[2022-09-07T09:40:15.844Z] 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:127)
[2022-09-07T09:40:15.844Z] 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:90)
[2022-09-07T09:40:15.844Z] 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:55)
[2022-09-07T09:40:15.844Z] 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:102)
[2022-09-07T09:40:15.844Z] 	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:54)
[2022-09-07T09:40:15.844Z] 	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:114)
[2022-09-07T09:40:15.844Z] 	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:86)
[2022-09-07T09:40:15.844Z] 	at org.junit.platform.launcher.core.DefaultLauncherSession$DelegatingLauncher.execute(DefaultLauncherSession.java:86)
[2022-09-07T09:40:15.844Z] 	at org.apache.maven.surefire.junitplatform.LazyLauncher.execute(LazyLauncher.java:55)
[2022-09-07T09:40:15.844Z] 	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.lambda$execute$1(JUnitPlatformProvider.java:234)
[2022-09-07T09:40:15.844Z] 	at java.base/java.util.Iterator.forEachRemaining(Iterator.java:133)
[2022-09-07T09:40:15.844Z] 	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.execute(JUnitPlatformProvider.java:228)
[2022-09-07T09:40:15.844Z] 	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invokeAllTests(JUnitPlatformProvider.java:175)
[2022-09-07T09:40:15.844Z] 	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invoke(JUnitPlatformProvider.java:131)
[2022-09-07T09:40:15.845Z] 	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:456)
[2022-09-07T09:40:15.845Z] 	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:169)
[2022-09-07T09:40:15.845Z] 	at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:595)
[2022-09-07T09:40:15.845Z] 	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:581)
[2022-09-07T09:40:15.845Z] 

09:40:17.609 [Broker-0-LogStream-1] DEBUG io.camunda.zeebe.logstreams - Configured log appender back pressure at partition 1 as AppenderVegasCfg{initialLimit=1024, maxConcurrency=32768, alphaLimit=0.7, betaLimit=0.95}. Window limiting is disabled
09:40:17.682 [Broker-0-StreamProcessor-1] DEBUG io.camunda.zeebe.logstreams - Recovering state of partition 1 from snapshot
09:40:17.682 [Broker-0-StreamProcessor-1] INFO  org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@6393bc21)), function-provider: io.camunda.zeebe.feel.impl.FeelFunctionProvider@2c194307, clock: io.camunda.zeebe.el.impl.ZeebeFeelEngineClock@32ee7ccf, configuration: Configuration(false)]
09:40:17.683 [Broker-0-StreamProcessor-1] INFO  io.camunda.zeebe.logstreams - Recovered state of partition 1 from snapshot at position -1
09:40:17.684 [Broker-0-StreamProcessor-1] INFO  org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@56e11e73)), function-provider: io.camunda.zeebe.feel.impl.FeelFunctionProvider@353274f2, clock: io.camunda.zeebe.el.impl.ZeebeFeelEngineClock@4a4b2004, configuration: Configuration(false)]
09:40:17.685 [Broker-0-StreamProcessor-1] INFO  org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@6f0ea696)), function-provider: io.camunda.zeebe.feel.impl.FeelFunctionProvider@101d650e, clock: io.camunda.zeebe.el.impl.ZeebeFeelEngineClock@37a994f7, configuration: Configuration(false)]
09:40:17.686 [Broker-0-StreamProcessor-1] INFO  org.camunda.dmn.DmnEngine - DMN-Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@257b88b7)), function-provider: org.camunda.feel.context.FunctionProvider$EmptyFunctionProvider$@2aa69c73, audit-loggers: List(), configuration: Configuration(false,false,false)]
09:40:17.686 [Broker-0-StreamProcessor-1] INFO  org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(org.camunda.dmn.NoUnpackValueMapper@54bccc84)), function-provider: org.camunda.feel.context.FunctionProvider$EmptyFunctionProvider$@2aa69c73, clock: SystemClock, configuration: Configuration(false)]
09:40:17.687 [Broker-0-StreamProcessor-1] INFO  org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@c561538)), function-provider: io.camunda.zeebe.feel.impl.FeelFunctionProvider@63037349, clock: io.camunda.zeebe.el.impl.ZeebeFeelEngineClock@31ecfbd3, configuration: Configuration(false)]
09:40:17.687 [Broker-0-StreamProcessor-1] INFO  org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@1a2d30e6)), function-provider: io.camunda.zeebe.feel.impl.FeelFunctionProvider@26ee094e, clock: io.camunda.zeebe.el.impl.ZeebeFeelEngineClock@5e0fbfe1, configuration: Configuration(false)]
09:40:17.689 [Broker-0-StreamProcessor-1] INFO  org.camunda.dmn.DmnEngine - DMN-Engine created. [value-mapper: CompositeValueMapper(List(io.camunda.zeebe.feel.impl.MessagePackValueMapper@30aba1ae)), function-provider: org.camunda.feel.context.FunctionProvider$EmptyFunctionProvider$@2aa69c73, audit-loggers: List(), configuration: Configuration(false,false,false)]
09:40:17.689 [Broker-0-StreamProcessor-1] INFO  org.camunda.feel.FeelEngine - Engine created. [value-mapper: CompositeValueMapper(List(org.camunda.dmn.NoUnpackValueMapper@19a35a5d)), function-provider: org.camunda.feel.context.FunctionProvider$EmptyFunctionProvider$@2aa69c73, clock: SystemClock, configuration: Configuration(false)]
09:40:17.690 [Broker-0-StreamProcessor-1] INFO  io.camunda.zeebe.processor - Processor starts replay of events. [snapshot-position: -1, replay-mode: PROCESSING]
09:40:17.690 [Broker-0-StreamProcessor-1] INFO  io.camunda.zeebe.processor - Processor finished replay, with [lastProcessedPosition: -1, lastWrittenPosition: -1]
09:40:17.690 [Broker-0-StreamProcessor-1] INFO  io.camunda.zeebe.engine.state.migration - Starting processing of migration tasks (use LogLevel.DEBUG for more details) ... 
09:40:17.690 [Broker-0-StreamProcessor-1] DEBUG io.camunda.zeebe.engine.state.migration - Found 3 migration tasks: ProcessMessageSubscriptionSentTimeMigration, MessageSubscriptionSentTimeMigration, TemporaryVariableMigration
09:40:17.691 [Broker-0-StreamProcessor-1] INFO  io.camunda.zeebe.engine.state.migration - Skipping ProcessMessageSubscriptionSentTimeMigration migration (1/3).  It was determined it does not need to run right now.
09:40:17.691 [Broker-0-StreamProcessor-1] INFO  io.camunda.zeebe.engine.state.migration - Skipping MessageSubscriptionSentTimeMigration migration (2/3).  It was determined it does not need to run right now.
09:40:17.691 [Broker-0-StreamProcessor-1] INFO  io.camunda.zeebe.engine.state.migration - Skipping TemporaryVariableMigration migration (3/3).  It was determined it does not need to run right now.
09:40:17.691 [Broker-0-StreamProcessor-1] INFO  io.camunda.zeebe.engine.state.migration - Completed processing of migration tasks (use LogLevel.DEBUG for more details) ... 
09:40:17.691 [Broker-0-StreamProcessor-1] DEBUG io.camunda.zeebe.engine.state.migration - Executed 0 migration tasks: 
09:40:17.736 [] DEBUG io.camunda.zeebe.broker.logstreams - Close stream processor
09:40:17.736 [Broker-0-StreamProcessor-1] DEBUG io.camunda.zeebe.scheduler.ActorTask - Discard job io.camunda.zeebe.scheduler.future.FutureContinuationRunnable QUEUED from fastLane of Actor Broker-0-StreamProcessor-1.
09:40:17.736 [Broker-0-StreamProcessor-1] DEBUG io.camunda.zeebe.logstreams - Closed stream processor controller Broker-0-StreamProcessor-1.
09:40:17.775 [Broker-0-LogStream-1] INFO  io.camunda.zeebe.logstreams - Close appender for log stream stream-1
09:40:17.775 [stream-1-write-buffer] DEBUG io.camunda.zeebe.dispatcher - Dispatcher closed
09:40:17.775 [Broker-0-LogStream-1] INFO  io.camunda.zeebe.logstreams - On closing logstream stream-1 close 2 readers
09:40:17.776 [] DEBUG io.camunda.zeebe.broker.test - Clean up test files on path /tmp/junit9104157836144718197
09:40:17.778 [] DEBUG io.camunda.zeebe.util.actor - Closing actor thread ground '-zb-fs-workers'
09:40:17.778 [] DEBUG io.camunda.zeebe.util.actor - Closing actor thread ground '-zb-actors'
09:40:17.779 [] DEBUG io.camunda.zeebe.util.actor - Closing actor thread ground '-zb-fs-workers': closed successfully
09:40:17.779 [] DEBUG io.camunda.zeebe.util.actor - Closing actor thread ground '-zb-actors': closed successfully

@Zelldon
Copy link
Member

Zelldon commented Sep 8, 2022

I think if we remove the complexity in the ScheduleService as described here #9723 (comment) we might overcome this (at least I think it is related).

@saig0 saig0 mentioned this issue Sep 8, 2022
Merged
10 tasks
ghost pushed a commit that referenced this issue Sep 8, 2022
@saig0
merge: #10300
2648f87 
10300: test(engine): stabilize the timer start event test r=korthout a=saig0

## Description
* we assume that pinning the time causes more test cases to be unstable
* so, first we try to stabilize the test by avoiding pinning the time

## Related issues

contributes to #10272



Co-authored-by: Philipp Ossler <philipp.ossler@gmail.com>
@Zelldon Zelldon mentioned this issue Sep 14, 2022
Merged
10 tasks
ghost pushed a commit that referenced this issue Sep 15, 2022
@remcowesterhoud @Zelldon
merge: #10352 #10355
93cfe32 
10352: PI Modification: Reject direct termination of child process r=remcowesterhoud a=remcowesterhoud

## Description

<!-- Please explain the changes you made here. -->
It is possible to terminate a process instance using a modification command. This is done by adding terminate instructions for all of the active element instances of the process. When this happens the process will be fully terminated.

However, it could be the case that a process is started with a call activity. This causes a complex situation. Terminating the child process would mean the parent process is "stuck". There is a few ways around this.

1. We could terminate the parent process. This could have unintended consequence for the user.
2. An incident is created on the parent process. The problem here is that the current incident logic makes it impossible to resolve these incidents. These could be worked around by doing another modification. That leaves the question why the user wouldn't modify the parent process in the first place.
3. We reject the command and advice the user to modify the parent process if the child process needs to be terminated.

The option we are going for is option 3. When we detect that we are trying to terminate a process which is called by a parent process, the command will be rejected. The user received a message with the advice to modify the parent process instead.

## Related issues

<!-- Which issues are closed by this PR or are related -->

closes #10347 



10355: Run ScheduledTasks during processing r=Zelldon a=Zelldon

## Description

Removes the guarantee that scheduled Tasks are only executed after commit and only if no inProcessing is going on. This is not necessary, since all actions we want to execute after a commit are executed via PostcommitTasks which are added to the ProcessingResult.

See related comment and discussion #9723 (comment)

Future improvements:

 * We can create our own actor for the SchedulingService this would decouple better than scheduling and processing
 * We can remove the multiple scheduling in the SchedulingService #10291

<!-- Please explain the changes you made here. -->

## Related issues

<!-- Which issues are closed by this PR or are related -->

closes #9723
related #10272



Co-authored-by: Remco Westerhoud <remco@westerhoud.nl>
Co-authored-by: Christopher Zell <zelldon91@googlemail.com>
@remcowesterhoud
Copy link
Contributor

TimerStartEventTest.shouldCreateCronTimer stack trace

(run)

io.camunda.zeebe.test.util.stream.StreamWrapperException: No event found matching the criteria
	at java.base/java.util.Optional.orElseThrow(Optional.java:403)
	at io.camunda.zeebe.test.util.stream.StreamWrapper.getFirst(StreamWrapper.java:77)
	at io.camunda.zeebe.engine.processing.timer.TimerStartEventTest.shouldCreateCronTimer(TimerStartEventTest.java:1249)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:61)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
	at org.junit.vintage.engine.execution.RunnerExecutor.execute(RunnerExecutor.java:42)
	at org.junit.vintage.engine.VintageTestEngine.executeAllChildren(VintageTestEngine.java:80)
	at org.junit.vintage.engine.VintageTestEngine.execute(VintageTestEngine.java:72)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:147)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:127)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:90)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:55)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:102)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:54)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:114)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:86)
	at org.junit.platform.launcher.core.DefaultLauncherSession$DelegatingLauncher.execute(DefaultLauncherSession.java:86)
	at org.apache.maven.surefire.junitplatform.LazyLauncher.execute(LazyLauncher.java:55)
	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.lambda$execute$1(JUnitPlatformProvider.java:234)
	at java.base/java.util.Iterator.forEachRemaining(Iterator.java:133)
	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.execute(JUnitPlatformProvider.java:228)
	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invokeAllTests(JUnitPlatformProvider.java:175)
	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invoke(JUnitPlatformProvider.java:131)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:456)
	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:169)
	at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:595)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:581)

@lenaschoenburg
Copy link
Member

TimerStartEventTest.shouldTriggerAndCreateProcessInstance stack trace

(run)

Expecting actual:
  [TRIGGER, TRIGGER]
to contain exactly (and in same order):
  [TRIGGER, TRIGGERED]
but some elements were not found:
  [TRIGGERED]
and others were not expected:
  [TRIGGER]

@Zelldon
Copy link
Member

Zelldon commented Oct 12, 2022

I guess related #10058

This was referenced Oct 12, 2022
Closed
Merged
@saig0
Copy link
Member

saig0 commented Oct 18, 2022

TimerStartEventTest.shouldAvoidTimeShifting 
io.camunda.zeebe.engine.processing.timer.TimerStartEventTest.shouldAvoidTimeShifting  Time elapsed: 5.479 s  <<< ERROR!
io.camunda.zeebe.test.util.stream.StreamWrapperException: No event found matching the criteria
	at java.base/java.util.Optional.orElseThrow(Optional.java:403)
	at io.camunda.zeebe.test.util.stream.StreamWrapper.getFirst(StreamWrapper.java:77)
	at io.camunda.zeebe.engine.processing.timer.TimerStartEventTest.shouldAvoidTimeShifting(TimerStartEventTest.java:1169)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:61)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.ExternalResource$1.evaluate(ExternalResource.java:54)
	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
	at org.junit.vintage.engine.execution.RunnerExecutor.execute(RunnerExecutor.java:42)
	at org.junit.vintage.engine.VintageTestEngine.executeAllChildren(VintageTestEngine.java:80)
	at org.junit.vintage.engine.VintageTestEngine.execute(VintageTestEngine.java:72)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:147)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:127)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:90)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.lambda$execute$0(EngineExecutionOrchestrator.java:55)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.withInterceptedStreams(EngineExecutionOrchestrator.java:102)
	at org.junit.platform.launcher.core.EngineExecutionOrchestrator.execute(EngineExecutionOrchestrator.java:54)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:114)
	at org.junit.platform.launcher.core.DefaultLauncher.execute(DefaultLauncher.java:86)
	at org.junit.platform.launcher.core.DefaultLauncherSession$DelegatingLauncher.execute(DefaultLauncherSession.java:86)
	at org.apache.maven.surefire.junitplatform.LazyLauncher.execute(LazyLauncher.java:55)
	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.lambda$execute$1(JUnitPlatformProvider.java:234)
	at java.base/java.util.Iterator.forEachRemaining(Iterator.java:133)
	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.execute(JUnitPlatformProvider.java:228)
	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invokeAllTests(JUnitPlatformProvider.java:175)
	at org.apache.maven.surefire.junitplatform.JUnitPlatformProvider.invoke(JUnitPlatformProvider.java:131)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:456)
	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:169)
	at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:595)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:581)

@korthout
Copy link
Member Author

TimerStartEventTest.shouldAvoidTimeshifting flaked again in https://github.com/camunda/zeebe/actions/runs/3311836398/jobs/5467767104

@korthout
Copy link
Member Author

TimerStartEventTest.shouldCreateCronTimer flaked again in https://github.com/camunda/zeebe/actions/runs/3342691385/jobs/5535172256

@npepinpe
Copy link
Member

shouldCreateCronTimer: https://github.com/camunda/zeebe/actions/runs/3345340779/jobs/5540745068

@korthout korthout assigned korthout, saig0 and remcowesterhoud and unassigned korthout and saig0 Oct 31, 2022
@korthout korthout mentioned this issue Oct 31, 2022
Merged
9 tasks
ghost pushed a commit that referenced this issue Nov 1, 2022
@korthout
merge: #10867
f784cc5 
10867: Unflake timer start event test r=remcowesterhoud a=korthout

## Description

<!-- Please explain the changes you made here. -->

Most cases in the timer start event test were suffering from flakiness. This stabilizes these tests again.

The cause of the flakiness was a race condition between time traveling and scheduling an upcoming timer:
 - the time would be increased after the deployment is completed
 - that includes writing all the deployment events (up to and including fully_distributed)
 - it does not await post-commit task execution
 - upcoming timers are scheduled in a post-commit task
 - this post-commit task could be executed after the time traveling
 - in that case the timer does not trigger after the time travel, as it is scheduled in the future

This changes the time travel to guarantee that the post-commit tasks have been executed. It does that by awaiting that the engine reaches the end of the log.

## Related issues

<!-- Which issues are closed by this PR or are related -->

closes #10272 



Co-authored-by: Nico Korthout <nico.korthout@camunda.com>
@ghost ghost closed this as completed in f93a7e1 Nov 2, 2022
@backport-action backport-action mentioned this issue Nov 2, 2022
Merged
ghost pushed a commit that referenced this issue Nov 2, 2022
@korthout @remcowesterhoud
merge: #10891
751a687 
10891: [Backport stable/8.1] Unflake timer start event test r=korthout a=backport-action

# Description
Backport of #10867 to `stable/8.1`.

relates to #10272

Co-authored-by: Nico Korthout <nico.korthout@camunda.com>
Co-authored-by: Remco Westerhoud <remco@westerhoud.nl>
@korthout korthout mentioned this issue Nov 2, 2022
Merged
ghost pushed a commit that referenced this issue Nov 2, 2022
@korthout @remcowesterhoud
merge: #10893
b8d7088 
10893: [Backport stable/8.0] Unflake timer start event test r=remcowesterhoud a=korthout

# Description
Backport of #10867 to `stable/8.0`.

relates to #10272

---

Reviewer, I had to resolve a few conflicts:
- some import changes
- new tests in TimerStartEventTest were changed, but these tests don't exist in 8.0

Co-authored-by: Nico Korthout <nico.korthout@camunda.com>
Co-authored-by: Remco Westerhoud <remco@westerhoud.nl>
@lzgabel
Copy link
Contributor

lzgabel commented Nov 3, 2022

TimerStartEventTest.shouldTriggerAndCreateProcessInstance flaked in
https://github.com/camunda/zeebe/actions/runs/3383895953/jobs/5620286359

@korthout
Copy link
Member Author

korthout commented Nov 3, 2022 •
edited
Loading

TimerStartEventTest.shouldTriggerAndCreateProcessInstance flaked in https://github.com/camunda/zeebe/actions/runs/3383895953/jobs/5620286359

@lzgabel the commit on which that action was run does not yet contain the fix (f784cc5). After a rebase on (or merge with) main the test should be stable. You may want to consider rebasing the PR, but as this relates to a flaky test it isn't mandatory.

git merge-base f784cc5 --is-ancestor d02a975b24 && echo yes || echo no
no

@deepthidevaki
Copy link
Contributor

Observed this in https://github.com/camunda/zeebe/actions/runs/3436982198/jobs/5731160232

Error:    Run 1: TimerStartEventTest.shouldTriggerAndCreateProcessInstance:371 
Expecting actual:
  [TRIGGER, TRIGGER]
to contain exactly (and in same order):
  [TRIGGER, TRIGGERED]
but some elements were not found:
  [TRIGGERED]
and others were not expected:
  [TRIGGER]

@korthout
Copy link
Member Author

@deepthidevaki Thanks for reporting. This run contained the fix (f93a7e1 is an ancestor of 640074b). Let's re-open this issue.

 git merge-base f93a7e1a --is-ancestor 640074b2 && echo yes || echo no
yes

@korthout korthout reopened this Nov 10, 2022
@remcowesterhoud
Copy link
Contributor

I just got another case https://github.com/camunda/zeebe/actions/runs/3437675187/jobs/5732753249

@lenaschoenburg lenaschoenburg mentioned this issue Nov 11, 2022
Closed
@remcowesterhoud remcowesterhoud mentioned this issue Nov 17, 2022
Merged
9 tasks
@npepinpe
Copy link
Member

New case: https://github.com/camunda/zeebe/actions/runs/3493816232/jobs/5849027273

@ghost ghost closed this as completed in 6f775d9 Nov 18, 2022
This was referenced Nov 18, 2022
Closed
Merged
ghost pushed a commit that referenced this issue Nov 18, 2022
@remcowesterhoud
merge: #11052
6314b42 
11052: [Backport stable/8.1] Resolve flaky timer test r=remcowesterhoud a=backport-action

# Description
Backport of #11033 to `stable/8.1`.

relates to #10272

Co-authored-by: Remco Westerhoud <remco@westerhoud.nl>
@remcowesterhoud remcowesterhoud added the version:8.1.4 Marks an issue as being completely or in parts released in 8.1.4 label Nov 22, 2022
ghost pushed a commit that referenced this issue Nov 22, 2022
@remcowesterhoud
merge: #11051
27fd39a 
11051: [Backport stable/8.0] Resolve flaky timer test r=remcowesterhoud a=backport-action

# Description
Backport of #11033 to `stable/8.0`.

relates to #10272

Co-authored-by: Remco Westerhoud <remco@westerhoud.nl>
@remcowesterhoud remcowesterhoud added version:8.2.0-alpha2 Marks an issue as being completely or in parts released in 8.2.0-alpha2 release/8.0.9 labels Dec 6, 2022
@npepinpe npepinpe added the version:8.2.0 Marks an issue as being completely or in parts released in 8.2.0 label Apr 5, 2023
This issue was closed.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@korthout korthout

@saig0 saig0

@remcowesterhoud remcowesterhoud

Labels
kind/flake Categorizes issue or PR as related to a flaky test version:8.1.4 Marks an issue as being completely or in parts released in 8.1.4 version:8.2.0-alpha2 Marks an issue as being completely or in parts released in 8.2.0-alpha2 version:8.2.0 Marks an issue as being completely or in parts released in 8.2.0
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Unflake timer start event test camunda/camunda
Resolve flaky timer test camunda/camunda
9 participants
@npepinpe @megglos @lenaschoenburg @deepthidevaki @Zelldon @korthout @saig0 @remcowesterhoud @lzgabel