TestWorkflowEnvironment#sleep hangs indefinitely

[rpost]

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 complete

out and leave only SubscriberTerminationWorkflow in test then everything runs fine, without deadlocks.

Specifications

• Version: 1.31.0
• Platform: n/a

[oleg-kovrizhin-paradym]

Looks like the same issue: #2642