TestWorkflowEnvironment#sleep hangs indefinitely #2670
Description
Actual Behavior
Under certain execution path io.temporal.testing.TestWorkflowEnvironment#sleep hangs indefinitely.
Steps to Reproduce the Problem
Please have a look at https://github.com/rpost/temporal-java-sdk-bug-2670/blob/main/src/test/java/com/example/temporalsleepbug/TemporalSleepBugApplicationTests.java
Execution stops at https://github.com/rpost/temporal-java-sdk-bug-2670/blob/main/src/test/java/com/example/temporalsleepbug/TemporalSleepBugApplicationTests.java#L52 and never finishes.
Thread dump shows:
"main" #1 [1711914] prio=5 os_prio=0 cpu=2324,38ms elapsed=23,31s tid=0x00007cac5c033e30 nid=1711914 waiting on condition [0x00007cac60512000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@21.0.7/Native Method)
- parking to wait for <0x00000002b9220bc8> (a io.grpc.stub.ClientCalls$ThreadlessExecutor)
at java.util.concurrent.locks.LockSupport.park(java.base@21.0.7/LockSupport.java:221)
at io.grpc.stub.ClientCalls$ThreadlessExecutor.waitAndDrain(ClientCalls.java:717)
at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:159)
at io.temporal.api.testservice.v1.TestServiceGrpc$TestServiceBlockingStub.unlockTimeSkippingWithSleep(TestServiceGrpc.java:586)
at io.temporal.testing.TestWorkflowEnvironmentInternal.sleep(TestWorkflowEnvironmentInternal.java:165)
at com.example.temporalsleepbug.TemporalSleepBugApplicationTests.shouldExecuteWorkflow(TemporalSleepBugApplicationTests.java:52)
at java.lang.invoke.LambdaForm$DMH/0x00007cabc8170800.invokeVirtual(java.base@21.0.7/LambdaForm$DMH)
at java.lang.invoke.LambdaForm$MH/0x00007cabc86b8000.invoke(java.base@21.0.7/LambdaForm$MH)
at java.lang.invoke.Invokers$Holder.invokeExact_MT(java.base@21.0.7/Invokers$Holder)
at jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(java.base@21.0.7/DirectMethodHandleAccessor.java:153)
at jdk.internal.reflect.DirectMethodHandleAccessor.invoke(java.base@21.0.7/DirectMethodHandleAccessor.java:103)
at java.lang.reflect.Method.invoke(java.base@21.0.7/Method.java:580)
at org.junit.platform.commons.util.ReflectionUtils.invokeMethod(ReflectionUtils.java:775)
....
"workflow-method-SubscriberTerminationWorkflow-1234-84b7b4fc-bea0-42f3-a168-fb8ebac7c408" #71 [1712086] prio=5 os_prio=0 cpu=4,69ms elapsed=20,45s tid=0x00007caaf80059f0 nid=1712086 waiting on condition [0x00007cac14629000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@21.0.7/Native Method)
- parking to wait for <0x00000007ffd017e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(java.base@21.0.7/LockSupport.java:371)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(java.base@21.0.7/AbstractQueuedSynchronizer.java:519)
at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@21.0.7/ForkJoinPool.java:3780)
at java.util.concurrent.ForkJoinPool.managedBlock(java.base@21.0.7/ForkJoinPool.java:3725)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(java.base@21.0.7/AbstractQueuedSynchronizer.java:1712)
at io.temporal.internal.sync.WorkflowThreadScheduler.yieldLocked(WorkflowThreadScheduler.java:37)
at io.temporal.internal.sync.WorkflowThreadContext.yield(WorkflowThreadContext.java:70)
at io.temporal.internal.sync.WorkflowThreadImpl.yield(WorkflowThreadImpl.java:378)
at io.temporal.internal.sync.WorkflowThread.await(WorkflowThread.java:27)
at io.temporal.internal.sync.SyncWorkflowContext.await(SyncWorkflowContext.java:1290)
at io.temporal.internal.sync.WorkflowInternal.await(WorkflowInternal.java:510)
at io.temporal.workflow.Workflow.await(Workflow.java:611)
at com.example.temporalsleepbug.SubscriberTerminationWorkflow$SubscriberTerminationWorkflowImpl.execute(SubscriberTerminationWorkflow.java:25)
at java.lang.invoke.LambdaForm$DMH/0x00007cabc8778000.invokeInterface(java.base@21.0.7/LambdaForm$DMH)
at java.lang.invoke.LambdaForm$MH/0x00007cabc8778c00.invoke(java.base@21.0.7/LambdaForm$MH)
at java.lang.invoke.Invokers$Holder.invokeExact_MT(java.base@21.0.7/Invokers$Holder)
at jdk.internal.reflect.DirectMethodHandleAccessor.invokeImpl(java.base@21.0.7/DirectMethodHandleAccessor.java:154)
at jdk.internal.reflect.DirectMethodHandleAccessor.invoke(java.base@21.0.7/DirectMethodHandleAccessor.java:103)
at java.lang.reflect.Method.invoke(java.base@21.0.7/Method.java:580)
at io.temporal.internal.sync.POJOWorkflowImplementationFactory$POJOWorkflowImplementation$RootWorkflowInboundCallsInterceptor.execute(POJOWorkflowImplementationFactory.java:406)
at io.temporal.internal.sync.POJOWorkflowImplementationFactory$POJOWorkflowImplementation.execute(POJOWorkflowImplementationFactory.java:354)
at io.temporal.internal.sync.WorkflowExecutionHandler.runWorkflowMethod(WorkflowExecutionHandler.java:51)
at io.temporal.internal.sync.SyncWorkflow.lambda$start$0(SyncWorkflow.java:122)
at io.temporal.internal.sync.SyncWorkflow$$Lambda/0x00007cabc8743860.run(Unknown Source)
at io.temporal.internal.sync.CancellationScopeImpl.run(CancellationScopeImpl.java:99)
at io.temporal.internal.sync.WorkflowThreadImpl$RunnableWrapper.run(WorkflowThreadImpl.java:92)
at io.temporal.worker.ActiveThreadReportingExecutor.lambda$submit$0(ActiveThreadReportingExecutor.java:34)
at io.temporal.worker.ActiveThreadReportingExecutor$$Lambda/0x00007cabc8741dc0.run(Unknown Source)
at java.util.concurrent.Executors$RunnableAdapter.call(java.base@21.0.7/Executors.java:572)
at java.util.concurrent.FutureTask.run$$$capture(java.base@21.0.7/FutureTask.java:317)
at java.util.concurrent.FutureTask.run(java.base@21.0.7/FutureTask.java)
at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@21.0.7/ThreadPoolExecutor.java:1144)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@21.0.7/ThreadPoolExecutor.java:642)
at java.lang.Thread.runWith(java.base@21.0.7/Thread.java:1596)
at java.lang.Thread.run(java.base@21.0.7/Thread.java:1583)
"grpc-default-executor-5" #63 [1712078] daemon prio=5 os_prio=0 cpu=134,75ms elapsed=20,72s tid=0x00007cac5fec8ce0 nid=1712078 waiting on condition [0x00007cac14e2a000]
java.lang.Thread.State: WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@21.0.7/Native Method)
- parking to wait for <0x00000002b9358e08> (a java.util.concurrent.CompletableFuture$Signaller)
at java.util.concurrent.locks.LockSupport.park(java.base@21.0.7/LockSupport.java:221)
at java.util.concurrent.CompletableFuture$Signaller.block(java.base@21.0.7/CompletableFuture.java:1864)
at java.util.concurrent.ForkJoinPool.unmanagedBlock(java.base@21.0.7/ForkJoinPool.java:3780)
at java.util.concurrent.ForkJoinPool.managedBlock(java.base@21.0.7/ForkJoinPool.java:3725)
at java.util.concurrent.CompletableFuture.waitingGet(java.base@21.0.7/CompletableFuture.java:1898)
at java.util.concurrent.CompletableFuture.get(java.base@21.0.7/CompletableFuture.java:2072)
at io.temporal.internal.testservice.TestService.unlockTimeSkippingWhileSleep(TestService.java:126)
at io.temporal.internal.testservice.TestService.unlockTimeSkippingWithSleep(TestService.java:95)
at io.temporal.api.testservice.v1.TestServiceGrpc$MethodHandlers.invoke(TestServiceGrpc.java:747)
at io.grpc.stub.ServerCalls$UnaryServerCallHandler$UnaryServerCallListener.onHalfClose(ServerCalls.java:182)
at io.grpc.PartialForwardingServerCallListener.onHalfClose(PartialForwardingServerCallListener.java:35)
at io.grpc.ForwardingServerCallListener.onHalfClose(ForwardingServerCallListener.java:23)
at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.halfClosed(ServerCallImpl.java:351)
at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed.runInContext(ServerImpl.java:860)
at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:133)
at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@21.0.7/ThreadPoolExecutor.java:1144)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@21.0.7/ThreadPoolExecutor.java:642)
at java.lang.Thread.runWith(java.base@21.0.7/Thread.java:1596)
at java.lang.Thread.run(java.base@21.0.7/Thread.java:1583)
What is interesting is when I comment:
CreateCustomerWorkflow createCustomerWorkflow = workflowClient.newWorkflowStub(
CreateCustomerWorkflow.class,
WorkflowOptions.newBuilder()
.setWorkflowId(CreateCustomerWorkflow.class.getSimpleName() + "-" + 1234L)
.setTaskQueue(TemporalSleepBugApplication.TASK_QUEUE)
.build()
);
WorkflowClient.execute(createCustomerWorkflow::execute, 1234L);
Thread.sleep(5000); // let previous workflow completeout and leave only SubscriberTerminationWorkflow in test then everything runs fine, without deadlocks.
Specifications
- Version: 1.31.0
- Platform: n/a