Throw Status.UNAVAILABLE on connection refused #1720

lukaszx0 · 2016-04-26T15:49:46Z

I think we want to catch io.netty.channel.ChannelException and re-throw as Status.UNAVIALIBLE when endpoint is unreachable:

http2.Http2ConnectionHandler - [id: 0x39fed2a5] Sending GOAWAY failed: lastStreamId '0', errorCode '2', debugData 'Connection refused: example.lukasz.local/127.0.0.1:12345'. Forcing shutdown of the connection.
io.netty.channel.ChannelException: Pending write on removal of SslHandler
    at io.netty.handler.ssl.SslHandler.handlerRemoved0(SslHandler.java:426)
[...]

The text was updated successfully, but these errors were encountered:

ejona86 · 2016-04-26T16:07:59Z

This is what I'm currently seeing:

$ ./build/install/grpc-examples/bin/hello-world-client
Apr 26, 2016 9:05:24 AM io.grpc.internal.ManagedChannelImpl <init>
INFO: [ManagedChannelImpl@7bb11784] Created with target localhost:50051
Apr 26, 2016 9:05:24 AM io.grpc.examples.helloworld.HelloWorldClient greet
INFO: Will try to greet world ...
Apr 26, 2016 9:05:24 AM io.grpc.examples.helloworld.HelloWorldClient greet
WARNING: RPC failed: Status{code=UNAVAILABLE, description=Transport closed for unknown reason, cause=null}
Apr 26, 2016 9:05:24 AM io.grpc.internal.ManagedChannelImpl maybeTerminateChannel
INFO: [ManagedChannelImpl@7bb11784] Terminated

So it is unavailable for me, but the description and cause are missing. Basically, the root cause was missed/lost and now the code doesn't know what went wrong. I've fixed this before, but I think we may be hitting a race such that the behavior morphs.

lukaszx0 · 2016-04-26T17:08:34Z

Sorry, my bad, the issue was on my side. It is working as expected besides description= not being populated from time to time just like @ejona86 said.

ejona86 · 2016-06-09T18:01:46Z

This is related (but not necessarily the same) to #1330.

buchgr · 2016-06-12T14:48:53Z

It looks to me that with the current master this is no longer reproducable. I tried a dozen times and always get the same result.

Jakobs-MBP-4:bin buchgr$ ./hello-world-client
Jun 12, 2016 4:46:00 PM io.grpc.internal.ManagedChannelImpl <init>
INFO: [ManagedChannelImpl@2b80d80f] Created with target localhost:50051
Jun 12, 2016 4:46:01 PM io.grpc.examples.helloworld.HelloWorldClient greet
INFO: Will try to greet world ...
Jun 12, 2016 4:46:01 PM io.grpc.examples.helloworld.HelloWorldClient greet
WARNING: RPC failed: Status{code=UNAVAILABLE, description=Terminated fail fast stream., cause=io.grpc.StatusException: UNAVAILABLE}
Jun 12, 2016 4:46:01 PM io.grpc.internal.ManagedChannelImpl maybeTerminateChannel
INFO: [ManagedChannelImpl@2b80d80f] Terminated

The QPS client gives (without TLS)

Encountered an error in unaryCall. Status is Status{code=UNAVAILABLE, description=Terminated fail fast stream., cause=io.grpc.StatusException: UNAVAILABLE}
io.grpc.StatusRuntimeException: UNAVAILABLE: Terminated fail fast stream.
    at io.grpc.Status.asRuntimeException(Status.java:543)
    at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:317)
    at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$3.runInContext(ClientCallImpl.java:447)
    at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:52)
    at io.grpc.internal.SerializingExecutor$TaskRunner.run(SerializingExecutor.java:154)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: io.grpc.StatusException: UNAVAILABLE
    at io.grpc.Status.asException(Status.java:551)
    at io.grpc.internal.DelayedClientTransport$3.run(DelayedClientTransport.java:327)
    ... 3 more
Caused by: java.net.ConnectException: Connection refused: localhost/127.0.0.1:8081
    at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
    at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717)
    at io.netty.channel.socket.nio.NioSocketChannel.doFinishConnect(NioSocketChannel.java:330)
    at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.finishConnect(AbstractNioChannel.java:338)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:580)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:504)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:418)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:390)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:742)
    ... 1 more

When the TLS Handshake fails I get

io.grpc.StatusRuntimeException: UNAVAILABLE: Terminated fail fast stream.
    at io.grpc.Status.asRuntimeException(Status.java:543)
    at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:317)
    at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$3.runInContext(ClientCallImpl.java:447)
    at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:52)
    at io.grpc.internal.SerializingExecutor$TaskRunner.run(SerializingExecutor.java:154)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: io.grpc.StatusException: UNAVAILABLE
    at io.grpc.Status.asException(Status.java:551)
    at io.grpc.internal.DelayedClientTransport$3.run(DelayedClientTransport.java:327)
    ... 3 more
Caused by: io.netty.handler.ssl.NotSslRecordException: not an SSL/TLS record: 00000c04000000000000037fffffff000400100000000004080000000000000f0001
    at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:915)
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:411)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:248)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
...

io.grpc.StatusRuntimeException: UNAVAILABLE: Terminated fail fast stream.
    at io.grpc.Status.asRuntimeException(Status.java:543)
    at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:317)
    at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$3.runInContext(ClientCallImpl.java:447)
    at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:52)
    at io.grpc.internal.SerializingExecutor$TaskRunner.run(SerializingExecutor.java:154)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: io.grpc.StatusException: UNAVAILABLE
    at io.grpc.Status.asException(Status.java:551)
    at io.grpc.internal.DelayedClientTransport$3.run(DelayedClientTransport.java:327)
    ... 3 more
Caused by: javax.net.ssl.SSLHandshakeException: General OpenSslEngine problem
    at io.netty.handler.ssl.OpenSslContext$AbstractCertificateVerifier.verify(OpenSslContext.java:466)
    at org.apache.tomcat.jni.SSL.readFromSSL(Native Method)
    at io.netty.handler.ssl.OpenSslEngine.readPlaintextData(OpenSslEngine.java:365)
    at io.netty.handler.ssl.OpenSslEngine.unwrap(OpenSslEngine.java:725)
    at io.netty.handler.ssl.OpenSslEngine.unwrap(OpenSslEngine.java:831)

All of that seems correct @ejona86 ?

ejona86 · 2016-06-13T16:16:06Z

@buchgr, it may no longer be present. But I do think it was a race to begin with. I just tried running a bunch of times and didn't see it (and I was using #1921 to get better output). But you got io.grpc.StatusException: UNAVAILABLE which seems suspicious; you may have hit ClosedChannelException which is being converted to UNAVAILABLE since #1516.

buchgr · 2016-06-15T15:40:49Z

@ejona86 that cause: UNAVAILABLE seems to be what was fixed by your commit 26bace6 and not #1516.

ejona86 · 2016-06-15T15:44:08Z

@buchgr, so are you seeing helpful errors now?

buchgr · 2016-06-15T15:49:02Z

@ejona86
oh sorry 😅 yeah :)

WARNING: RPC failed: Status{code=UNAVAILABLE, description=null, cause=java.net.ConnectException: Connection refused: localhost/fe80:0:0:0:0:0:0:1%1:50051}

buchgr · 2016-06-15T15:50:04Z

@ejona86 looking into the description.

ejona86 · 2016-06-15T15:51:45Z

@buchgr, null description is fine, since it has that "Connection Refused" cause. And we didn't see it before because the toString of the exception doesn't include any dependent causes. That Status you got LGTM

buchgr · 2016-06-15T15:54:46Z

I assume that means I can close this. Reopen if it's not the case :).

buchgr · 2016-06-15T15:55:30Z

Fixed by 26bace6

ejona86 added this to the 1.0 milestone Apr 26, 2016

hsaliak added bug P2 labels Apr 26, 2016

ejona86 added the netty label Jun 9, 2016

ejona86 assigned nmittler and buchgr and unassigned nmittler Jun 9, 2016

buchgr closed this as completed Jun 15, 2016

ejona86 modified the milestones: 1.0, 0.15.0 Jul 1, 2016

lock bot locked as resolved and limited conversation to collaborators Sep 22, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Throw Status.UNAVAILABLE on connection refused #1720

Throw Status.UNAVAILABLE on connection refused #1720

lukaszx0 commented Apr 26, 2016

ejona86 commented Apr 26, 2016

lukaszx0 commented Apr 26, 2016

ejona86 commented Jun 9, 2016

buchgr commented Jun 12, 2016 •

edited

ejona86 commented Jun 13, 2016

buchgr commented Jun 15, 2016

ejona86 commented Jun 15, 2016

buchgr commented Jun 15, 2016

buchgr commented Jun 15, 2016

ejona86 commented Jun 15, 2016

buchgr commented Jun 15, 2016

buchgr commented Jun 15, 2016

Throw Status.UNAVAILABLE on connection refused #1720

Throw Status.UNAVAILABLE on connection refused #1720

Comments

lukaszx0 commented Apr 26, 2016

ejona86 commented Apr 26, 2016

lukaszx0 commented Apr 26, 2016

ejona86 commented Jun 9, 2016

buchgr commented Jun 12, 2016 • edited

ejona86 commented Jun 13, 2016

buchgr commented Jun 15, 2016

ejona86 commented Jun 15, 2016

buchgr commented Jun 15, 2016

buchgr commented Jun 15, 2016

ejona86 commented Jun 15, 2016

buchgr commented Jun 15, 2016

buchgr commented Jun 15, 2016

buchgr commented Jun 12, 2016 •

edited