OkHttp exception logging level too high?

[jhspaybar]

Please answer these questions before submitting your issue.

What version of gRPC are you using?

1.3.0

What JVM are you using (java -version)?

1.8

What did you do?

If possible, provide a recipe for reproducing the error.
Normal usage

What did you expect to see?

No logs

What did you see instead?

May 31, 2017 5:04:13 PM io.grpc.okhttp.AsyncFrameWriter$14 run
WARNING: Failed closing connection
java.net.SocketException: Socket closed
        at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:118)
        at java.net.SocketOutputStream.write(SocketOutputStream.java:155)
        at okio.Okio$1.write(Okio.java:80)
        at okio.AsyncTimeout$1.write(AsyncTimeout.java:155)
        at okio.RealBufferedSink.close(RealBufferedSink.java:234)
        at io.grpc.okhttp.internal.framed.Http2$Writer.close(Http2.java:568)
        at io.grpc.okhttp.AsyncFrameWriter$14.run(AsyncFrameWriter.java:218)
        at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:117)
        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)

It looks like the socket is already dead and the close call here throws as a result

grpc-java/okhttp/src/main/java/io/grpc/okhttp/AsyncFrameWriter.java

Line 221 in 89bc2cd

log.log(Level.WARNING, "Failed closing connection", e);

. It isn't clear to me that this needs to be a WARNING since the exception is coming from us trying to close a closed socket. Maybe other failure modes here should be a warning, but should we maybe inspect the SocketException type specifically and log at FINE if the message is "Socket closed" ?

[bubenheimer]

I see this error in my client logs periodically right after the server automatically closes the connection once all RPCs are closed. This causes the channel state to change to IDLE and apparently triggers an effort on the client to close the socket that just got closed by the server. Would be nice to not see this.

My stacktrace looks marginally different, but I assume it's the same issue carried forward to grpc 1.8.0, and on Android:

W/OkHttpClientTransport: Failed closing connection
 java.net.SocketException: Socket closed
     at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:116)
     at java.net.SocketOutputStream.write(SocketOutputStream.java:153)
     at okio.Okio$1.write(Okio.java:80)
     at okio.AsyncTimeout$1.write(AsyncTimeout.java:155)
     at okio.RealBufferedSink.close(RealBufferedSink.java:234)
     at io.grpc.okhttp.internal.framed.Http2$Writer.close(Http2.java:569)
     at io.grpc.okhttp.AsyncFrameWriter$14.run(AsyncFrameWriter.java:203)
     at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
     at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1162)
     at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:636)
     at java.lang.Thread.run(Thread.java:764)