grpc-default-executor threads stop processing tasks: how can we troubleshoot in such situation?

[suztomo]

Do you know a good way to troubleshoot "grpc-default-executor" threads' status?

In apache/beam#14768 (comment), when I tried to upgrade Beam's vendored (shaded) gRPC dependency to 1.37.0 (or 1.36) from gRPC 1.26.0, I observed that some tests (GrpcLoggingServiceTest or BeamFnLoggingServiceTest randomly) do not finish. Borrowing Kenn's words, BeamFnLoggingServiceTest does the followings:

• start a logging service
• set up some stub clients, each with onError wired up to release a countdown latch
• send error responses to all three of them (actually it sends the error in the same task it creates the stub)
• each task waits on the latch

(GrpcLoggingServiceTest has similar structure)

Unfortunately it occurs only in Beam's CI Jenkins environment (which takes ~1 hour to finish). I cannot reproduce the problem locally.

From the observation of the trace log and the previous thread dump, it seems that grpc-default-executor threads stop processing tasks (the thread dump showed no "grpc-default-executor" threads in the JVM when the test was waiting for the them to count down a CountDownLatch) and one of the latches are not counted down. This results in the test threads waiting forever for the remaining latch. I cannot tell why the "grpc-default-executor" threads stop working (disappear?).

Do you know how to troubleshot such situation?

[sanjaypujare]

it seems that grpc-default-executor threads stop processing tasks (the thread dump showed no "grpc-default-executor" threads in the JVM when the test was waiting for the them to count down a CountDownLatch)

I am a bit confused: are you saying there are no "grpc-default-executor" threads or the threads are there but there are no tasks to process or the threads have stopped processing tasks?

[suztomo]

Thank you for response. There were no "grpc-default-executor" threads in the thread dump, which was taken 12 minutes after the tests got hung (forever waiting for the CountDownLatch).

[sanjaypujare]

Oh, so based on this, it is a regression from 1.26.0 to 1.37 (or 1.36). Would it be possible to pass a custom executor to your channel builder and see what the behavior is?

It is unclear why there are no "grpc-default-executor" threads but it is concerning. Is it possible you have some uncaught exceptions in your onError() which causes the thread to die? Also I looked at apache/beam#14768 (comment) and are the messages "Logging client failed unexpectedly." and "CANCELLED: client cancelled" part of the test or could they somehow be related to this issue?

[suztomo]

"Logging client failed unexpectedly." and "CANCELLED: client cancelled" are expected messages in the test. After these messages, the service should call corresponding method (to count down the latches) for the exceptions.

Trying the executor option.

[sanjaypujare]

"Logging client failed unexpectedly." and "CANCELLED: client cancelled" are expected messages in the test. After these messages, the service should call corresponding method (to count down the latches) for the exceptions.

Trying the executor option.

One more thing you may want to try is to catch all Throwables in your onError, log them and see if that was the issue. It is possible that because of an unrelated behavior change between 1.26 to 1.37 there is an uncaught exception that causes the thread to exit/die.

[suztomo]

With the executor option (commit), GrpcLoggingServiceTest passes, but BeamFnLoggingServiceTest failed.

[sanjaypujare]

With the executor option (commit), GrpcLoggingServiceTest passes, but BeamFnLoggingServiceTest failed.

What about modifying your onError to make sure you catch all exceptions and log them?

[suztomo]

Thanks. Let me try that.

[suztomo]

I tried catching Throwable in onError (commit) but the method succeeded.

suztomo-macbookpro44% grep 'onError succeeded'  17724.log
    14:37:16.420 [grpc-default-executor-1] DEBUG o.a.b.r.f.logging.GrpcLoggingService - onError succeeded
    14:37:16.423 [grpc-default-executor-2] DEBUG o.a.b.r.f.logging.GrpcLoggingService - onError succeeded
    14:37:16.430 [grpc-default-executor-3] DEBUG o.a.b.r.f.logging.GrpcLoggingService - onError succeeded
    14:52:04.255 [grpc-default-executor-6] DEBUG o.a.b.r.d.w.f.l.BeamFnLoggingService - onError succeeded
    14:52:04.255 [grpc-default-executor-3] DEBUG o.a.b.r.d.w.f.l.BeamFnLoggingService - onError succeeded
    14:52:04.255 [grpc-default-executor-0] DEBUG o.a.b.r.d.w.f.l.BeamFnLoggingService - onError succeeded

I wish there's a way to log lifecycle/state of grpc-default-executor threads. Or setting Thread.setUncaughtExceptionHandler

[sanjaypujare]

I tried catching Throwable in onError (commit) but the method succeeded.

To summarize:

• you are using a custom executor now and that allows one test to pass but another test is still failing
• based on the latest commit it looks like there are no uncaught exceptions happening in onError

Is your test failing because of disappearing threads still? If that's the case and you are using a custom executor would you be able to instrument it to see why threads are disappearing?

[suztomo]

That's right. Now it's my custom executors that is responsible to count down the latches. Let me add more logging.

[sanjaypujare]

That's right. Now it's my custom executors that is responsible to count down the latches. Let me add more logging.

The executor (ThreadFactory) is yours and the onError code executed is also yours. This is unlikely to be a gRPC issue then. But it will be good to know what the root cause is.