Failing to write to logstream during stepdown is logged as error

[deepthidevaki]

Describe the bug

ERROR 2023-05-16T00:30:04.104402170Z [resource.labels.containerName: zeebe] Unexpected error on writing CREATE command Failed to write request to logstream

The error is from CommandAPIHandler when it tries to write a user request to the leader's logstream. This happened while the leader is transition to follower, and the logstream has already closed. Before this error we see that Sequencer rejects the record because it is closed.

This is a new error message introduced in #12676. Previously this error was ignored. So we never got the error message.

logs

Expected behavior

• Reduce the log level to warn/debug
• logstream#tryWrite should return specific error code instead of -1, and use that to log more meaningful message.
• If we can recognize that this is during the leader transition we can chose to not log the error. Instead return a PARTITION_LEADER_MISMATCH code back to the gateway so that it can retry the command with the new leader before sending an error to the client.

[megglos]

ZDP-Triage:

• mostly noise
• it's expected and shouldn't be logged as error in the particular scenario
• as it's new (last or next patch) it can be considered a regression => could be confusing after update

[megglos]

ZDP-Planning:

• we will look into it before the next release
• also affects 8.2,8.1,8.0 due to a backporrt

[Zelldon]

I feel this is not 100% resolved. We see a lot of errors messages also in the gateway, which is also in this case a lot of noise.

Example of a current medic benchmark

io.camunda.zeebe.gateway.cmd.BrokerErrorException: Received error from broker (INTERNAL_ERROR): Failed writing request: Failed to write request to logstream
	at io.camunda.zeebe.gateway.impl.broker.BrokerRequestManager.handleResponse(BrokerRequestManager.java:194) ~[zeebe-gateway-8.3.0-SNAPSHOT.jar:8.3.0-SNAPSHOT]
	at io.camunda.zeebe.gateway.impl.broker.BrokerRequestManager.lambda$sendRequestInternal$2(BrokerRequestManager.java:143) ~[zeebe-gateway-8.3.0-SNAPSHOT.jar:8.3.0-SNAPSHOT]
	at io.camunda.zeebe.scheduler.future.FutureContinuationRunnable.run(FutureContinuationRunnable.java:28) [zeebe-scheduler-8.3.0-SNAPSHOT.jar:8.3.0-SNAPSHOT]
	at io.camunda.zeebe.scheduler.ActorJob.invoke(ActorJob.java:94) [zeebe-scheduler-8.3.0-SNAPSHOT.jar:8.3.0-SNAPSHOT]
	at io.camunda.zeebe.scheduler.ActorJob.execute(ActorJob.java:45) [zeebe-scheduler-8.3.0-SNAPSHOT.jar:8.3.0-SNAPSHOT]
	at io.camunda.zeebe.scheduler.ActorTask.execute(ActorTask.java:119) [zeebe-scheduler-8.3.0-SNAPSHOT.jar:8.3.0-SNAPSHOT]
	at io.camunda.zeebe.scheduler.ActorThread.executeCurrentTask(ActorThread.java:106) [zeebe-scheduler-8.3.0-SNAPSHOT.jar:8.3.0-SNAPSHOT]
	at io.camunda.zeebe.scheduler.ActorThread.doWork(ActorThread.java:87) [zeebe-scheduler-8.3.0-SNAPSHOT.jar:8.3.0-SNAPSHOT]
	at io.camunda.zeebe.scheduler.ActorThread.run(ActorThread.java:198) [zeebe-scheduler-8.3.0-SNAPSHOT.jar:8.3.0-SNAPSHOT]
"

Where at this time a role change happens

[deepthidevaki]

@Zelldon That is an old benchmark before the bug fix.

[Zelldon]

Ups thanks @deepthidevaki you're right 👍