cadence-java-client icon indicating copy to clipboard operation
cadence-java-client copied to clipboard
verified publisher icon uber

Timeout when starting workflow with WorkflowClient.execute

Open doruchiulan opened this issue 5 years ago • 0 comments

Seems there's a bug when using JavaClient WorkflowClient.execute to start a new workflow async.

WorkflowClient.execute(workflow::start)

JavaClient version: <groupId>com.uber.cadence</groupId> <artifactId>cadence-client</artifactId> 2.7.1

Cadence container that i'm running: ubercadence/server:0.11.0-auto-setup

020-04-10 03:20:03.204  INFO 46272 --- [           main] c.u.c.s.WorkflowServiceTChannel          : Initialized TChannel for service cadence-frontend, LibraryVersion: UNKNOWN, FeatureVersion: 1.2.0
Domain "mesterache" is already registered
2020-04-10 03:20:03.627  INFO 46272 --- [           main] c.u.c.s.WorkflowServiceTChannel          : Initialized TChannel for service cadence-frontend, LibraryVersion: UNKNOWN, FeatureVersion: 1.2.0
2020-04-10 03:20:03.758  INFO 46272 --- [           main] com.uber.cadence.internal.worker.Poller  : start(): Poller{options=PollerOptions{maximumPollRateIntervalMilliseconds=1000, maximumPollRatePerSecond=0.0, pollBackoffCoefficient=2.0, pollBackoffInitialInterval=PT0.2S, pollBackoffMaximumInterval=PT20S, pollThreadCount=1, pollThreadNamePrefix='Workflow Poller taskList="HelloActivity", domain="mesterache"'}, [email protected]}
2020-04-10 03:20:03.763  INFO 46272 --- [           main] com.uber.cadence.internal.worker.Poller  : start(): Poller{options=PollerOptions{maximumPollRateIntervalMilliseconds=1000, maximumPollRatePerSecond=0.0, pollBackoffCoefficient=2.0, pollBackoffInitialInterval=PT0.2S, pollBackoffMaximumInterval=PT20S, pollThreadCount=1, pollThreadNamePrefix='Local Activity Poller taskList="HelloActivity", domain="mesterache"'}, [email protected]}
2020-04-10 03:20:03.766  INFO 46272 --- [           main] com.uber.cadence.internal.worker.Poller  : start(): Poller{options=PollerOptions{maximumPollRateIntervalMilliseconds=1000, maximumPollRatePerSecond=0.0, pollBackoffCoefficient=2.0, pollBackoffInitialInterval=PT0.2S, pollBackoffMaximumInterval=PT20S, pollThreadCount=1, pollThreadNamePrefix='Activity Poller taskList="HelloActivity", domain="mesterache"'}, [email protected]}
2020-04-10 03:20:03.766  INFO 46272 --- [           main] com.uber.cadence.internal.worker.Poller  : start(): Poller{options=PollerOptions{maximumPollRateIntervalMilliseconds=1000, maximumPollRatePerSecond=0.0, pollBackoffCoefficient=2.0, pollBackoffInitialInterval=PT0.2S, pollBackoffMaximumInterval=PT20S, pollThreadCount=1, pollThreadNamePrefix='null'}, identity=b0fe640e-e009-4a21-b605-2e7c0898c9a2}
2020-04-10 03:20:03.774  INFO 46272 --- [           main] c.u.c.s.WorkflowServiceTChannel          : Initialized TChannel for service cadence-frontend, LibraryVersion: UNKNOWN, FeatureVersion: 1.2.0
2020-04-10 03:20:04.901 ERROR 46272 --- [ool-13-thread-1] c.u.c.s.WorkflowServiceTChannel          : Unexpected error in GetWorkflowExecutionHistory

java.util.concurrent.CompletionException: org.apache.thrift.TException: Rpc error:<ErrorResponse id=2 errorType=Timeout message=Request timeout after 1008ms>
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:769) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:736) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977) ~[na:1.8.0_221]
	at com.uber.cadence.serviceclient.WorkflowServiceTChannel.lambda$doRemoteCallAsync$0(WorkflowServiceTChannel.java:534) ~[cadence-client-2.7.1.jar:na]
	at com.uber.tchannel.api.TFuture$1.onSuccess(TFuture.java:88) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.api.TFuture$1.onSuccess(TFuture.java:85) ~[tchannel-core-0.8.5.jar:na]
	at com.google.common.util.concurrent.Futures$CallbackListener.run(Futures.java:1021) ~[guava-28.1-jre.jar:na]
	at com.uber.tchannel.api.TFuture$2.run(TFuture.java:135) ~[tchannel-core-0.8.5.jar:na]
	at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30) ~[guava-28.1-jre.jar:na]
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137) ~[guava-28.1-jre.jar:na]
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957) ~[guava-28.1-jre.jar:na]
	at com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:726) ~[guava-28.1-jre.jar:na]
	at com.uber.tchannel.api.TFuture.set(TFuture.java:115) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.OutRequest.setResponseFuture(OutRequest.java:187) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.OutRequest.setFuture(OutRequest.java:157) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.OutRequest.setFuture(OutRequest.java:161) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.api.SubChannel.sendOutRequest(SubChannel.java:181) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.OutRequest.handleResponse(OutRequest.java:174) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.ResponseRouter.handleResponse(ResponseRouter.java:185) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.ResponseRouter$1.run(ResponseRouter.java:166) ~[tchannel-core-0.8.5.jar:na]
	at io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:672) ~[netty-common-4.1.45.Final.jar:4.1.45.Final]
	at io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:747) ~[netty-common-4.1.45.Final.jar:4.1.45.Final]
	at io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:472) ~[netty-common-4.1.45.Final.jar:4.1.45.Final]
	at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_221]
Caused by: org.apache.thrift.TException: Rpc error:<ErrorResponse id=2 errorType=Timeout message=Request timeout after 1008ms>
	... 21 common frames omitted

2020-04-10 03:20:06.406 ERROR 46272 --- [ool-13-thread-1] c.u.c.s.WorkflowServiceTChannel          : Unexpected error in GetWorkflowExecutionHistory

java.util.concurrent.CompletionException: org.apache.thrift.TException: Rpc error:<ErrorResponse id=3 errorType=Timeout message=Request timeout after 1008ms>
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:769) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:736) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977) ~[na:1.8.0_221]
	at com.uber.cadence.serviceclient.WorkflowServiceTChannel.lambda$doRemoteCallAsync$0(WorkflowServiceTChannel.java:534) ~[cadence-client-2.7.1.jar:na]
	at com.uber.tchannel.api.TFuture$1.onSuccess(TFuture.java:88) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.api.TFuture$1.onSuccess(TFuture.java:85) ~[tchannel-core-0.8.5.jar:na]
	at com.google.common.util.concurrent.Futures$CallbackListener.run(Futures.java:1021) ~[guava-28.1-jre.jar:na]
	at com.uber.tchannel.api.TFuture$2.run(TFuture.java:135) ~[tchannel-core-0.8.5.jar:na]
	at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30) ~[guava-28.1-jre.jar:na]
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137) ~[guava-28.1-jre.jar:na]
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957) ~[guava-28.1-jre.jar:na]
	at com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:726) ~[guava-28.1-jre.jar:na]
	at com.uber.tchannel.api.TFuture.set(TFuture.java:115) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.OutRequest.setResponseFuture(OutRequest.java:187) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.OutRequest.setFuture(OutRequest.java:157) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.OutRequest.setFuture(OutRequest.java:161) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.api.SubChannel.sendOutRequest(SubChannel.java:181) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.OutRequest.handleResponse(OutRequest.java:174) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.ResponseRouter.handleResponse(ResponseRouter.java:185) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.ResponseRouter$1.run(ResponseRouter.java:166) ~[tchannel-core-0.8.5.jar:na]
	at io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:672) ~[netty-common-4.1.45.Final.jar:4.1.45.Final]
	at io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:747) ~[netty-common-4.1.45.Final.jar:4.1.45.Final]
	at io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:472) ~[netty-common-4.1.45.Final.jar:4.1.45.Final]
	at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_221]
Caused by: org.apache.thrift.TException: Rpc error:<ErrorResponse id=3 errorType=Timeout message=Request timeout after 1008ms>
	... 21 common frames omitted

2020-04-10 03:20:08.417 ERROR 46272 --- [ool-13-thread-1] c.u.c.s.WorkflowServiceTChannel          : Unexpected error in GetWorkflowExecutionHistory

java.util.concurrent.CompletionException: org.apache.thrift.TException: Rpc error:<ErrorResponse id=4 errorType=Timeout message=Request timeout after 1009ms>
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:769) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:736) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977) ~[na:1.8.0_221]
	at com.uber.cadence.serviceclient.WorkflowServiceTChannel.lambda$doRemoteCallAsync$0(WorkflowServiceTChannel.java:534) ~[cadence-client-2.7.1.jar:na]
	at com.uber.tchannel.api.TFuture$1.onSuccess(TFuture.java:88) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.api.TFuture$1.onSuccess(TFuture.java:85) ~[tchannel-core-0.8.5.jar:na]
	at com.google.common.util.concurrent.Futures$CallbackListener.run(Futures.java:1021) ~[guava-28.1-jre.jar:na]
	at com.uber.tchannel.api.TFuture$2.run(TFuture.java:135) ~[tchannel-core-0.8.5.jar:na]
	at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30) ~[guava-28.1-jre.jar:na]
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137) ~[guava-28.1-jre.jar:na]
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957) ~[guava-28.1-jre.jar:na]
	at com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:726) ~[guava-28.1-jre.jar:na]
	at com.uber.tchannel.api.TFuture.set(TFuture.java:115) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.OutRequest.setResponseFuture(OutRequest.java:187) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.OutRequest.setFuture(OutRequest.java:157) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.OutRequest.setFuture(OutRequest.java:161) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.api.SubChannel.sendOutRequest(SubChannel.java:181) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.OutRequest.handleResponse(OutRequest.java:174) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.ResponseRouter.handleResponse(ResponseRouter.java:185) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.ResponseRouter$1.run(ResponseRouter.java:166) ~[tchannel-core-0.8.5.jar:na]
	at io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:672) ~[netty-common-4.1.45.Final.jar:4.1.45.Final]
	at io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:747) ~[netty-common-4.1.45.Final.jar:4.1.45.Final]
	at io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:472) ~[netty-common-4.1.45.Final.jar:4.1.45.Final]
	at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_221]
Caused by: org.apache.thrift.TException: Rpc error:<ErrorResponse id=4 errorType=Timeout message=Request timeout after 1009ms>
	... 21 common frames omitted

2020-04-10 03:20:11.426 ERROR 46272 --- [ool-13-thread-1] c.u.c.s.WorkflowServiceTChannel          : Unexpected error in GetWorkflowExecutionHistory

java.util.concurrent.CompletionException: org.apache.thrift.TException: Rpc error:<ErrorResponse id=5 errorType=Timeout message=Request timeout after 1005ms>
	at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:769) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:736) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474) ~[na:1.8.0_221]
	at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977) ~[na:1.8.0_221]
	at com.uber.cadence.serviceclient.WorkflowServiceTChannel.lambda$doRemoteCallAsync$0(WorkflowServiceTChannel.java:534) ~[cadence-client-2.7.1.jar:na]
	at com.uber.tchannel.api.TFuture$1.onSuccess(TFuture.java:88) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.api.TFuture$1.onSuccess(TFuture.java:85) ~[tchannel-core-0.8.5.jar:na]
	at com.google.common.util.concurrent.Futures$CallbackListener.run(Futures.java:1021) ~[guava-28.1-jre.jar:na]
	at com.uber.tchannel.api.TFuture$2.run(TFuture.java:135) ~[tchannel-core-0.8.5.jar:na]
	at com.google.common.util.concurrent.DirectExecutor.execute(DirectExecutor.java:30) ~[guava-28.1-jre.jar:na]
	at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:1137) ~[guava-28.1-jre.jar:na]
	at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:957) ~[guava-28.1-jre.jar:na]
	at com.google.common.util.concurrent.AbstractFuture.set(AbstractFuture.java:726) ~[guava-28.1-jre.jar:na]
	at com.uber.tchannel.api.TFuture.set(TFuture.java:115) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.OutRequest.setResponseFuture(OutRequest.java:187) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.OutRequest.setFuture(OutRequest.java:157) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.OutRequest.setFuture(OutRequest.java:161) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.api.SubChannel.sendOutRequest(SubChannel.java:181) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.OutRequest.handleResponse(OutRequest.java:174) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.ResponseRouter.handleResponse(ResponseRouter.java:185) ~[tchannel-core-0.8.5.jar:na]
	at com.uber.tchannel.handlers.ResponseRouter$1.run(ResponseRouter.java:166) ~[tchannel-core-0.8.5.jar:na]
	at io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:672) ~[netty-common-4.1.45.Final.jar:4.1.45.Final]
	at io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:747) ~[netty-common-4.1.45.Final.jar:4.1.45.Final]
	at io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:472) ~[netty-common-4.1.45.Final.jar:4.1.45.Final]
	at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_221]
Caused by: org.apache.thrift.TException: Rpc error:<ErrorResponse id=5 errorType=Timeout message=Request timeout after 1005ms>
	... 21 common frames omitted

Sending accept offer signal // Here is some signal I send which is logged.. so workflow starts following these first logged errors
[8a585846-09c4-4991-b6f3-4fd61964d854] I'm done, found new job. // Workflow ends here

doruchiulan avatar Apr 10 '20 00:04 doruchiulan