java.lang.IllegalStateException: call already closed

[korthout]

Describe the bug
Gateway was unable to inform go client of RESOURCE_EXHAUSTED error, because of GRPC: call already closed.

Also the go client was logging:

Failed to activate jobs for worker default rpc error: code = Unknown desc =

It might be related to #5179

To Reproduce
I have not yet reproduced it, but the user had the following set-up:

Go job worker:

handler := func(jclient worker.JobClient, job entities.Job) {
    fmt.Println("handling zeebe job")
  }
  worker := zbclient.NewJobWorker().
    JobType(starter.jobType).
    Handler(handler).
    Open()
  defer worker.Close()
  worker.AwaitClose()

A broker that is rejecting to activate jobs due to RESOURCE_EXHAUSTED (not directly seen, but considering io.zeebe.gateway.impl.job.LongPollingActivateJobsHandler.lambda$onCompleted$5(LongPollingActivateJobsHandler.java:144) ~[zeebe-gateway-0.24.3.jar:0.24.3] this appears to be the case.

Expected behavior
I expected a clear message logged by the go client, that the request to activate jobs was rejected by the broker due to resource exhausted.

Log/Stacktrace

Full Stacktrace

java.lang.IllegalStateException: call already closed
	at com.google.common.base.Preconditions.checkState(Preconditions.java:508) ~[guava-29.0-jre.jar:?]
	at io.grpc.internal.ServerCallImpl.closeInternal(ServerCallImpl.java:209) ~[grpc-core-1.30.2.jar:1.30.2]
	at io.grpc.internal.ServerCallImpl.close(ServerCallImpl.java:202) ~[grpc-core-1.30.2.jar:1.30.2]
	at io.grpc.stub.ServerCalls$ServerCallStreamObserverImpl.onError(ServerCalls.java:360) ~[grpc-stub-1.30.2.jar:1.30.2]
	at io.zeebe.gateway.impl.job.LongPollingActivateJobsHandler.lambda$onCompleted$5(LongPollingActivateJobsHandler.java:144) ~[zeebe-gateway-0.24.3.jar:0.24.3]
	at io.zeebe.util.sched.ActorJob.invoke(ActorJob.java:73) ~[zeebe-util-0.24.3.jar:0.24.3]
	at io.zeebe.util.sched.ActorJob.execute(ActorJob.java:39) [zeebe-util-0.24.3.jar:0.24.3]
	at io.zeebe.util.sched.ActorTask.execute(ActorTask.java:118) [zeebe-util-0.24.3.jar:0.24.3]
	at io.zeebe.util.sched.ActorThread.executeCurrentTask(ActorThread.java:107) [zeebe-util-0.24.3.jar:0.24.3]
	at io.zeebe.util.sched.ActorThread.doWork(ActorThread.java:91) [zeebe-util-0.24.3.jar:0.24.3]
	at io.zeebe.util.sched.ActorThread.run(ActorThread.java:204) [zeebe-util-0.24.3.jar:0.24.3]

Environment:

• OS: k8s (looked like gke)
• Zeebe Version: 0.24.3
• Configuration: set-up using helm chart
• Clients: go client

[npepinpe]

Can you check if this is a duplicate of #5187 ? That was already merged but not yet released (only released in 0.25.0-alpha2 yet).

[korthout]

@npepinpe Yes this should be resolved with #5228, since the same exact line of code is executed (i.e. io.zeebe.gateway.impl.job.LongPollingActivateJobsHandler.lambda$onCompleted$5(LongPollingActivateJobsHandler.java:144) ~[zeebe-gateway-0.24.3.jar:0.24.3]).

Reading that PR makes me think: Instead of responding Expected to activate jobs of type '%s', but no jobs available and at least one broker returned 'RESOURCE_EXHAUSTED'. Please try again later., shouldn't we just back off from the exhausted broker and keep trying the others? Only when all brokers are exhausted the gateway should tell the client to backoff

[deepthidevaki]

This occurs again in 0.25.0.
log

java.lang.IllegalStateException: call already closed

        at com.google.common.base.Preconditions.checkState (Preconditions.java:508)
        at io.grpc.internal.ServerCallImpl.closeInternal (ServerCallImpl.java:209)
        at io.grpc.internal.ServerCallImpl.close (ServerCallImpl.java:202)
        at io.grpc.stub.ServerCalls$ServerCallStreamObserverImpl.onError (ServerCalls.java:374)
        at io.zeebe.gateway.grpc.ErrorMappingStreamObserver.onError (ErrorMappingStreamObserver.java:105)
        at io.zeebe.gateway.impl.job.LongPollingActivateJobsHandler.lambda$onCompleted$5 (LongPollingActivateJobsHandler.java:152)
        at io.zeebe.util.sched.ActorJob.invoke (ActorJob.java:73)
        at io.zeebe.util.sched.ActorJob.execute (ActorJob.java:39)
        at io.zeebe.util.sched.ActorTask.execute (ActorTask.java:122)
        at io.zeebe.util.sched.ActorThread.executeCurrentTask (ActorThread.java:107)
        at io.zeebe.util.sched.ActorThread.doWork (ActorThread.java:91)
        at io.zeebe.util.sched.ActorThread.run (ActorThread.java:204)

It indicates that client has closed the connection. It might have happened because of a real network issue or client has crashed or shutdown. Other possibility is that grpc connection timeout is not long enough to include the longpolling timeout. Hence the connection get closed before long polling connection is closed.

[npepinpe]

I would imagine in most cases it's safe to ignore that the call was already closed, especially in the onError case. On response, we might want to do something (e.g. re-activate jobs?), but that's out of scope here. If we can verify that IllegalStateException is only thrown when the call was already closed, then we could catch it and simply log it at a lower level. First we could possibly look at how the framework authors expect us to handle it, there might be a nicer way to handle this already built-in.

[npepinpe]

Tentatively fixed by the same fix as #3631 (at least for the most pervasive case). Please open a new issue if this occur server side, as this was originally a client side issue which was reopened for a similar server side issue.