Q: blocking grpc client stub doesn't terminate/exit when server is down

[lmcdasi]

Hi,

I'm having an issue with one grpc application. For some reasons, a grpc client blocking unary call does not end when the server is down. The 'interesting' part is that I have two others using the same dependencies and the same library that executes the blocking unary call that have no issues.

The unary call has a wait for set at 15 seconds:

               final var createSessionResponse = serviceBlockingStub
                    .withDeadlineAfter(withDeadlineAfter, TimeUnit.MILLISECONDS) - 15000 ms
                    .createSession(createSessionRequest);

In the logs of the working grpc apps when I see:

    Channel$AnnotatedConnectException: finishConnect(..) failed: Connection refused: /192.168.1.41:9090
Caused by: java.net.ConnectException: finishConnect(..) failed: Connection refused
   at io.grpc.netty.shaded.io.netty.channel.unix.Errors.newConnectException0(Errors.java:166)
   at io.grpc.netty.shaded.io.netty.channel.unix.Errors.handleConnectErrno(Errors.java:131)
   at io.grpc.netty.shaded.io.netty.channel.unix.Socket.finishConnect(Socket.java:359)
   at io.grpc.netty.shaded.io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.doFinishConnect(AbstractEpollChannel.java:710)
   at io.grpc.netty.shaded.io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.finishConnect(AbstractEpollChannel.java:687)
   at io.grpc.netty.shaded.io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.epollOutReady(AbstractEpollChannel.java:567)
   at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:499)
   at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:407)
   at io.grpc.netty.shaded.io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
   at io.grpc.netty.shaded.io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)at io.grpc.netty.shaded.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
   at java.base/java.lang.Thread.run(Thread.java:840)

then I do get an ExecutionException thrown which is converted to StatusRuntimeException and the blocking stub is exiting.

But for one it does not. That ExecutionException seems not happen or not propagated and I'm running out of ideas on how can find the cause. I did look at the maven dependencies and I did not capture any difference at the grpc level nor at the netty level.
All 3 are using the same linux os based on ubuntu.

2024-06-20T22:00:01.889Z <> {extension=,callId=,thread=grpc-default-worker-ELG-1-1} DEBUG: [io.grpc.ChannelLogger] [Subchannel<5>: (192.168.1.41:9090)] TRANSIENT
FAILURE (UNAVAILABLE(io exception)[io.grpc.netty.shaded.io.netty.channel.AbstractChannel$AnnotatedConnectException: finishConnect(..) failed: Connection refused: /192.168.1.41:9090]). Will reconnect after 2,384,379,243 ns
2024-06-20T22:00:01.889Z <> {extension=,callId=,thread=grpc-default-worker-ELG-1-1} DEBUG: [io.grpc.ChannelLogger] [Channel<3>: (dns:///192.168.1.41:9090)] Entering TRANSIENT
FAILURE state with picker: EmptyPicker{status=Status{code=UNAVAILABLE, description=io exception, cause=io.grpc.netty.shaded.io.netty.channel.AbstractChannel$AnnotatedConnectException: finishConnect(..) failed: Connection refused: /192.168.1.41:9090
Caused by: java.net.ConnectException: finishConnect(..) failed: Connection refused
   at io.grpc.netty.shaded.io.netty.channel.unix.Errors.newConnectException0(Errors.java:166)
     at io.grpc.netty.shaded.io.netty.channel.unix.Errors.handleConnectErrno(Errors.java:131)
 at io.grpc.netty.shaded.io.netty.channel.unix.Socket.finishConnect(Socket.java:359)
    at io.grpc.netty.shaded.io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.doFinishConnect(AbstractEpollChannel.java:710)
   at io.grpc.netty.shaded.io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.finishConnect(AbstractEpollChannel.java:687)
     at io.grpc.netty.shaded.io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.epollOutReady(AbstractEpollChannel.java:567)
     at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:499)
      at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:407)
     at io.grpc.netty.shaded.io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
     at io.grpc.netty.shaded.io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)at io.grpc.netty.shaded.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
   at java.base/java.lang.Thread.run(Thread.java:840)
}}
2024-06-20T22:00:01.890Z <> {extension=,callId=,thread=grpc-default-worker-ELG-1-1} DEBUG: [io.grpc.ChannelLogger] [Subchannel<5>: (192.168.1.41:9090)] NettyClientTransport<10>: (/192.168.1.41:9090) Terminated
2024-06-20T22:00:04.277Z <> {extension=,callId=,thread=grpc-default-worker-ELG-1-2} DEBUG: [io.grpc.ChannelLogger] [Subchannel<5>: (192.168.1.41:9090)] CONNECTING after backoff
2024-06-20T22:00:04.278Z <> {extension=,callId=,thread=grpc-default-worker-ELG-1-2} DEBUG: [i.g.n.shaded.io.grpc.netty.Utils] Using custom allocator: forceHeapBuffer=false, defaultPreferDirect=true
2024-06-20T22:00:04.280Z <> {extension=,callId=,thread=grpc-default-worker-ELG-1-2} DEBUG: [io.grpc.ChannelLogger] [Subchannel<5>: (192.168.1.41:9090)] Started transport NettyClientTransport<11>: (/192.168.1.41:9090)
2024-06-20T22:00:04.280Z <> {extension=,callId=,thread=grpc-default-worker-ELG-1-1} TRACE: [io.grpc.ChannelLogger] [NettyClientTransport<11>: (/192.168.1.41:9090)] WaitUntilActive started
2024-06-20T22:00:07.382Z <> {extension=,callId=,thread=grpc-default-worker-ELG-1-1} DEBUG: [io.grpc.ChannelLogger] [Subchannel<5>: (192.168.1.41:9090)] NettyClientTransport<11>: (/192.168.1.41:9090) SHUTDOWN with UNAVAILABLE(io exception)[io.grpc.netty.shaded.io.netty.channel.AbstractChannel$AnnotatedConnectException: finishConnect(..) failed: Connection refused: /192.168.1.41:9090]
2024-06-20T22:00:07.383Z <> {extension=,callId=,thread=grpc-default-worker-ELG-1-1} DEBUG: [io.grpc.ChannelLogger] [Subchannel<5>: (192.168.1.41:9090)] TRANSIENT
FAILURE (UNAVAILABLE(io exception)[io.grpc.netty.shaded.io.netty.channel.AbstractChannel$AnnotatedConnectException: finishConnect(..) failed: Connection refused: /192.168.1.41:9090]). Will reconnect after 6,922,835,538 ns
2024-06-20T22:00:07.383Z <> {extension=,callId=,thread=grpc-default-worker-ELG-1-1} DEBUG: [io.grpc.ChannelLogger] [Channel<3>: (dns:///192.168.1.41:9090)] Entering TRANSIENT
FAILURE state with picker: EmptyPicker{status=Status{code=UNAVAILABLE, description=io exception, cause=io.grpc.netty.shaded.io.netty.channel.AbstractChannel$AnnotatedConnectException: finishConnect(..) failed: Connection refused: /192.168.1.41:9090
Caused by: java.net.ConnectException: finishConnect(..) failed: Connection refused
   at io.grpc.netty.shaded.io.netty.channel.unix.Errors.newConnectException0(Errors.java:166)
     at io.grpc.netty.shaded.io.netty.channel.unix.Errors.handleConnectErrno(Errors.java:131)
 at io.grpc.netty.shaded.io.netty.channel.unix.Socket.finishConnect(Socket.java:359)
    at io.grpc.netty.shaded.io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.doFinishConnect(AbstractEpollChannel.java:710)
   at io.grpc.netty.shaded.io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.finishConnect(AbstractEpollChannel.java:687)
     at io.grpc.netty.shaded.io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.epollOutReady(AbstractEpollChannel.java:567)
     at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:499)
      at io.grpc.netty.shaded.io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:407)
     at io.grpc.netty.shaded.io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
     at io.grpc.netty.shaded.io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)at io.grpc.netty.shaded.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
   at java.base/java.lang.Thread.run(Thread.java:840)
}}
2024-06-20T22:00:07.383Z <> {extension=,callId=,thread=grpc-default-worker-ELG-1-1} DEBUG: [io.grpc.ChannelLogger] [Subchannel<5>: (192.168.1.41:9090)] NettyClientTransport<11>: (/192.168.1.41:9090) Terminated
2024-06-20T22:00:14.313Z <> {extension=,callId=,thread=grpc-default-worker-ELG-1-2} DEBUG: [io.grpc.ChannelLogger] [Subchannel<5>: (192.168.1.41:9090)] CONNECTING after backoff

Since it is a common library that perform this blocking unary call, I have hard time to see how the one that does not work impacts it.
All 3 grpc apps are configured in the same way when communicating with the server too. Same keepalives, same idle setup.

The io.grpc version is 1.59.1.

Any suggestions on what would be the issue or how I could find the root cause ?

Thank you.

[lmcdasi]

I have changed the code to use a async call instead:

try {

            final var createSessionResponse = futureStub
                    .withDeadlineAfter(withDeadlineAfter, TimeUnit.MILLISECONDS)
                    .createSession(createSessionRequest);

            return createSessionResponse.get();
} catch .......

and I have the same behavior.

If I use a debugger with ExecutionException enabled, the debugger catches that and the code executes as expected.

Without a debugger, the code blocks on LockSupport.park(this) for some reasons.

[lmcdasi]

I have added two breakpoints in ClientCalls.java in waitAndDrain when the waiter is reset to null and one in execute when the local waiter is assigned.

Now in the debugger, if I turnoff the 2nd breakpoint, then the execute method is never executed - the 1st breakpoint never wakes up since the lock is not unparked.

So - is this a bug in grpc ?!? I do not see any issue from the above calls in the stack.

[lmcdasi]

In the end there is a dependency issue with google protobuf pkgs.