Sometime Getting exception in zeebe broker and also zeebe client taking long time to complete it

Hi,

I am using the Zeebe 0.21.1 client and broker. sometimes i getting some weird exception in broker and also the client taking a longer time to pull/listen the request.

here is exception in zeebe broker

10/16/2019 12:15:26 PM2019-10-16 06:45:26.930 [io.zeebe.gateway.impl.job.LongPollingActivateJobsHandler] [10.42.37.204:26501-zb-actors-0] WARN  io.zeebe.gateway - Failed to complete io.zeebe.gateway.impl.broker.request.BrokerActivateJobsRequest@1fc07628
10/16/2019 12:15:26 PMio.grpc.StatusRuntimeException: CANCELLED: call already cancelled
10/16/2019 12:15:26 PM	at io.grpc.Status.asRuntimeException(Status.java:524) ~[grpc-api-1.24.0.jar:1.24.0]
10/16/2019 12:15:26 PM	at io.grpc.stub.ServerCalls$ServerCallStreamObserverImpl.onCompleted(ServerCalls.java:368) ~[grpc-stub-1.24.0.jar:1.24.0]
10/16/2019 12:15:26 PM	at io.zeebe.gateway.impl.job.LongPollingActivateJobsRequest.complete(LongPollingActivateJobsRequest.java:72) ~[zeebe-gateway-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.gateway.impl.job.LongPollingActivateJobsRequest.timeout(LongPollingActivateJobsRequest.java:94) ~[zeebe-gateway-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.gateway.impl.job.LongPollingActivateJobsHandler.lambda$addTimeOut$9(LongPollingActivateJobsHandler.java:176) ~[zeebe-gateway-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorJob.invoke(ActorJob.java:76) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorJob.execute(ActorJob.java:39) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorTask.execute(ActorTask.java:127) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorThread.executeCurrentTask(ActorThread.java:107) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorThread.doWork(ActorThread.java:91) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorThread.run(ActorThread.java:195) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM2019-10-16 06:45:26.931 [io.zeebe.gateway.impl.job.LongPollingActivateJobsHandler] [10.42.37.204:26501-zb-actors-0] WARN  io.zeebe.gateway - Failed to complete io.zeebe.gateway.impl.broker.request.BrokerActivateJobsRequest@50203f27
10/16/2019 12:15:26 PMio.grpc.StatusRuntimeException: CANCELLED: call already cancelled
10/16/2019 12:15:26 PM	at io.grpc.Status.asRuntimeException(Status.java:524) ~[grpc-api-1.24.0.jar:1.24.0]
10/16/2019 12:15:26 PM	at io.grpc.stub.ServerCalls$ServerCallStreamObserverImpl.onCompleted(ServerCalls.java:368) ~[grpc-stub-1.24.0.jar:1.24.0]
10/16/2019 12:15:26 PM	at io.zeebe.gateway.impl.job.LongPollingActivateJobsRequest.complete(LongPollingActivateJobsRequest.java:72) ~[zeebe-gateway-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.gateway.impl.job.LongPollingActivateJobsRequest.timeout(LongPollingActivateJobsRequest.java:94) ~[zeebe-gateway-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.gateway.impl.job.LongPollingActivateJobsHandler.lambda$addTimeOut$9(LongPollingActivateJobsHandler.java:176) ~[zeebe-gateway-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorJob.invoke(ActorJob.java:76) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorJob.execute(ActorJob.java:39) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorTask.execute(ActorTask.java:127) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorThread.executeCurrentTask(ActorThread.java:107) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorThread.doWork(ActorThread.java:91) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorThread.run(ActorThread.java:195) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM2019-10-16 06:45:26.940 [io.zeebe.gateway.impl.job.LongPollingActivateJobsHandler] [10.42.37.204:26501-zb-actors-1] WARN  io.zeebe.gateway - Failed to complete io.zeebe.gateway.impl.broker.request.BrokerActivateJobsRequest@5ced0b18
10/16/2019 12:15:26 PMio.grpc.StatusRuntimeException: CANCELLED: call already cancelled
10/16/2019 12:15:26 PM	at io.grpc.Status.asRuntimeException(Status.java:524) ~[grpc-api-1.24.0.jar:1.24.0]
10/16/2019 12:15:26 PM	at io.grpc.stub.ServerCalls$ServerCallStreamObserverImpl.onCompleted(ServerCalls.java:368) ~[grpc-stub-1.24.0.jar:1.24.0]
10/16/2019 12:15:26 PM	at io.zeebe.gateway.impl.job.LongPollingActivateJobsRequest.complete(LongPollingActivateJobsRequest.java:72) ~[zeebe-gateway-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.gateway.impl.job.LongPollingActivateJobsRequest.timeout(LongPollingActivateJobsRequest.java:94) ~[zeebe-gateway-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.gateway.impl.job.LongPollingActivateJobsHandler.lambda$addTimeOut$9(LongPollingActivateJobsHandler.java:176) ~[zeebe-gateway-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorJob.invoke(ActorJob.java:76) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorJob.execute(ActorJob.java:39) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorTask.execute(ActorTask.java:127) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorThread.executeCurrentTask(ActorThread.java:107) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorThread.doWork(ActorThread.java:91) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorThread.run(ActorThread.java:195) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM2019-10-16 06:45:26.941 [io.zeebe.gateway.impl.job.LongPollingActivateJobsHandler] [10.42.37.204:26501-zb-actors-1] WARN  io.zeebe.gateway - Failed to complete io.zeebe.gateway.impl.broker.request.BrokerActivateJobsRequest@69745aaa
10/16/2019 12:15:26 PMio.grpc.StatusRuntimeException: CANCELLED: call already cancelled
10/16/2019 12:15:26 PM	at io.grpc.Status.asRuntimeException(Status.java:524) ~[grpc-api-1.24.0.jar:1.24.0]
10/16/2019 12:15:26 PM	at io.grpc.stub.ServerCalls$ServerCallStreamObserverImpl.onCompleted(ServerCalls.java:368) ~[grpc-stub-1.24.0.jar:1.24.0]
10/16/2019 12:15:26 PM	at io.zeebe.gateway.impl.job.LongPollingActivateJobsRequest.complete(LongPollingActivateJobsRequest.java:72) ~[zeebe-gateway-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.gateway.impl.job.LongPollingActivateJobsRequest.timeout(LongPollingActivateJobsRequest.java:94) ~[zeebe-gateway-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.gateway.impl.job.LongPollingActivateJobsHandler.lambda$addTimeOut$9(LongPollingActivateJobsHandler.java:176) ~[zeebe-gateway-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorJob.invoke(ActorJob.java:76) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorJob.execute(ActorJob.java:39) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorTask.execute(ActorTask.java:127) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorThread.executeCurrentTask(ActorThread.java:107) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorThread.doWork(ActorThread.java:91) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM	at io.zeebe.util.sched.ActorThread.run(ActorThread.java:195) [zeebe-util-0.21.1.jar:0.21.1]
10/16/2019 12:15:26 PM2019-10-16 06:45:26.947 [io.zeebe.gateway.impl.job.LongPollingActivateJobsHandler] [10.42.37.204:26501-zb-actors-1] WARN  io.zeebe.gateway - Failed to complete io.zeebe.gateway.impl.broker.request.BrokerActivateJobsRequest@217c706c
10/16/2019 12:15:26 PMio.grpc.StatusRuntimeException: CANCELLED: call already cancelled

Hi @regojoyson this is interesting… can you help me to reproduce the problem?
When are you getting these exceptions? How did you notice the delay on the client side? How many workers do you have? Are you using Docker Compose?

Hi @salaboy,

here is my configurations:

 spring boot  :2.1.9.release 
   java            : OpenJDK 11
  zeebe            :0.21.1  docker

last week I upgraded zeebe 0.19.0 to 0.21.1. it’s in the development environment so I cleaned up all data also. Previously I am running zeebe for the past 1-month, till no issue but after upgrading, I am getting these issues.

this issue will come after certain service workers job is done. like if I have A, B, C, D jobs in workflow it works fine till A, B but in Step C it’s taking a minimum of 5 to 10 min of time then it will listen to the job and do the work. But there are no issues in client-side logs.

here is bpmn file : https://drive.google.com/file/d/1vKhXZzrSvqTx3hcN1tK7YyRaTloqhItq/view?usp=sharing

here is my client side code

Total Job works : 15

Config :

@Bean
	public ZeebeClient zeebe() {
		return ZeebeClient.newClientBuilder().brokerContactPoint(brokerContactPoint).usePlaintext().build();
	}


Listener :

@Component("complete-validation-Worker")
public class CompleteValidation extends AbstractWorker implements JobHandler {

	// Logger
	private static final Logger log = LoggerFactory.getLogger(CompleteValidation.class);

	/**
	 * Call after initiating the class
	 */
	@PostConstruct
	public void subscribe() {
		subscription = client.newWorker().jobType("CompleteValidationTask").handler(this)
				.open();
	}

	/**
	 * @see JobHandler#handle(JobClient, ActivatedJob)
	 */
	@Override
	public void handle(JobClient client, ActivatedJob job) {
		componentWorkflowHandlerService.completeFulfillmentItemValidation(client, job);
	}

	/**
	 * Call before destroying the class
	 */
	@PreDestroy
	public void closeSubscription() {
		subscription.close();
	}

}
``

Can you check how many instances of that @Bean you have ? You can do a printout on each @PostConstruct and then see the output… Just to make sure that you are not creating tons of those beans registering tons of subscribers.

Also, are you using Spring Boot? I would recommend to use the spring boot integration for creating workers and clients.

HTH

Salaboy

@salaboy

I printed the bean name in @PostConstruct it’s creating only one bean.

This error only comes in zeebe 0.21.1. actually i degraded zeebe to 0.20.1 due to this issue now its working fine.

Hi @regojoyson, this sounds like a bug. Open a GitHub issue for it - you’ll get the best results in getting it fixed fast if you produce a Minimal Reproducible Example in a GitHub repo, one where someone can git clone it, then run it with one or two commands from its README file.

1 Like

@jwulf
sure I will do that.

1 Like