Unhealthy partition in long running benchmark

[pihme]

Describe the bug

Partition 1 is unhalthy.

Observed in benchmark on non-preemptiable nodes: http://35.189.240.202/d/I4lo7_EZk/zeebe?orgId=1&refresh=10s&var-DS_PROMETHEUS=Prometheus&var-namespace=release-1-3-alpha1&var-pod=All&var-partition=All

Environment:

• Benchmark running on non-premptible nodes
• Zeebe Version: 1.3.0.alpha1

[pihme]

On first glance the same root cause as: #7862

There is still the question of why it does not recover. From the logs we can see that it is stuck an unable to transition to follower. Further investigation needed here.

[pihme]

Heap Dump: https://drive.google.com/file/d/1AghnhO5v2L7kcjeTxXL1904UL-ID8m5_/view?usp=sharing
Logs: https://drive.google.com/file/d/1bvweSi5bnKkJ5GxMHSAoKYYNpxF9LpjD/view?usp=sharing

[pihme]

Filtered log:

I 2021-11-30T10:48:46.109125039Z Transition to LEADER on term 1 completed 
I 2021-11-30T10:48:46.109162718Z Completed processing of migration tasks (use LogLevel.DEBUG for more details) ...  
D 2021-11-30T10:48:46.109574331Z Executed 0 migration tasks:  
D 2021-11-30T10:48:46.109716756Z Recovered exporter 'Broker-0-Exporter-1' from snapshot at lastExportedPosition -1 
D 2021-11-30T10:48:46.110122406Z Configure exporter with id 'elasticsearch' 
D 2021-11-30T10:48:46.110575759Z Exporter configured with ElasticsearchExporterConfiguration{url='http://elasticsearch-master:9200', index=IndexConfiguration{indexPrefix='zeebe-record', createTemplate=true, command=false, event=true, rejection=false, error=true, deployment=false, process=true, incident=true, job=true, message=false, messageSubscription=false, variable=true, variableDocument=true, processInstance=true, processInstanceCreation=false, processMessageSubscription=false}, bulk=BulkConfiguration{delay=5, size=1000, memoryLimit=10485760}} 
D 2021-11-30T10:48:46.111091495Z Configure exporter with id 'MetricsExporter' 
D 2021-11-30T10:48:46.111767390Z Set event filter for exporters: ExporterEventFilter{acceptRecordTypes={COMMAND=true, NULL_VAL=true, COMMAND_REJECTION=true, SBE_UNKNOWN=true, EVENT=true}, acceptValueTypes={SBE_UNKNOWN=true, PROCESS_INSTANCE=true, PROCESS_MESSAGE_SUBSCRIPTION=true, INCIDENT=true, ERROR=true, MESSAGE_SUBSCRIPTION=true, PROCESS_INSTANCE_RESULT=true, TIMER=true, PROCESS=true, MESSAGE_START_EVENT_SUBSCRIPTION=true, VARIABLE_DOCUMENT=true, MESSAGE=true, JOB_BATCH=true, PROCESS_EVENT=true, JOB=true, PROCESS_INSTANCE_CREATION=true, DEPLOYMENT_DISTRIBUTION=true, VARIABLE=true, NULL_VAL=true, DEPLOYMENT=true}} 
D 2021-11-30T10:48:46.112722114Z Open exporter with id 'elasticsearch' 
I 2021-11-30T10:48:46.114187182Z Exporter opened 
D 2021-11-30T10:48:46.115327838Z Open exporter with id 'MetricsExporter' 
D 2021-11-30T10:48:46.805993898Z Distribute deployment 2251799813685250 to partition 2. 
D 2021-11-30T10:48:46.813888588Z Distribute deployment 2251799813685250 to partition 3. 
E 2021-11-30T10:48:46.816926234Z Failed to append block with last event position 4. 
I 2021-11-30T10:48:46.824728815Z RaftServer{raft-partition-partition-1} - Transitioning to FOLLOWER 
E 2021-11-30T10:48:46.824783042Z Actor Broker-0-LogAppender-1 failed in phase STARTED. 
I 2021-11-30T10:48:46.826803125Z Close appender for log stream logstream-raft-partition-partition-1 
W 2021-11-30T10:48:46.827689214Z logstream-raft-partition-partition-1 failed, marking it as unhealthy 
I 2021-11-30T10:48:46.828325797Z On closing logstream logstream-raft-partition-partition-1 close 2 readers 
D 2021-11-30T10:48:46.828627052Z Detected 'UNHEALTHY' components. The current health status of components: {ZeebePartition-1=HEALTHY, raft-partition-partition-1=HEALTHY, Broker-0-Exporter-1=HEALTHY, Broker-0-StreamProcessor-1=HEALTHY, logstream-raft-partition-partition-1=UNHEALTHY, Broker-0-SnapshotDirector-1=HEALTHY} 
I 2021-11-30T10:48:46.829435262Z Transition to FOLLOWER on term 1 requested. 
D 2021-11-30T10:48:46.829953936Z Paused processing for partition 1 
D 2021-11-30T10:48:46.830319037Z Partition role transitioning from LEADER to FOLLOWER in term 1 
I 2021-11-30T10:48:46.830745888Z Received cancel signal for transition to LEADER on term 1 
I 2021-11-30T10:48:46.831215316Z Prepare transition from FOLLOWER on term 1 to FOLLOWER 
I 2021-11-30T10:48:46.831709702Z Prepare transition from FOLLOWER on term 1 to FOLLOWER - preparing ExporterDirector 
D 2021-11-30T10:48:46.832470666Z Discard job io.camunda.zeebe.broker.exporter.stream.ExporterDirector$$Lambda$1804/0x000000080143bb90 QUEUED from fastLane of Actor Broker-0-Exporter-1. 
I 2021-11-30T10:48:46.833665375Z Exporter closed 
D 2021-11-30T10:48:46.834326892Z Closed exporter director 'Broker-0-Exporter-1'. 
I 2021-11-30T10:48:46.834799790Z Prepare transition from FOLLOWER on term 1 to FOLLOWER - preparing SnapshotDirector 
I 2021-11-30T10:48:46.835519298Z Prepare transition from FOLLOWER on term 1 to FOLLOWER - preparing StreamProcessor 
I 2021-11-30T10:48:49.514044943Z RaftServer{raft-partition-partition-1}{role=FOLLOWER} - Accepted PollRequest{term=1, candidate=1, lastLogIndex=2, lastLogTerm=1}: candidate's log is up-to-date 
I 2021-11-30T10:48:49.539957490Z RaftServer{raft-partition-partition-1}{role=FOLLOWER} - Accepted VoteRequest{term=2, candidate=1, lastLogIndex=2, lastLogTerm=1}: candidate's log is up-to-date 
I 2021-11-30T10:48:49.572570762Z RaftServer{raft-partition-partition-1} - Found leader 1 
I 2021-11-30T10:52:50.217881801Z RaftServer{raft-partition-partition-1}{role=FOLLOWER} - Started receiving new snapshot FileBasedReceivedSnapshot{directory=/usr/local/zeebe/data/raft-partition/partitions/1/pending/179061-2-535701-535154-1, snapshotStore=io.camunda.zeebe.snapshots.impl.FileBasedSnapshotStore@5781b566, metadata=FileBasedSnapshotMetadata{index=179061, term=2, processedPosition=535701, exporterPosition=535154}} from 1 
I 2021-11-30T10:52:50.219772959Z Transition to INACTIVE on term 1 requested. 
I 2021-11-30T10:52:50.220184722Z Received cancel signal for transition to FOLLOWER on term 1 
I 2021-11-30T10:52:50.324353127Z Committed new snapshot 179061-2-535701-535154 
D 2021-11-30T10:52:50.325461529Z Scheduling log compaction up to index 179061 
I 2021-11-30T10:52:50.326274496Z RaftServer{raft-partition-partition-1}{role=FOLLOWER} - Committed snapshot FileBasedSnapshot{directory=/usr/local/zeebe/data/raft-partition/partitions/1/snapshots/179061-2-535701-535154, checksumFile=/usr/local/zeebe/data/raft-partition/partitions/1/snapshots/179061-2-535701-535154.checksum, checksum=3340915422, metadata=FileBasedSnapshotMetadata{index=179061, term=2, processedPosition=535701, exporterPosition=535154}} 
I 2021-11-30T10:52:50.330511243Z RaftServer{raft-partition-partition-1}{role=FOLLOWER} - Delete existing log (lastIndex '173925') and replace with received snapshot (index '179061') 
I 2021-11-30T10:52:50.689038565Z Transition to FOLLOWER on term 2 requested. 

[pihme]

From looking at the logs and the heap dump (and thanks to the help by @deepthidevaki ) we were able to establish the following course of events:

• Last successful transition was to leader
• Shortly afterwards the log appender had an error. This actor shuts itself down when an error occurs. This actor is now in state closed
• Then a transition to follower was requested
• This transition got stuck in the prepare phase for the step preparing the stream processor
• "Stuck" means that the future of streamProcessor.closeAsync() was never completed
• We tried investigating further which step in the close process had failed, but it's hard to judge with a heap dump and we ran out of time.

[Zelldon]

Haven't looked at the code but thinking about your analysis and of the top of my head I think a closed actor makes sense to me to explain the stuck "scenario".

The logAppender is opened when we open a logstream writer. If we close the streamProcessor we want to close the writer and we can't do that since the actor is already in closed state.

So solution would be to handle the already closed actor, i think. But it feels like a general issue how we currently do the failure/error handling with actors and dependent actors. Ideally if an actor fails and there exist an dependency chain all dependent actors should be closed or handle that failure as well. This is again a topic we discussed several times I would say and is nothing new. I really would like to see an improvement in the current situation or some progress in regards to replacing the actor scheduler.

[npepinpe]

I would like to tackle this sooner than later, as in this case, for example, if partition 1 is unavailable for a long time then no deployments can occur, no timer start events, etc.

You mentioned that "we ran out of time" - what do you mean? Did we exhaust all leads/hypotheses we had?

[pihme]

No no, we just were cut off, because I had to go to another meeting. And we decided to put this up for prioritization before digging deeper.

[Zelldon]

Looking at the code it seems we already check whether the actor is closed

https://github.com/camunda-cloud/zeebe/blob/develop/logstreams/src/main/java/io/camunda/zeebe/logstreams/impl/log/LogStorageAppender.java#L163

and return the close future

[pihme]

I had another look at it, but honestly without Deepthi I am just lost. I looked through the shutdown logic of StreamProcessor and there is nothing that looks like it would be blocking or waiting for a future. As far as I can see, it closes the LogStreamReader which as a multi level cascade of resets. Then it removes listeners and waits for the replay state machine to close, which also just removes listeners.

The issue is not the LogStorageAppender, in my mind. The log storage appender for this partition has already been GC and is not available in the heap dump.

The actor that is stopped is the LogStreamImpl.

This is also the only piece which looks a bit fishy, to be honest. Because as part of the close of StraemProcessor we call

  private void tearDown() {
    processingContext.getLogStreamReader().close();
    logStream.removeRecordAvailableListener(this);
    replayStateMachine.close();
  }

which in turn calls:

  @Override
  public void removeRecordAvailableListener(final LogRecordAwaiter recordAwaiter) {
    actor.call(() -> recordAwaiters.remove(recordAwaiter));
  }

So we try to schedule a task on an actor that is already closed. I simply don't know what the behavior is in this case.

From the Java side none of that looks like blocking code. If anything, the task should not get executed.
Maybe this throws an exception? But then again a) I have not seen any exception like this in the log and b) the exception in my mind should not interrupt the shutdown.

Anyways, I think I cannot contribute much here.

[pihme]

Hint for troubleshooting: in HeapDump search for PartitionStartupAndTransitionContextImpl of partition 1. There you have a good access to the relevant actors.

[npepinpe]

To investigate further do we need the release-1.3.0-alpha1 benchmark, or have we extracted everything from it by now? I know I already asked, but just want to double check before I delete it 🙂

[pihme]

To the best of my knowledge we got everything we need. But if another engineer wants to do thread dumps or stuff like that, it might make sense to keep it running.

We do have an excerpt of the log and a heap dump.

[romansmirnov]

I had a quick look at the heap dump. Long story short, the actor is blocked by the execution of

https://github.com/camunda-cloud/zeebe/blob/b6a5d65a9a9103dc663afa03102d12c11bb1fcec/engine/src/main/java/io/camunda/zeebe/engine/processing/deployment/distribute/DeploymentDistributionBehavior.java#L83-L96

Actually, the stream processor for partition 1 is closed (i.e., StreamProcessor#isOpened == false) but the actor itself is not closed. The actor still is in the state STARTED.

Basically, StreamProcessor#closeAsync() (subsequently ActorControl#close()) submits an actor job which is not being executed so far. The actor job has not been executed, because the queue of submitted jobs in the actor is rather larger (and the closing actor job is most likely somewhere in between):

In total, there are 23.5k Actor jobs and most of them are submitted by the stream processor for partition 1:

The actor is currently executing an actor job submitted by DeploymentDistributedBehavior:

This actor job runs with #runUntilDone() which means the actor does not autocomplete the actor job and waits for a done signal. As long as the signal does not happen, it will execute the actor job over and over.

So far, I had no chance to look into the workflow-engine but to my understanding, the issue seems to be with DeploymentDistributedBehavior.

[Zelldon]

Makes sense if the logAppender is closed the dispatcher is not cleared which means the distributor cant write to the dispatcher and retries for ever.

[romansmirnov]

Yes, exactly! I had the same finding 😄

Maybe a (unrelated) comment to the previous observation (mentioned above):

This is also the only piece which looks a bit fishy, to be honest. Because as part of the close of StraemProcessor we call
...
So we try to schedule a task on an actor that is already closed. I simply don't know what the behavior is in this case.

This is actually not a problem, because the actor does not close immediately, i.e., the actor transitions from CLOSE_REQUESTED to CLOSING to CLOSED. Along with those transitions, any submitted actor jobs are executed.

[romansmirnov]

@Zelldon, actually, the dispatcher is closed

Since the dispatcher is closed, it will do nothing:

https://github.com/camunda-cloud/zeebe/blob/b6a5d65a9a9103dc663afa03102d12c11bb1fcec/dispatcher/src/main/java/io/camunda/zeebe/dispatcher/Dispatcher.java#L172-L209

[deepthidevaki]

Just as a side note: LogStream is closed because LogStorageAppender is "failed". May be it is not necessary to close LogStream, but only mark it as "unhealthy". LogStorageAppender will be closed anyway, so no harm (data consistency related) will be done even if new records are written to the dispatcher.

[npepinpe]

To summarize, if I understand correctly, the issue is with the runUntilDone behavior which will block the actor from closing until actor.done() is called (which it will not in this case because the dispatcher will always fail to write since it's closed), is that correct?

[npepinpe]

I'm wondering if we shouldn't have that requesting an actor to close short circuits this. Is there any reason why we want to ignore the close request in favor of running until done?

I'm also wondering if the runBlockingPhase should also be able to block the closing of the actor? We only use it in two instances (in StreamProcess#onActorStarting and ExporterDirector#onActorStarting), where it's arguable if we truly need this (at least for blocking the close of the actor).

Let's say we do allow short circuiting, what should be the behavior here? Right now, requesting close means the request is a job itself, and it's submitted at the end of the task queue for this actor. So if I had the following:

1. run(JobA)
2. run(JobB)
3. run(JobC)
4. close()
5. run(JobD)

Then the job queue is: fastLane => JobA, JobB, JobC, JobD, and submittedJobs => ActorTask::requestClose. Note that anything in the fast lane will take precedence over closing (since it's only a submitted job). When requestClose runs, it will discard the jobs after itself.

Intuitively, I would expect requesting the close would discard all jobs (and let the current one finish), and it would prevent an ongoing non-auto-completing job to be resubmitted. Jobs could still be enqueued in the closing/close phase, but runUntilDone would not be allowed (again to avoid locking the closing actor).

That said, my preference would be to just get rid of runUntilDone if possible at all, as it's easy to shoot yourself in the foot with it. The only use cases I think might be a bit more difficult to emulate are the retry strategies.

[lenaschoenburg]

👍 for getting rid of runUntilDone and simplifying the shutdown behavior. Especially the shutdown behavior is not intuitive and seems incidental.

[npepinpe]

Some notes from our discussion:

• Closing after fail hangs
  • Proposal: when calling ActorControl#fail(), immediately complete the future successful so subsequent close calls return a completed future.
• Closing while in a runUntilDone hangs
  • push/deployment usages probably not required
  • TODO: check if logstorageappender yieldThread is required
  • RetryStrategy usage: verify if can replace runUntilDone with normal run
    • ExporterDirector
    • ProcessingStateMachine
    • ReplayStateMachine
    • Removing this would affect the health check in StreamProcessor because the tick would happen even if we're in a loop
    • Proposal: replace runUntilDone with run (and reschedules). Requesting close means all jobs until the requestClose job is executed are rejected, and then we accept new jobs after.
• Closing while in a runOnCompletionBlockingPhase hangs
  • Postponed for now

I think my notes may be undecipherable if you weren't there, so to sum up:

1. We'll ignore runOnCompletionBlockingPhase for now
2. One PR which marks the actor start/close future as completed exceptionally when you explicitly fail it or when an uncaught exception is thrown.
3. One PR which replaces runUntilDone with just run usages (e.g. yieldThread becomes another run call, and markAsDone() simply doesn't schedule anything else). The hope is reusing run will keep the same semantics as now. The actors which use runUntilDone anyway already have to keep track of their state as jobs may be interleaved, so it shouldn't affect them.
4. One PR which will cause requesting to close to prevent submitting new jobs (both via run and submit, or via future completions) until ActorTask#requestClose is ran, after which new jobs can be submitted again.

Hopefully this brings us closer to guaranteeing that closing always closes and we don't end up in loops.

[npepinpe]

Not closed yet! Sorry about that.

[npepinpe]

Regarding the last point, I tried different approaches, but they all required changing existing behavior more than we'd like. I'd rather make progress on holistic improvements we discussed before than improve the existing design, as mentioned in our team meeting. So I'll close this issue as done for now.