IllegalStateException: There should be no outstanding pingFuture when setting keepAliveTime

[RocketRider]

What version of gRPC are you using?
Android, 1.16.1

I tried to keep a channel open and send data periodically. I wanted the connection to stay open so I set setkeepAliveTime to 10 seconds and keepAliveTimeout to 2 seconds.
In my Application I saw a lot of crashes when sending data because of an IllegalStateException: "There should be no outstanding pingFuture".

So I tried to reproduce it with the sample and saw the same error. I modified the HelloworldActivity to keep the Channel open and did set the keepAlive.

The Client crashes with the following error after waiting 10 seconds and trying to send new data:

2018-11-29 14:43:07.784 25648-25694/io.grpc.helloworldexample I/System.out: [socket][close] /192.168.42.129:41788
2018-11-29 14:43:07.790 25648-25704/io.grpc.helloworldexample E/GRPC: Error
    io.grpc.StatusRuntimeException: UNAVAILABLE: error in frame handler
        at io.grpc.stub.ClientCalls.toStatusRuntimeException(ClientCalls.java:233)
        at io.grpc.stub.ClientCalls.getUnchecked(ClientCalls.java:214)
        at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:139)
        at io.grpc.examples.helloworld.GreeterGrpc$GreeterBlockingStub.sayHello(GreeterGrpc.java:177)
        at io.grpc.helloworldexample.HelloworldActivity$GrpcTask.doInBackground(HelloworldActivity.java:107)
        at io.grpc.helloworldexample.HelloworldActivity$GrpcTask.doInBackground(HelloworldActivity.java:92)
        at android.os.AsyncTask$2.call(AsyncTask.java:333)
        at java.util.concurrent.FutureTask.run(FutureTask.java:266)
        at android.os.AsyncTask$SerialExecutor$1.run(AsyncTask.java:245)
        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)
     Caused by: java.lang.IllegalStateException: There should be no outstanding pingFuture
        at com.google.common.base.Preconditions.checkState(Preconditions.java:510)
        at io.grpc.internal.KeepAliveManager.onDataReceived(KeepAliveManager.java:175)
        at io.grpc.okhttp.OkHttpClientTransport$ClientFrameHandler.run(OkHttpClientTransport.java:970)
        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) 

The server shows a termination of the stream:

 Nov 29, 2018 1:43:43 PM io.grpc.netty.shaded.io.grpc.netty.NettyServerTransport notifyTerminated
INFORMATION: Transport failed
java.io.IOException: Die Verbindung wurde vom Kommunikationspartner zurückgesetzt
	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.grpc.netty.shaded.io.netty.buffer.PooledUnsafeDirectByteBuf.setBytes(PooledUnsafeDirectByteBuf.java:288)
	at io.grpc.netty.shaded.io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1128)
	at io.grpc.netty.shaded.io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:347)
	at io.grpc.netty.shaded.io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148)
	at io.grpc.netty.shaded.io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:644)
	at io.grpc.netty.shaded.io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:579)
	at io.grpc.netty.shaded.io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:496)
	at io.grpc.netty.shaded.io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:458)
	at io.grpc.netty.shaded.io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897)
	at io.grpc.netty.shaded.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.lang.Thread.run(Thread.java:745)

To reproduce, you can use the attached HelloworldActivity class with the sample server and send some data, wait over 10 seconds and try to send some more data.

HelloworldActivity.zip

[carl-mastrangelo]

@creamsoup since you have looked at the OkHttp code recently, can you peek if the ping implementation may be racy?

[creamsoup]

There could be a race between sendPing runnable and onDataReceived method in KeepAliveManager.
This race seems like unintentionally fixed by #5036, but the PR is not released yet.

@RocketRider, can you check if the issue is fixed on the master branch?

[RocketRider]

I tried to reproduce it with the master branch. I was not able to reproduce the issue, so it seems as the issue is already fixed.

Thank you for the very fast answer. Amazing support 👍

[ejona86]

I made #5036 because someone had experienced this issue, but at the time I hadn't yet proven it was related.