On Windows, when doing a heartbeat check of a Grpc server using Socket, Grpc has very noisy logging

[nddipiazza]

What version of gRPC are you using?

grpcVersion = 1.6.1
protocVersion = 3.3.0
Issue only reproduces on Windows operating systems.

What JVM are you using (java -version)?

java version "1.8.0_131"
Java(TM) SE Runtime Environment (build 1.8.0_131-b11)
Java HotSpot(TM) 64-Bit Server VM (build 25.131-b11, mixed mode)

What did you do?

1. git clone this project https://github.com/nddipiazza/grpc-java-bidirectional-streaming-example
2. Open cmd prompt and run gradlew startServer
3. Open another cmd prompt and run gradlew runHeartbeat

Notice each time you do a heartbeat on Grpc's port you get this INFO stack trace:

Oct 12, 2017 12:58:21 AM io.grpc.netty.NettyServerTransport notifyTerminated
INFO: Transport failed
java.io.IOException: An established connection was aborted by the software in your host machine
        at sun.nio.ch.SocketDispatcher.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:43)
        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:288)
        at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1106)
        at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:372)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:123)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:580)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:497)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:459)
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
        at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:138)
        at java.lang.Thread.run(Thread.java:748)

What did you expect to see?

No log noise on a SocketHeartbeat that is gracefully closed on the client side.

What did you see instead?

Lots of log noise with the stacktrace on a SocketHeartbeat that is gracefully closed on the client side.

[carl-mastrangelo]

@nddipiazza

It seems like this log is working as intended. An unexpected shutdown (that not from a GOAWAY) is a loggable event. Can you silence this logger using a log config?

For gRPC team:

Some followup things to consider:

• Lower this to a fine level log once we have a server trace
• Move connection setup and teardown events to a separate logger for easier silencing.

[zpencer]

@nddipiazza please see this update for recommendations:
#1768 (comment)

If you are still having problems please re-open the issue.

[nddipiazza]

excellent. thanks for taking care of this.