TestWorkflowEnvironment#sleep hangs indefinitely

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

Start with the linked TemporalSleepBugApplicationTests.java reproduction, especially line 52, then trace TestWorkflowEnvironmentInternal.sleep through TestService.unlockTimeSkippingWithSleep and unlockTimeSkippingWhileSleep. Compare the behavior when both workflows run with the case where CreateCustomerWorkflow is removed. Done means the reproduction completes without the indefinite wait or deadlock.