WARNING: Received unexpected ping ack. No ping outstanding

[mfirry]

Please answer these questions before submitting your issue.

What version of gRPC are you using?

1.6.1

What JVM are you using (java -version)?

1.8.0_141-b15

What did you do?

If possible, provide a recipe for reproducing the error.

What did you expect to see?

What did you see instead?

I see lots of these lines:

Nov 07, 2017 11:52:01 PM io.grpc.netty.NettyServerHandler$FrameListener onPingAckRead
WARNING: Received unexpected ping ack. No ping outstanding

Looks like just a warning, but I wanted to know if this could be some network issue.

[carl-mastrangelo]

Do you know what server implementation you are connected to?

[mfirry]

Client runs on Tomcat 7.0.65.

[ejona86]

@mfirry, we were hoping to know the server (or proxy) the client was talking to. We'd like to see if it was a server/proxy bug.

[mfirry]

Oh, ok... I use it on my standalone Scala app like this:

    val server = NettyServerBuilder.forPort(port)
      .keepAliveTime(20, TimeUnit.SECONDS)
      .addService(ServerInterceptors.intercept(new AlertServer, new AuthInterceptor(pwd)))
      .build()
...
    server.start()

The apps runs on mesosphere/marathon and we're using mesosphere/marathon-lb (though it's only one node now).

[ejona86]

Marathon-lb seems to be a wrapper around HAProxy. It seems HAProxy doesn't yet support HTTP/2 to the backend, so this would be a TCP (L4) proxy.

I've been able to reproduce this. It looks like a bug in our server implementation due to an intended-immutable buffer being modified.

Nov 13, 2017 2:20:40 PM io.netty.handler.codec.http2.Http2FrameLogger logPing
FINE: [id: 0xbe97b185, L:/127.0.0.1:8080 - R:/127.0.0.1:60042] OUTBOUND PING: ack=false length=8 bytes=000000000000dead
Nov 13, 2017 2:20:40 PM io.netty.handler.codec.http2.Http2FrameLogger logPingAck
FINE: [id: 0xbe97b185, L:/127.0.0.1:8080 - R:/127.0.0.1:60042] INBOUND PING: ack=true length=8 bytes=000000000000dead
Nov 13, 2017 2:20:40 PM io.grpc.netty.NettyServerHandler$FrameListener onPingAckRead
WARNING: Received unexpected ping ack. No ping outstanding

And then if you wait longer:

Nov 13, 2017 2:20:50 PM io.netty.handler.codec.http2.Http2FrameLogger logPing
FINE: [id: 0xbe97b185, L:/127.0.0.1:8080 - R:/127.0.0.1:60042] OUTBOUND PING: ack=false length=0 bytes=

This second ping is broken, since it has no 8-byte id. Netty notices and fails the future, but gRPC doesn't notice until keepAliveTimeout is exceeded. So server-side keepalive is pretty broken right now. It appears it's always been broken, since v1.3.1 behaves this way.

[ejona86]

I tested with a modified interop client/server:

diff --git a/interop-testing/src/main/java/io/grpc/testing/integration/TestServiceClient.java b/interop-testing/src/main/java/io/grpc/testing/integration/TestServiceClient.java
index bbe60cc3..9b1c9ea7 100644
--- a/interop-testing/src/main/java/io/grpc/testing/integration/TestServiceClient.java
+++ b/interop-testing/src/main/java/io/grpc/testing/integration/TestServiceClient.java
@@ -200,6 +200,7 @@ public class TestServiceClient {
     switch (testCase) {
       case EMPTY_UNARY:
         tester.emptyUnary();
+        Thread.sleep(100 * 1000);
         break;
 
       case CACHEABLE_UNARY: {
diff --git a/interop-testing/src/main/java/io/grpc/testing/integration/TestServiceServer.java b/interop-testing/src/main/java/io/grpc/testing/integration/TestServiceServer.java
index 48dd37db..b6aaa722 100644
--- a/interop-testing/src/main/java/io/grpc/testing/integration/TestServiceServer.java
+++ b/interop-testing/src/main/java/io/grpc/testing/integration/TestServiceServer.java
@@ -125,6 +125,8 @@ public class TestServiceServer {
               TestUtils.loadCert("server1.pem"), TestUtils.loadCert("server1.key")).build();
     }
     server = NettyServerBuilder.forPort(port)
+        .keepAliveTime(10, TimeUnit.SECONDS)
+        .keepAliveTimeout(1, TimeUnit.SECONDS)
         .sslContext(sslContext)
         .maxMessageSize(AbstractInteropTest.MAX_MESSAGE_SIZE)
         .addService(ServerInterceptors.intercept(

[dapengzhang0]

This failure occurs when using TLS, but not with plaintext. Netty's TLS handler may modify the ping bytebuf's reader index.

[mfirry]

Wow, that is some awesome support!
Thanks @ejona86 and @dapengzhang0.

Talking about HAProxy, I was actually looking for a proper HTTP/2 compliant proxy. Any hint?

[ejona86]

@mfirry, HAProxy is proper HTTP/2, but not to the backend. (Same as nginx.) nghttpx and derivatives (envoy, istio) are what we tend to recommend.