temporalio / temporalio/sdk-java

GRPC falling into in-process server long polls after interruption breaks graceful Worker Pollers shutdown

Open
#608 0 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

bug test server
Dominant language
Java
Stars
433
Forks
249
Avg merge
5d 6h
Merged PRs (30d)
26

Description

Problem

An investigation of flaky InterceptorsExceptionsTests#testExceptionOnStart test from https://github.com/temporalio/sdk-java/issues/455 ended up inside GRPC code that swallows InterruptedException in intention to perform a graceful shutdown, but instead peeking up a long poll task submitted by another poller thread (from another non-shutdown thread pool) and falling into a long poll inside in-memory GRPC server implementation. The stacktrace of the hanging Poller thread AFTER receiving an interruption:

"Host Local Workflow Poller: 5@3606" daemon prio=5 tid=0x1c nid=NA waiting
  java.lang.Thread.State: WAITING
	  at jdk.internal.misc.Unsafe.park(Unsafe.java:-1)
	  at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:252)
	  at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1661)
	  at java.util.concurrent.LinkedBlockingQueue.poll(LinkedBlockingQueue.java:460)
	  at io.temporal.internal.testservice.TestWorkflowStoreImpl.pollWorkflowTaskQueue(TestWorkflowStoreImpl.java:347)
	  at io.temporal.internal.testservice.TestWorkflowService.pollWorkflowTaskQueue(TestWorkflowService.java:448)
	  at io.temporal.api.workflowservice.v1.WorkflowServiceGrpc$MethodHandlers.invoke(WorkflowServiceGrpc.java:3625)
	  at io.grpc.stub.ServerCalls$UnaryServerCallHandler$UnaryServerCallListener.onHalfClose(ServerCalls.java:182)
	  at io.grpc.internal.ServerCallImpl$ServerStreamListenerImpl.halfClosed(ServerCallImpl.java:331)
	  at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener$1HalfClosed.runInContext(ServerImpl.java:797)
	  at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
	  at io.grpc.internal.SerializeReentrantCallsDirectExecutor.execute(SerializeReentrantCallsDirectExecutor.java:49)
	  at io.grpc.internal.ServerImpl$JumpToApplicationThreadServerStreamListener.halfClosed(ServerImpl.java:808)
	  at io.grpc.inprocess.InProcessTransport$InProcessStream$InProcessClientStream.halfClose(InProcessTransport.java:793)
	  - locked <0xf41> (a io.grpc.inprocess.InProcessTransport$InProcessStream$InProcessClientStream)
	  at io.grpc.internal.ForwardingClientStream.halfClose(ForwardingClientStream.java:72)
	  at io.grpc.internal.DelayedStream$9.run(DelayedStream.java:344)
	  at io.grpc.internal.DelayedStream.drainPendingCalls(DelayedStream.java:181)
	  at io.grpc.internal.DelayedStream.access$100(DelayedStream.java:43)
	  at io.grpc.internal.DelayedStream$4.run(DelayedStream.java:147)
	  at io.grpc.stub.ClientCalls$ThreadlessExecutor.waitAndDrain(ClientCalls.java:740)
	  at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:149)
	  at io.temporal.api.workflowservice.v1.WorkflowServiceGrpc$WorkflowServiceBlockingStub.pollWorkflowTaskQueue(WorkflowServiceGrpc.java:2639)
	  at io.temporal.internal.worker.WorkflowPollTask.poll(WorkflowPollTask.java:81)
	  at io.temporal.internal.worker.WorkflowPollTask.poll(WorkflowPollTask.java:37)
	  at io.temporal.internal.worker.Poller$PollExecutionTask.run(Poller.java:270)
	  at io.temporal.internal.worker.Poller$PollLoopTask.run(Poller.java:235)
	  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
	  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
	  at java.lang.Thread.run(Thread.java:832)

Partial notes made during an investigation

https://github.com/grpc/grpc-java/blob/9b803f3/stub/src/main/java/io/grpc/stub/ClientCalls.java#L149
GRPC catches the InterruptedException, puts it into a flag var, and goes to a new iteration of the loop. (based on comments waiting for “onClose” to be called)
What actually happens at the moment when we experience problems with shutdown - it finds a job that actually calls a long poll inside waitAndDrain, starts to execute it, and hangs there, because the interrupted status has been flushed.
This happens only in a case when a long-poll task ends up in this executor AFTER the thread is interrupted. A situation is likely to happen only when we shut down the environment right after the start. That’s why most tests are ok - they actually take stuff from the server, so long poll is already triggered.
I made a branch (https://github.com/Spikhalskiy/java-sdk/commit/f543651432f0f7d0173e2461ec00287219c91b12) where I threw a bunch of debug prints inside GRPC code around this waitAndDrain and it shows one more strange/unexpected thing - the long poll task that blocks the intercepted thread is put to the executor of interrupted Poller by another non-yet-interrupted Poller thread. Basically, we have an intercepted sticky poller thread and the non-intercepted workflow poller thread publishes a long poll task into the intercepted sticky poller executor.

Assumptions

It looks like this situation is only happening when we have a GRPC client + a GRPC in-process server that performs the long poll. Interruption in the client thread ends up ignored and a Poller thread falls into a long poll inside the in-process GRPC server implementation. Also, timing is very important for it, because the long poll task needs to be submitted right after threads get terminated.
We were unable to reproduce an issue with an actual dockerized Temporal server.
An investigation of this issue is not finished. The best bet right now is: it's a bug in GRPC happening when GRPC client & GRPC in-process server & long polls are used and the right timing is needed for the problem to reproduce.

Mitigation

Taking into account that further investigation of this issue is very time-consuming, we decided to mitigate the problem in this specific flaky test by triggering a shutdown of GRPC in-process Temporal server implementation before shutdown of workers. This way GRPC client doesn't have a long poll to fall into after getting an interception. This workaround is implemented in: https://github.com/temporalio/sdk-java/pull/601 and affects only tests code.
The last master commit where InterceptorsExceptionsTests#testExceptionOnStart is able to often reproduce the described problem is b4cbaa13f32590e2337a03305dfb6a0af6628bdc.

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start with InterceptorsExceptionsTests#testExceptionOnStart and the stack-trace entry points in WorkflowPollTask, Poller, TestWorkflowStoreImpl, and TestWorkflowService; compare behavior at commit b4cbaa13f32590e2337a03305dfb6a0af6628bdc. Reproduce the shutdown timing issue with the in-process gRPC server, then determine whether the poller shutdown can complete reliably without relying on the mitigation in PR 601.

Written by the indexing model from the issue text.

Assessment

Tech stack
grpc, java
Domain
backend, distributed-systems, testing-qa
Issue type
Bug
Difficulty
5/5
Estimated time
Over a week
Activity status
Stale
Clarity
Needs clarification
Newbie friendliness
25/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.