camunda
camunda copied to clipboard
Published
20 hours ago •
camunda
camunda
Running blocking ActorJob can impact and block scheduled timers
Describe the bug
When investigating https://github.com/camunda/zeebe/issues/11847 we (@oleschoenburg and I) realized that some scheduled job (which should release a latch) is not executed.
After further investigation, we realized that it depends on which Thread the timer (or job) is scheduled.
Note: Jobs that are scheduled via
runDelayedare put into a TimerQueue (DeadlineTimerWheel). Each ActorThread has its own queue. This means a scheduled job is bound to the specific Thread, after submitted.
When we schedule a job, on a Thread X and later the same Thread executed another Actor, which blocks the thread, then this Timer can't be executed after the time is due.
Impact:
It depends on the case, but it can be severe if we wait on one Actor (blocking) on something and want to release it on another Actor (after some time, e.g. via a scheduled timer). This will end in a deadlock if both are on the same thread, as we have seen here https://github.com/camunda/zeebe/issues/11847.
This can happen everywhere in our code base. If an actor job is scheduled and executed and blocks an ActorThread it might block the execution of future ActorJobs, which are scheduled as runDelayed.
To Reproduce
Run test from https://github.com/camunda/zeebe/issues/11847. Can be simplified in a way that one actor needs to wait for on a latch and the other actor schedules an job, which releases the latch. If we run this multiple times, the chances are high that we run into the situation.
Expected behavior
One issue is of course we can't always be sure that we are not blocking. Another is that we expect, based on our programming model, that actors are independent. If we schedule an timer on one we expect it to be executed, even if another might be blocked.
Ideally we should have one TimerQueue or observer thread, which checks that queue and puts the due timers or jobs into the ActorTask. This allows to decouple this a bit more, and it is not necessary to check all the time the queues and maintain them in each thread.
Log/Stacktrace
In the following failing test run we can see that the scheduled job, has been scheduled on the same Thread as the Blocking stream processor. Based on the test https://github.com/camunda/zeebe/issues/11847
Failing test run
12:12:07.795 [io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Start waiting - io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1
12:12:07.795 [Broker-0-LogStream-1] [-zb-actors-13] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1
12:12:07.796 [] [-zb-actors-13] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.796 [io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Actor io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1 set new state WAKING_UP from WAITING
12:12:07.796 [] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1
12:12:07.796 [Broker-0-LogStream-1] [-zb-actors-13] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.796 [io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1
12:12:07.796 [] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1
12:12:07.796 [io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1] [-zb-actors-13] ERROR io.camunda.zeebe.util.actor - Start waiting - io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1
12:12:07.822 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.823 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:07.823 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.823 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-StreamProcessor-1
12:12:07.823 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:07.823 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-StreamProcessor-1 set new state WAKING_UP from WAITING
12:12:07.823 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-StreamProcessor-1
12:12:07.823 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.823 [] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-StreamProcessor-1
12:12:07.823 [Broker-0-StreamProcessor-1] [-zb-actors-9] DEBUG io.camunda.zeebe.logstreams - Recovering state of partition 1 from snapshot
12:12:07.823 [Broker-0-StreamProcessor-1] [-zb-actors-9] INFO io.camunda.zeebe.logstreams - Recovered state of partition 1 from snapshot at position -1
12:12:07.824 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Scheduled runnable io.camunda.zeebe.stream.impl.StreamProcessor$$Lambda$530/0x0000000800f72ed0@1027f7a6 - delay PT5S
12:12:07.824 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - ActorThread ACTIVE
12:12:07.824 [Broker-0-StreamProcessor-1] [-zb-actors-9] INFO io.camunda.zeebe.processor - Processor starts replay of events. [snapshot-position: -1, replay-mode: PROCESSING]
12:12:07.824 [Broker-0-StreamProcessor-1] [-zb-actors-9] INFO io.camunda.zeebe.processor - Processor finished replay, with [lastProcessedPosition: -1, lastWrittenPosition: -1]
12:12:07.824 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.824 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:07.824 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.824 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-StreamProcessor-1
12:12:07.824 [Broker-0-LogStream-1] [-zb-actors-9] TRACE io.camunda.zeebe.logstreams.impl.log.Sequencer - Starting new sequencer at position 1
12:12:07.824 [Broker-0-LogStream-1] [-zb-actors-9] DEBUG io.camunda.zeebe.logstreams.impl.flowcontrol.AppenderFlowControl - Configured log appender back pressure as BackpressureCfgVegas{initialLimit=1024, maxConcurrency=32768, alphaLimit=0.7, betaLimit=0.95}. Window limiting is disabled
12:12:07.825 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.825 [Broker-0-LogAppender-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogAppender-1
12:12:07.825 [Broker-0-LogAppender-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.825 [Broker-0-LogAppender-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:07.825 [Broker-0-LogAppender-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.825 [] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogAppender-1
12:12:07.825 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.825 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogAppender-1
12:12:07.825 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:07.825 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-StreamProcessor-1 set new state WAKING_UP from WAITING
12:12:07.825 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-StreamProcessor-1
12:12:07.825 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.825 [Broker-0-LogAppender-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogAppender-1
12:12:07.825 [Broker-0-StreamProcessor-1] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.825 [Broker-0-StreamProcessor-1] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:07.825 [Broker-0-StreamProcessor-1] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.825 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:07.825 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.825 [Broker-0-StreamProcessor-1] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:07.825 [Broker-0-StreamProcessor-1] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-StreamProcessor-1
12:12:07.825 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.825 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:07.825 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.825 [Broker-0-LogStream-1] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.825 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.825 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:07.825 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-StreamProcessor-1 set new state WAKING_UP from WAITING
12:12:07.825 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-StreamProcessor-1
12:12:07.825 [] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.825 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.825 [Broker-0-StreamProcessor-1] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.825 [Broker-0-StreamProcessor-1] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:07.825 [Broker-0-StreamProcessor-1] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.825 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.826 [Broker-0-StreamProcessor-1] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.826 [Broker-0-StreamProcessor-1] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Actor io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor set new state WAKING_UP from WAITING
12:12:07.826 [Broker-0-StreamProcessor-1] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.826 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-9] ERROR io.camunda.zeebe.stream - SCHEDULE TASK ALTER
12:12:07.826 [Broker-0-StreamProcessor-1] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:07.826 [Broker-0-StreamProcessor-1] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-StreamProcessor-1
12:12:07.826 [Broker-0-StreamProcessor-1] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-StreamProcessor-1 set new state WAKING_UP from WAITING
12:12:07.826 [] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-StreamProcessor-1
12:12:07.826 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Scheduled runnable io.camunda.zeebe.stream.impl.ProcessingScheduleServiceImpl$$Lambda$586/0x0000000800f90dd0@1adf9cd6 - delay PT1M
12:12:07.826 [Broker-0-StreamProcessor-1] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-StreamProcessor-1
12:12:07.826 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - ActorThread ACTIVE
12:12:07.826 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.833 [] [main] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.833 [] [main] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:07.833 [] [main] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.833 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.834 [] [main] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogAppender-1
12:12:07.834 [] [main] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogAppender-1 set new state WAKING_UP from WAITING
12:12:07.834 [] [main] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogAppender-1
12:12:07.834 [Broker-0-LogAppender-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.834 [Broker-0-LogAppender-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:07.834 [Broker-0-LogAppender-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.834 [Broker-0-LogAppender-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogAppender-1
12:12:07.834 [Broker-0-LogAppender-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogAppender-1
12:12:07.834 [Broker-0-LogAppender-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogAppender-1 set new state WAKING_UP from WAITING
12:12:07.834 [] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogAppender-1
12:12:07.834 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:07.834 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-StreamProcessor-1 set new state WAKING_UP from WAITING
12:12:07.834 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-StreamProcessor-1
12:12:07.834 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.834 [Broker-0-LogAppender-1] [-zb-actors-12] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogAppender-1
12:12:07.835 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Wait processing, actortask Broker-0-StreamProcessor-1 ACTIVE phase: STARTED
12:12:08.036 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:14:08.036Z and await false
12:12:08.237 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:16:08.237Z and await false
12:12:08.438 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:18:08.438Z and await false
12:12:08.639 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:20:08.639Z and await false
12:12:08.839 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:22:08.839Z and await false
12:12:09.040 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:24:09.040Z and await false
12:12:09.241 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:26:09.241Z and await false
12:12:09.442 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:28:09.442Z and await false
12:12:09.642 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:30:09.642Z and await false
12:12:09.843 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:32:09.843Z and await false
12:12:10.044 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:34:10.044Z and await false
12:12:10.245 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:36:10.245Z and await false
12:12:10.446 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:38:10.446Z and await false
12:12:10.647 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:40:10.646Z and await false
12:12:10.847 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:42:10.847Z and await false
12:12:11.048 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:44:11.048Z and await false
12:12:11.249 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:46:11.249Z and await false
12:12:11.450 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:48:11.450Z and await false
12:12:11.651 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:50:11.650Z and await false
12:12:11.852 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:52:11.852Z and await false
12:12:12.053 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:54:12.053Z and await false
12:12:12.254 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:56:12.254Z and await false
12:12:12.455 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:58:12.455Z and await false
12:12:12.656 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T12:00:12.656Z and await false
12:12:12.839 [] [main] ERROR io.camunda.zeebe.stream - WAIT LATCH COUNT DOWN
12:12:12.840 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:12.840 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:12.840 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:12.841 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:12.841 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:12.841 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-StreamProcessor-1
12:12:12.841 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-StreamProcessor-1 set new state WAKING_UP from WAITING
12:12:12.841 [] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-StreamProcessor-1
12:12:12.841 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-StreamProcessor-1
12:12:12.841 [] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:12.841 [] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor set new state WAKING_UP from WAITING
12:12:12.841 [] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:12.841 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Scheduled Task, actortask io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor ACTIVE phase: STARTED
12:12:12.841 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - COUNT DOWN YO Clock: 2023-02-28T12:02:12.841Z
12:12:12.841 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - COUNTED DOWN 0
12:12:12.841 [] [main] DEBUG io.camunda.zeebe.stream - Close stream processor
12:12:12.841 [] [main] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:12.841 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Scheduled runnable io.camunda.zeebe.stream.impl.ProcessingScheduleServiceImpl$$Lambda$586/0x0000000800f90dd0@5fdd01e9 - delay PT1M
12:12:12.841 [] [main] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-StreamProcessor-1 set new state WAKING_UP from WAITING
12:12:12.841 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - ActorThread ACTIVE
12:12:12.841 [] [main] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-StreamProcessor-1
12:12:12.841 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:12.841 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:12.841 [] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:12.841 [] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-StreamProcessor-1
12:12:12.841 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:12.842 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor set new state WAKING_UP from WAITING
12:12:12.842 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:12.842 [] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:12.842 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:12.842 [] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:12.842 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:12.842 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:12.842 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:12.842 [] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-StreamProcessor-1
12:12:12.842 [Broker-0-LogStream-1] [-zb-actors-3] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:12.842 [Broker-0-StreamProcessor-1] [-zb-actors-3] DEBUG io.camunda.zeebe.logstreams - Closed stream processor controller Broker-0-StreamProcessor-1.
12:12:12.869 [] [main] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:12.869 [] [main] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:12.869 [] [main] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:12.869 [Broker-0-LogStream-1] [-zb-actors-1] INFO io.camunda.zeebe.logstreams - Close appender for log stream stream-1
12:12:12.869 [Broker-0-LogStream-1] [-zb-actors-1] INFO io.camunda.zeebe.logstreams.impl.log.Sequencer - Closing sequencer for writing
12:12:12.869 [Broker-0-LogStream-1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogAppender-1
12:12:12.869 [Broker-0-LogStream-1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogAppender-1 set new state WAKING_UP from WAITING
12:12:12.869 [Broker-0-LogStream-1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogAppender-1
12:12:12.869 [Broker-0-LogStream-1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:12.869 [] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogAppender-1
12:12:12.869 [] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogAppender-1
12:12:12.869 [Broker-0-LogAppender-1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:12.869 [Broker-0-LogAppender-1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:12.869 [Broker-0-LogAppender-1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:12.869 [Broker-0-LogStream-1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:12.869 [Broker-0-LogStream-1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:12.869 [] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:12.869 [Broker-0-LogStream-1] [-zb-actors-1] INFO io.camunda.zeebe.logstreams - On closing logstream stream-1 close 1 readers
12:12:12.869 [] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:12.869 [] [main] DEBUG io.camunda.zeebe.util.actor - Closing actor thread ground '-zb-fs-workers'
12:12:12.870 [] [main] DEBUG io.camunda.zeebe.util.actor - Closing actor thread ground '-zb-actors'
12:12:12.870 [] [-zb-fs-workers-1] DEBUG io.camunda.zeebe.util.actor - Closing actor thread ground '-zb-fs-workers': closed successfully
12:12:12.871 [] [-zb-actors-10] DEBUG io.camunda.zeebe.util.actor - Closing actor thread ground '-zb-actors': closed successfully
org.awaitility.core.ConditionTimeoutException: Condition with alias 'ProcessScheduleService should still work' didn't complete within 5 seconds because condition with io.camunda.zeebe.stream.impl.StreamProcessorTest was not fulfilled.
at org.awaitility.core.ConditionAwaiter.await(ConditionAwaiter.java:167)
at org.awaitility.core.CallableCondition.await(CallableCondition.java:78)
at org.awaitility.core.CallableCondition.await(CallableCondition.java:26)
at org.awaitility.core.ConditionFactory.until(ConditionFactory.java:985)
at org.awaitility.core.ConditionFactory.until(ConditionFactory.java:954)
at io.camunda.zeebe.stream.impl.StreamProcessorTest.shouldRunAsyncSchedulingEvenIfProcessingIsBlocked(StreamProcessorTest.java:530)
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.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:727)
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.interceptTestMethod(TimeoutExtension.java:86)
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:217)
at org.junit.platform.engine.support.hierarchical.ThrowableCollector.execute(ThrowableCollector.java:73)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.invokeTestMethod(TestMethodTestDescriptor.java:213)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:138)
at org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor.execute(TestMethodTestDescriptor.java:68)
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:1511)
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:1511)
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: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.junit.platform.launcher.core.SessionPerRequestLauncher.execute(SessionPerRequestLauncher.java:53)
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:30)
at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:35)
at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:235)
at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:54)
Caused by: java.util.concurrent.TimeoutException
at java.base/java.util.concurrent.FutureTask.get(FutureTask.java:204)
at org.awaitility.core.Uninterruptibles.getUninterruptibly(Uninterruptibles.java:101)
at org.awaitility.core.Uninterruptibles.getUninterruptibly(Uninterruptibles.java:81)
at org.awaitility.core.ConditionAwaiter.await(ConditionAwaiter.java:103)
... 75 more
In contrast to the succeeding test run where the scheduling happens on a different thread.
Succeed test run
12:12:07.578 [io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1] [-zb-actors-2] ERROR io.camunda.zeebe.util.actor - Start waiting - io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1
12:12:07.578 [Broker-0-LogStream-1] [-zb-actors-10] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1
12:12:07.579 [io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1] [-zb-actors-2] ERROR io.camunda.zeebe.util.actor - Actor io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1 set new state WAKING_UP from WAITING
12:12:07.579 [] [-zb-actors-10] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.579 [] [-zb-actors-2] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1
12:12:07.579 [Broker-0-LogStream-1] [-zb-actors-10] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.579 [io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1] [-zb-actors-2] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1
12:12:07.579 [] [-zb-actors-2] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1
12:12:07.579 [io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1] [-zb-actors-10] ERROR io.camunda.zeebe.util.actor - Start waiting - io.camunda.zeebe.logstreams.util.SyncLogStreamBuilder$1
12:12:07.608 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.608 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:07.608 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.608 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-StreamProcessor-1
12:12:07.608 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:07.608 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-StreamProcessor-1 set new state WAKING_UP from WAITING
12:12:07.608 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-StreamProcessor-1
12:12:07.608 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.608 [] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-StreamProcessor-1
12:12:07.608 [Broker-0-StreamProcessor-1] [-zb-actors-9] DEBUG io.camunda.zeebe.logstreams - Recovering state of partition 1 from snapshot
12:12:07.608 [Broker-0-StreamProcessor-1] [-zb-actors-9] INFO io.camunda.zeebe.logstreams - Recovered state of partition 1 from snapshot at position -1
12:12:07.609 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Scheduled runnable io.camunda.zeebe.stream.impl.StreamProcessor$$Lambda$530/0x0000000800f72ed0@301bcb3b - delay PT5S
12:12:07.609 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - ActorThread ACTIVE
12:12:07.609 [Broker-0-StreamProcessor-1] [-zb-actors-9] INFO io.camunda.zeebe.processor - Processor starts replay of events. [snapshot-position: -1, replay-mode: PROCESSING]
12:12:07.609 [Broker-0-StreamProcessor-1] [-zb-actors-9] INFO io.camunda.zeebe.processor - Processor finished replay, with [lastProcessedPosition: -1, lastWrittenPosition: -1]
12:12:07.609 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.609 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:07.609 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.609 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-StreamProcessor-1
12:12:07.609 [Broker-0-LogStream-1] [-zb-actors-9] TRACE io.camunda.zeebe.logstreams.impl.log.Sequencer - Starting new sequencer at position 1
12:12:07.609 [Broker-0-LogStream-1] [-zb-actors-9] DEBUG io.camunda.zeebe.logstreams.impl.flowcontrol.AppenderFlowControl - Configured log appender back pressure as BackpressureCfgVegas{initialLimit=1024, maxConcurrency=32768, alphaLimit=0.7, betaLimit=0.95}. Window limiting is disabled
12:12:07.610 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.610 [Broker-0-LogAppender-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogAppender-1
12:12:07.610 [Broker-0-LogAppender-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.610 [Broker-0-LogAppender-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:07.610 [Broker-0-LogAppender-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.610 [] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogAppender-1
12:12:07.610 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.610 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogAppender-1
12:12:07.610 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:07.610 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-StreamProcessor-1 set new state WAKING_UP from WAITING
12:12:07.610 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-StreamProcessor-1
12:12:07.610 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.610 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.610 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:07.610 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.610 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-StreamProcessor-1
12:12:07.610 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:07.610 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-StreamProcessor-1 set new state WAKING_UP from WAITING
12:12:07.610 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-StreamProcessor-1
12:12:07.610 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.610 [Broker-0-LogAppender-1] [-zb-actors-5] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogAppender-1
12:12:07.610 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:07.610 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-StreamProcessor-1
12:12:07.610 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-5] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.610 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-5] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:07.610 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-5] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.610 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.610 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-5] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.610 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.610 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-5] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:07.610 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-5] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-StreamProcessor-1 set new state WAKING_UP from WAITING
12:12:07.610 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-5] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-StreamProcessor-1
12:12:07.610 [] [-zb-actors-5] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.610 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-5] ERROR io.camunda.zeebe.util.actor - Start waiting - io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.610 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.610 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:07.610 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.611 [Broker-0-LogStream-1] [-zb-actors-12] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.611 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.611 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor set new state WAKING_UP from WAITING
12:12:07.611 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.611 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-12] ERROR io.camunda.zeebe.stream - SCHEDULE TASK ALTER
12:12:07.611 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:07.611 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-StreamProcessor-1
12:12:07.611 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-StreamProcessor-1 set new state WAKING_UP from WAITING
12:12:07.611 [] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-StreamProcessor-1
12:12:07.611 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-12] ERROR io.camunda.zeebe.util.actor - Scheduled runnable io.camunda.zeebe.stream.impl.ProcessingScheduleServiceImpl$$Lambda$586/0x0000000800f90dd0@2093c8d8 - delay PT1M
12:12:07.611 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-12] ERROR io.camunda.zeebe.util.actor - ActorThread ACTIVE
12:12:07.611 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-StreamProcessor-1
12:12:07.611 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-12] ERROR io.camunda.zeebe.util.actor - Start waiting - io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.618 [] [main] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.618 [] [main] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:07.618 [] [main] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.618 [Broker-0-LogStream-1] [-zb-actors-2] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.618 [] [main] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogAppender-1
12:12:07.619 [] [main] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogAppender-1 set new state WAKING_UP from WAITING
12:12:07.619 [] [main] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogAppender-1
12:12:07.619 [Broker-0-LogAppender-1] [-zb-actors-2] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.619 [Broker-0-LogAppender-1] [-zb-actors-2] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:07.619 [Broker-0-LogAppender-1] [-zb-actors-2] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.619 [Broker-0-LogAppender-1] [-zb-actors-2] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogAppender-1
12:12:07.619 [Broker-0-LogAppender-1] [-zb-actors-2] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogAppender-1
12:12:07.619 [Broker-0-LogAppender-1] [-zb-actors-2] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogAppender-1 set new state WAKING_UP from WAITING
12:12:07.619 [] [-zb-actors-2] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogAppender-1
12:12:07.619 [Broker-0-LogStream-1] [-zb-actors-2] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:07.619 [Broker-0-LogStream-1] [-zb-actors-2] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-StreamProcessor-1 set new state WAKING_UP from WAITING
12:12:07.619 [Broker-0-LogStream-1] [-zb-actors-2] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-StreamProcessor-1
12:12:07.619 [Broker-0-LogStream-1] [-zb-actors-2] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.619 [Broker-0-LogAppender-1] [-zb-actors-13] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogAppender-1
12:12:07.619 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Wait processing, actortask Broker-0-StreamProcessor-1 ACTIVE phase: STARTED
12:12:07.748 [] [-zb-actors-12] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.748 [] [-zb-actors-12] ERROR io.camunda.zeebe.util.actor - Actor io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor set new state WAKING_UP from WAITING
12:12:07.748 [] [-zb-actors-12] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.748 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-12] ERROR io.camunda.zeebe.util.actor - Scheduled Task, actortask io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor ACTIVE phase: STARTED
12:12:07.748 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-12] ERROR io.camunda.zeebe.util.actor - COUNT DOWN YO Clock: 2023-02-28T11:14:07.748Z
12:12:07.748 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-12] ERROR io.camunda.zeebe.util.actor - COUNTED DOWN 0
12:12:07.748 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-12] ERROR io.camunda.zeebe.util.actor - Scheduled runnable io.camunda.zeebe.stream.impl.ProcessingScheduleServiceImpl$$Lambda$586/0x0000000800f90dd0@24ac5812 - delay PT1M
12:12:07.748 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-12] ERROR io.camunda.zeebe.util.actor - ActorThread ACTIVE
12:12:07.748 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-12] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.748 [io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor] [-zb-actors-12] ERROR io.camunda.zeebe.util.actor - Start waiting - io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.748 [] [awaitility[ProcessScheduleService should still work]] ERROR io.camunda.zeebe.util.actor - Increase time Clock: 2023-02-28T11:14:07.748Z and await true
12:12:07.749 [] [main] ERROR io.camunda.zeebe.stream - WAIT LATCH COUNT DOWN
12:12:07.750 [] [main] DEBUG io.camunda.zeebe.stream - Close stream processor
12:12:07.750 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:07.750 [] [main] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-StreamProcessor-1
12:12:07.750 [Broker-0-StreamProcessor-1] [-zb-actors-9] DEBUG io.camunda.zeebe.scheduler.ActorTask - Discard job io.camunda.zeebe.scheduler.future.FutureContinuationRunnable QUEUED from fastLane of Actor Broker-0-StreamProcessor-1.
12:12:07.750 [] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-StreamProcessor-1
12:12:07.750 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.750 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor set new state WAKING_UP from WAITING
12:12:07.750 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.750 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.750 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:07.750 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.750 [Broker-0-StreamProcessor-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.750 [] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-StreamProcessor-1
12:12:07.750 [] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.750 [Broker-0-LogStream-1] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.750 [Broker-0-StreamProcessor-1] [-zb-actors-9] DEBUG io.camunda.zeebe.logstreams - Closed stream processor controller Broker-0-StreamProcessor-1.
12:12:07.750 [] [-zb-actors-9] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup io.camunda.zeebe.stream.impl.StreamProcessor$AsyncProcessingScheduleServiceActor
12:12:07.780 [] [main] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.780 [] [main] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:07.780 [] [main] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.780 [Broker-0-LogStream-1] [-zb-actors-1] INFO io.camunda.zeebe.logstreams - Close appender for log stream stream-1
12:12:07.781 [Broker-0-LogStream-1] [-zb-actors-1] INFO io.camunda.zeebe.logstreams.impl.log.Sequencer - Closing sequencer for writing
12:12:07.781 [Broker-0-LogStream-1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogAppender-1
12:12:07.781 [Broker-0-LogStream-1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogAppender-1 set new state WAKING_UP from WAITING
12:12:07.781 [Broker-0-LogStream-1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogAppender-1
12:12:07.781 [Broker-0-LogStream-1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Start waiting - Broker-0-LogStream-1
12:12:07.781 [] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogAppender-1
12:12:07.781 [] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogAppender-1
12:12:07.781 [Broker-0-LogAppender-1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.781 [Broker-0-LogAppender-1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Actor Broker-0-LogStream-1 set new state WAKING_UP from WAITING
12:12:07.781 [Broker-0-LogAppender-1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.781 [Broker-0-LogStream-1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.781 [Broker-0-LogStream-1] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Stop waiting - wakeup Broker-0-LogStream-1
12:12:07.781 [] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.781 [Broker-0-LogStream-1] [-zb-actors-1] INFO io.camunda.zeebe.logstreams - On closing logstream stream-1 close 1 readers
12:12:07.781 [] [-zb-actors-1] ERROR io.camunda.zeebe.util.actor - Resubmit - wakeup Broker-0-LogStream-1
12:12:07.781 [] [main] DEBUG io.camunda.zeebe.util.actor - Closing actor thread ground '-zb-fs-workers'
12:12:07.782 [] [main] DEBUG io.camunda.zeebe.util.actor - Closing actor thread ground '-zb-actors'
12:12:07.782 [] [-zb-fs-workers-0] DEBUG io.camunda.zeebe.util.actor - Closing actor thread ground '-zb-fs-workers': closed successfully
12:12:07.783 [] [-zb-actors-11] DEBUG io.camunda.zeebe.util.actor - Closing actor thread ground '-zb-actors': closed successfully
Environment:
- OS:
- Zeebe Version: all
- Configuration:
@Zelldon, why was the actor being "blocked" in the first place? Why was the actor thread not released in between?
why was the actor being "blocked" in the first place? Why was the actor thread not released in between?
@romansmirnov It was for a test: https://github.com/camunda/zeebe/issues/11847
Ah okay, but this seems to be an issue of the test itself, and it is not a bug in the actor itself. Or what I am missing?
I think this depends on how you define the API. In my opinion, I shouldn't be able to block the system or cause issues on different actors nor block them from doing their work if one actor is malicious and blocks.
... if one actor is malicious and blocks.
So, that means the test itself is malicious because it blocks. So, why we don't simply fix the malicious actor in the test? 😉 However, I understand the issue you are describing, but I still see it as a problem with the test case itself, and not as a bug in the actor.
Of course, nobody can avoid having malicious/blocking actors in all cases. But when an actor has been identified as "malicious" (and as "malicious" already suggests), the "malicious" actor itself should be fixed to avoid blocking behavior because it's not following Zeebe's programming model. Especially, when Zeebe controls the actors, and these actors are not externally managed.
Also, I am concerned about introducing a potentially shared data structure (like one timer queue) that requires concurrency control when submitting new timer jobs, etc.
Of course, nobody can avoid having malicious/blocking actors in all cases.
I think that's the point. We don't want to fix this for this one test where we noticed it. We want to fix it so that it is no longer a footgun. If we have a bug in an actor, the impact of that bug should be as narrow as possible. If the bug is that one actor job blocks forever, it should at worst occupy a thread forever. At least the other threads can continue running other actors. But right now, the impact of such a job is that it blocks the expiration of all timers that happened to be scheduled on the same thread. This seems bad to me.
There's also a deadlock scenario where an actor job waits for a condition that depends on the expiration of a timer. If the timer was scheduled on the same thread, the actor job is deadlocked because nothing will expire the timer and unblock the job.
So, that means the test itself is malicious because it blocks.
The test was on purpose written like this. We wanted to verify whether we can still schedule tasks, via the ProcessingScheduleService even if the Processor is not available ("busy"). This was done in a blocking way, since there is no other way to observe the behavior. This is not observable nor unit testable based on the current structure of our code and other things. This is not ideal, but this is where we are.
From the API perspective, there is no one preventing you from doing anything problematic/blocking. If the API allows it then it should be handled gracefully. Or it should disallow it in the first place. It is not transparent to the user of the API that a "blocking" actor might impact others.
Be aware "blocking" is here put to an extreme. It could also just be a slow actor, or io intense actor, which delays timers to work. This is especially an issue if we for example migrate Raft to actors and their timers are delayed because the thread (which contains the timer queue) is blocked with other work (even if we actually have enough threads available.) The problem is an implementation detail that should be fixed.
Especially, when Zeebe controls the actors, and these actors are not externally managed.
It is leaking to the outside, via the ProcessingScheduleService and due to the Exporter API so it is an issue that is no longer 100% under our control.
Also, I am concerned about introducing a potentially shared data structure (like one timer queue) that requires concurrency control when submitting new timer jobs, etc.
Right now (afaik) we haven't thought about it enough to fix/resolve it.
Right now (afaik) we haven't thought about it enough to fix/resolve it.
Sorry, then I misunderstood the following 😉
Ideally we should have one TimerQueue or observer thread, which checks that queue and puts the due timers or jobs into the ActorTask. This allows to decouple this a bit more, and it is not necessary to check all the time the queues and maintain them in each thread.
However, please don't get me wrong, I understand the problem and the challenges you are describing. But I disagree that a potential bug fix (whatever it looks like) is a solution for all issues you described. The proposal might mitigate the situation but it doesn't solve the issue of a malicious actor. Also, if there is a malicious actor blocking an actor thread, there is a high probability that other actor threads will end up in the same situation, i.e., being blocked by the same actor logic (i.e., it might not be the same actor instance, but logically the same actor running on another actor thread). Of course, there is still a counter-probability that they don't end up in the same situation. And so on...
And I think this is not the point as we all will be able to construct much more of these cases as described above. The question is how likely they are, whether it is worth catching all/most of these cases and how many of these cases are actually because the user didn't use the API as intended (even if the code base does not enforce specific usage). I think we all agree that a "malicious" actor (being slow or blocking or whatever) is the root of the problem, that's why I believe the main focus should be to identify these "malicious" actors and fix them accordingly, for example:
- If the actor blocks, then this is a bug in the actor which needs to be fixed so that the actor releases the thread to do other work.
- If the user implemented a blocking actor when using the exporter API, then the users need to understand the root cause and fix their implementation. (Luckily the exporter API does not use CPU-bound actor threads, so they should not impact stream processing.)
- If the actor is slow because the RocksDB access is slow and by that delaying other work to be done, then the RocksDB access needs to be improved.
- ...
However, please don't get me wrong, I understand the problem and the challenges you are describing. But I disagree that a potential bug fix (whatever it looks like) is a solution for all issues you described. The proposal might mitigate the situation but it doesn't solve the issue of a malicious actor
IMO we shouldn't let perfect become the enemy of good here. The case of one actor having a bug, leading to a permanently blocking job doesn't sound unrealistic to me and would be mitigated if we find a solution where timers are not coupled to the thread they were scheduled on.
Also, if there is a malicious actor blocking an actor thread, there is a high probability that other actor threads will end up in the same situation
That's a valid (although unlikely because we usually only have a single instance of any actor) scenario that we just can't protect against, I agree there. But why should we let that stop us from mitigating the original scenario and removing a footgun?
If the user implemented a blocking actor when using the exporter API, then the users need to understand the root cause and fix their implementation.
That'd be great but I don't think it's realistic. Making the connection from "any actor might have bug that prevents a job from terminating" to "ah and that's why our healtcheck service / periodic snapshots or who knows what else didn't run as expected" is not obvious at all, especially not for customers implementing exporters or for the ZPA team implementing periodic tasks.
The deadlock case (actor job depends on result from timer execution) is even worse in that regard I think because it's not a local bug. My actor job can be bug and deadlock free but when another actor that I don't know about changes implementation details, for example starts using a retry strategy with time based backoff, my actor job suddenly deadlocks if workstealing results in an unlucky execution order and thread assignment.
ZDP-Planning:
- improving the resilience to such situations is useful to do to reduce the impact on the whole system of such situations
- put into backlog as it's not considered to be done timely though
Triage: @mustafadagher was there any more recent examples of this happening so that we can access the likelihood?
@rodrigo-lourenco-lopes No, not that I know of!
Excuse my ignorance, I was just going through the main epic for context to another topic when I saw these issue archived in w deprecated project.
Should I not move similar issues to the current project if I encounter similar ones?
Should I not move similar issues to the current project if I encounter similar ones?
for now, no need, if anything needs attention let's add it to the project which will cause it to be triaged, there is no need to migrate all without a reason.