on_writable failed during connect with C++ client and Java server

[thej...@gmail.com]

I'm trying to debug an issue with connecting to a Java server created according to the following example:

public static void main(String [] args) throws IOException, InterruptedException {

  ServerImpl server = NettyServerBuilder.forPort(10001)

    .addService(NetPlayServerServiceGrpc.bindService(new Server())).build();

  server.start();

  log.info("Server started on port 10001.");

  server.awaitTermination();

}

Once this server is running and awaiting connections I go ahead and try to connect to it. I've got a simple RPC that just accepts and returns an empty proto:

    std::shared_ptr<grpc::Channel> channel =

        grpc::CreateChannel("localhost:10001", grpc::InsecureCredentials());

    auto stub = NetPlayServerService::NewStub(channel);

    PingPB ping_response;

    grpc::ClientContext context;

    context.set_deadline(std::chrono::system_clock::now() +

                         std::chrono::milliseconds(request_timeout_millis));

    if (stub->Ping(&context, ping_request, &ping_response).ok()) {

      return true;

    }

On the client side, I'm getting an error "on_writable failed during connect". I've investigated and it looks like this message is emitted in a callback that listens for a writable file descriptor state. 

I've attached the errors that I see on the Java side on the bottom of this message. It seems reasonable that connection reset I see result from the failures on the client side here. My best guess concerning the Http2Exception is that I somehow failed to compile netty support into the C++ side, although I don't see any error messages to that effect. 

I've tried not using a NettyServerBuilder and just using a raw server object, and I've tried pointing the client to a bogus address instead of a valid server, and the behavior is the same on the client side. 

I first encountered this issue on OS X El Capitan. My JVM is the following, installed using homebrew:

java version "1.8.0_51"

Java(TM) SE Runtime Environment (build 1.8.0_51-b16)

Java HotSpot(TM) 64-Bit Server VM (build 25.51-b03, mixed mode)

My software versions are:

GRPC C++: built from tag release_0_11_1

GRPC Java: 0.9.0, downloaded from Maven here.

Proto3: Built from source from tag v3.0.0-beta-1, note this tag is different from the Proto3 GRPC builds with (v3.0.0-alpha-4.1)

Here are my java errors:

WARNING: An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.

java.io.IOException: Connection reset by peer

at sun.nio.ch.FileDispatcherImpl.read0(Native Method)

at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)

at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)

at sun.nio.ch.IOUtil.read(IOUtil.java:192)

at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)

at io.netty.buffer.PooledUnsafeDirectByteBuf.setBytes(PooledUnsafeDirectByteBuf.java:312)

at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:854)

at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:245)

at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:112)

at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:510)

at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:467)

at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:381)

at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:353)

at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:742)

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)

Oct 01, 2015 9:52:14 PM io.grpc.netty.NettyServerHandler onConnectionError

WARNING: Connection Error

io.netty.handler.codec.http2.Http2Exception: HTTP/2 client preface string missing or corrupt. Hex dump for received bytes: 

at io.netty.handler.codec.http2.Http2Exception.connectionError(Http2Exception.java:82)

at io.netty.handler.codec.http2.Http2ConnectionHandler$PrefaceDecoder.readClientPrefaceString(Http2ConnectionHandler.java:322)

at io.netty.handler.codec.http2.Http2ConnectionHandler$PrefaceDecoder.decode(Http2ConnectionHandler.java:263)

at io.netty.handler.codec.http2.Http2ConnectionHandler.decode(Http2ConnectionHandler.java:445)

at io.netty.handler.codec.ByteToMessageDecoder.decodeLast(ByteToMessageDecoder.java:382)

at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:286)

at io.netty.handler.codec.http2.Http2ConnectionHandler.channelInactive(Http2ConnectionHandler.java:421)

at io.grpc.netty.NettyServerHandler.channelInactive(NettyServerHandler.java:227)

at io.netty.channel.ChannelHandlerInvokerUtil.invokeChannelInactiveNow(ChannelHandlerInvokerUtil.java:56)

at io.netty.channel.DefaultChannelHandlerInvoker.invokeChannelInactive(DefaultChannelHandlerInvoker.java:92)

at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:135)

at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:928)

at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:674)

at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:339)

at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:356)

at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:742)

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)

Oct 01, 2015 9:52:14 PM io.netty.handler.codec.http2.Http2ConnectionHandler processGoAwayWriteResult

SEVERE: Sending GOAWAY failed: lastStreamId '0', errorCode '1', debugData 'HTTP/2 client preface string missing or corrupt. Hex dump for received bytes: '. Forcing shutdown of the connection.

java.nio.channels.ClosedChannelException

[Eric Anderson]

Does the "on_writable failed on connect" error message stand out to anyone? It seems the C++ client encountered some problem before it had written any bytes to an insecure connection.

On Thu, Oct 1, 2015 at 7:21 PM, <thej...@gmail.com> wrote:

  ServerImpl server = NettyServerBuilder.forPort(10001)

    .addService(NetPlayServerServiceGrpc.bindService(new Server())).build();

  server.start();

Looks fine. A plaintext server on port 10001.

        grpc::CreateChannel("localhost:10001", grpc::InsecureCredentials());

...

    if (stub->Ping(&context, ping_request, &ping_response).ok()) {

From what I know of the C++ API, this also looks fine... I'd expect it to work.

On the client side, I'm getting an error "on_writable failed during connect". I've investigated and it looks like this message is emitted in a callback that listens for a writable file descriptor state. 

So this is useful information, but I don't know what could be causing it. 

I've attached the errors that I see on the Java side on the bottom of this message. It seems reasonable that connection reset I see result from the failures on the client side here.

Yeah, the Java server-side doesn't seem to have any useful information; it seems the client closed the connection immediately. 

My best guess concerning the Http2Exception is that I somehow failed to compile netty support into the C++ side, although I don't see any error messages to that effect. 

No, this is just weaker error handling for a semi-rare case. I've filed issue 1097 to improve it.

Netty is a Java-only detail; the other implementations aren't aware it is Netty when they are communicating with it.

I've tried not using a NettyServerBuilder and just using a raw server object,

That would have ended up using Netty, as it is the only server :-). The NettyServerBuilder is simply a more advanced API compared to ServerBuilder, but also with fewer API guarantees.

and I've tried pointing the client to a bogus address instead of a valid server, and the behavior is the same on the client side. 

That's useful to know.

My software versions are:

GRPC C++: built from tag release_0_11_1

GRPC Java: 0.9.0, downloaded from Maven here.

Proto3: Built from source from tag v3.0.0-beta-1, note this tag is different from the Proto3 GRPC builds with (v3.0.0-alpha-4.1)

All those look great. The v3.0.0-beta-1 is actually the one that gRPC builds with; when bumping the README to point to the new versions we forgot to bump the protobuf version as well. We fixed that on Tuesday.

java.io.IOException: Connection reset by peer

The client closed the connection. 

io.netty.handler.codec.http2.Http2Exception: HTTP/2 client preface string missing or corrupt. Hex dump for received bytes: 

Strange. Zero bytes? The client didn't send anything. This is the very first thing that happens on the TCP connection.

SEVERE: Sending GOAWAY failed: lastStreamId '0', errorCode '1', debugData 'HTTP/2 client preface string missing or corrupt. Hex dump for received bytes: '. Forcing shutdown of the connection.

This "GOAWAY failed" error is just useless noise coming from the Netty graceful shutdown code that we haven't cleaned up yet. It looks bad with the SEVERE, but really it is just failing to notify the remote side that we encountered an error, which of course fails because the TCP connection was closed.