Unexpected GO_AWAY with bi-directional keep-alive

[mopfattn]

What version of gRPC-Java are you using?

1.76.0

What is your environment?

macOS with JDK 17, 21, Android 15

What did you expect to see?

Keep-alive pings are successfully exchanged

What did you see instead?

Server responds with a GO_AWAY

Steps to reproduce the bug

A sample project to reproduce this issue is available at https://github.com/mopfattn/grpc-keep-alive-go-away.

To reproduce this issue the following setup is used:

• both gRPC server and client do keep-alive pings (without calls) each second
• the server permits pings at an interval of 500 ms
• run the server and client and wait
• after some time the server response with GO_AWAY

To my understanding this ping method is invoked for incoming ping requests AND ping responses:

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

Line 954 in 349a35a

if (!keepAliveEnforcer.pingAcceptable()) {

In both cases keepAliveEnforcer.pingAcceptable is invoked, which then results in the GO_AWAY error.

The pingAcceptable method should probably only called, when the ping is initiated by the client (ack=false), and not if the ping is a response (ack=true) to a ping issues by the server.

Server output:

2025-10-15 05:53:58.953 [io.grpc.okhttp.OkHttpClientTransport] OUTBOUND PING: ack=false bytes=57005
2025-10-15 05:53:58.956 [io.grpc.okhttp.OkHttpServerTransport] INBOUND PING: ack=true bytes=57005
2025-10-15 05:54:08.957 [io.grpc.okhttp.OkHttpClientTransport] OUTBOUND PING: ack=false bytes=57005
2025-10-15 05:54:08.958 [io.grpc.okhttp.OkHttpServerTransport] INBOUND PING: ack=false bytes=5241911198473060747
2025-10-15 05:54:08.958 [io.grpc.okhttp.OkHttpClientTransport] OUTBOUND PING: ack=true bytes=5241911198473060747
2025-10-15 05:54:08.961 [io.grpc.okhttp.OkHttpClientTransport] OUTBOUND GO_AWAY: lastStreamId=3 errorCode=ENHANCE_YOUR_CALM length=14 bytes=746f6f5f6d616e795f70696e6773

[kannanjgithub]

KeepAliveEnforcer.pingAcceptable is only called on incoming ping frame read in OkHttpServerTransport.FrameHandler, not for the outbound ping response.
I ran your repro with some more logging and it shows that the server sends GO AWAY because it receives ping frames before the expected time interval (500 ms since last ping). KeepaliveEnforcer keeps a count of such frames and when it reaches 3 it sends GO AWAY. The count only gets reset when header or data frame is received, so it only keeps increasing in your case where there is no RPCs initiated.
Ping frames arriving before the expected time interval and ping frames also arrive much later (10s), indicating that the queueing up and getting sent by the transport is likely causing this behavior.

keep-alive-instrumentation.patch.txt

Instrumented server logs

/home/kannanj/.jdks/openjdk-24.0.2+12-54/bin/java -javaagent:/opt/intellij-ce-2022.3/lib/idea_rt.jar=36259:/opt/intellij-ce-2022.3/bin -Dfile.encoding=UTF-8 -Dsun.stdout.encoding=UTF-8 -Dsun.stderr.encoding=UTF-8 -classpath /home/kannanj/workgithub/grpc-keep-alive-go-away/build/classes/java/main:/home/kannanj/workgithub/grpc-keep-alive-go-away/build/classes/kotlin/main:/home/kannanj/workgithub/grpc-keep-alive-go-away/build/resources/main:/home/kannanj/.m2/repository/io/grpc/grpc-core/1.77.0-SNAPSHOT/grpc-core-1.77.0-SNAPSHOT.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/io.grpc/grpc-okhttp/1.76.0/9c0afc8b4fd3c154d4bd04bb570058f13f74aa98/grpc-okhttp-1.76.0.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/io.grpc/grpc-protobuf/1.76.0/46ad89c9e74468c8e488b32c192ca18626b68a49/grpc-protobuf-1.76.0.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/io.grpc/grpc-stub/1.76.0/a3f668a0cfea0c0b92d85e7e243b6dc4d5f0380d/grpc-stub-1.76.0.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/com.google.protobuf/protobuf-java/4.32.1/e757b7f2b21298e341a6fbe126a6919e539da2ef/protobuf-java-4.32.1.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/javax.annotation/javax.annotation-api/1.3.2/934c04d3cfef185a8008e7bf34331b79730a9d43/javax.annotation-api-1.3.2.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/org.jetbrains.kotlin/kotlin-stdlib-jdk8/2.2.20/57c4d839a6e5ad105d61ffc5cc0bf4de649c1714/kotlin-stdlib-jdk8-2.2.20.jar:/home/kannanj/.m2/repository/io/grpc/grpc-api/1.77.0-SNAPSHOT/grpc-api-1.77.0-SNAPSHOT.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/com.google.api.grpc/proto-google-common-protos/2.59.2/7de5fb9d2ad6cd65e59194ff0cba99c1152e7786/proto-google-common-protos-2.59.2.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/com.google.code.findbugs/jsr305/3.0.2/25ea2e8b0c338a877313bd4672d3fe056ea78f0d/jsr305-3.0.2.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/org.codehaus.mojo/animal-sniffer-annotations/1.24/aa9ba58d30e0aad7f1808fce9c541ea3760678d8/animal-sniffer-annotations-1.24.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/com.google.guava/guava/33.4.8-android/e70a3268e6cd3e7d458aa15787ce6811c34e96ae/guava-33.4.8-jre.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/org.jetbrains.kotlin/kotlin-stdlib-jdk7/2.2.20/bdbe3b5d872fa3b74d8fcd4e7ca3193f4abc9cc8/kotlin-stdlib-jdk7-2.2.20.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/org.jetbrains.kotlin/kotlin-stdlib/2.2.20/5380b19fa1924399b62ce3a1faffebb2b4f82272/kotlin-stdlib-2.2.20.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/com.google.errorprone/error_prone_annotations/2.36.0/227d4d4957ccc3dc5761bd897e3a0ee587e750a7/error_prone_annotations-2.36.0.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/com.google.guava/failureaccess/1.0.3/aeaffd00d57023a2c947393ed251f0354f0985fc/failureaccess-1.0.3.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/com.google.guava/listenablefuture/9999.0-empty-to-avoid-conflict-with-guava/b421526c5f297295adef1c886e5246c39d4ac629/listenablefuture-9999.0-empty-to-avoid-conflict-with-guava.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/org.jspecify/jspecify/1.0.0/7425a601c1c7ec76645a78d22b8c6a627edee507/jspecify-1.0.0.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/com.google.j2objc/j2objc-annotations/3.0.0/7399e65dd7e9ff3404f4535b2f017093bdb134c7/j2objc-annotations-3.0.0.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/org.jetbrains/annotations/13.0/919f0dfe192fb4e063e7dacadee7f8bb9a2672a9/annotations-13.0.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/io.grpc/grpc-util/1.76.0/ba5ea4f0abf4ba97314fb38862c6bae9b45e14cd/grpc-util-1.76.0.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/io.perfmark/perfmark-api/0.27.0/f86f575a41b091786a4b027cd9c0c1d2e3fc1c01/perfmark-api-0.27.0.jar:/home/kannanj/.m2/repository/io/grpc/grpc-context/1.77.0-SNAPSHOT/grpc-context-1.77.0-SNAPSHOT.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/com.google.code.gson/gson/2.11.0/527175ca6d81050b53bdd4c457a6d6e017626b0e/gson-2.11.0.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/com.google.android/annotations/4.1.1.4/a1678ba907bf92691d879fef34e1a187038f9259/annotations-4.1.1.4.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/io.grpc/grpc-protobuf-lite/1.76.0/aa913fd7efa0047f4ecf94896caf7d3264a9c94e/grpc-protobuf-lite-1.76.0.jar:/home/kannanj/.gradle/caches/modules-2/files-2.1/com.squareup.okio/okio-jvm/3.4.0/4e8bd78a52ab935ce383d0092646922154295e54/okio-jvm-3.4.0.jar de.pfattner.ServerKt
2025-10-15 09:53:22.377 [de.pfattner.Server] Server started on port 8181
2025-10-15 09:53:25.221 [io.grpc.internal.KeepAliveEnforcer] minTimeNanos=500000000
2025-10-15 09:53:25.240 [io.grpc.okhttp.OkHttpClientTransport] OUTBOUND SETTINGS: ack=false settings={MAX_HEADER_LIST_SIZE=8192, INITIAL_WINDOW_SIZE=65535}
2025-10-15 09:53:25.253 [io.grpc.okhttp.OkHttpServerTransport] INBOUND SETTINGS: ack=false settings={INITIAL_WINDOW_SIZE=65535}
2025-10-15 09:53:25.254 [io.grpc.okhttp.OkHttpClientTransport] OUTBOUND SETTINGS: ack=true
2025-10-15 09:53:25.263 [io.grpc.okhttp.OkHttpServerTransport] INBOUND HEADERS: streamId=3 headers=[:scheme: http, :method: POST, :authority: localhost:8181, :path: /de.pfattner.proto.MyService/GetTime, user-agent: grpc-java-okhttp/1.77.0-SNAPSHOT, content-type: application/grpc, te: trailers, grpc-accept-encoding: gzip] endStream=false
2025-10-15 09:53:25.295 [io.grpc.okhttp.OkHttpServerTransport] INBOUND DATA: streamId=3 endStream=false length=5 bytes=0000000000000000000100000003
2025-10-15 09:53:25.296 [io.grpc.okhttp.OkHttpServerTransport] INBOUND DATA: streamId=3 endStream=true length=0 bytes=
WARNING: A terminally deprecated method in sun.misc.Unsafe has been called
WARNING: sun.misc.Unsafe::arrayBaseOffset has been called by com.google.protobuf.UnsafeUtil$MemoryAccessor (file:/home/kannanj/.gradle/caches/modules-2/files-2.1/com.google.protobuf/protobuf-java/4.32.1/e757b7f2b21298e341a6fbe126a6919e539da2ef/protobuf-java-4.32.1.jar)
WARNING: Please consider reporting this to the maintainers of class com.google.protobuf.UnsafeUtil$MemoryAccessor
WARNING: sun.misc.Unsafe::arrayBaseOffset will be removed in a future release
2025-10-15 09:53:25.323 [io.grpc.okhttp.OkHttpClientTransport] OUTBOUND DATA: streamId=3 endStream=false length=35 bytes=000000001e0a1c576564204f63742031352030393a35333a3235205554432032303235
2025-10-15 09:53:35.297 [io.grpc.okhttp.OkHttpClientTransport] OUTBOUND PING: ack=false bytes=57005
2025-10-15 09:53:35.301 [io.grpc.internal.KeepAliveEnforcer] Enter pingAcceptable.
2025-10-15 09:53:35.303 [io.grpc.internal.KeepAliveEnforcer] lastValidPingTime + minTimeNanos =170985382255888, now=170994962804309, difference=9.580548s, valid=true.
2025-10-15 09:53:35.303 [io.grpc.internal.KeepAliveEnforcer] Valid. Setting lastValidPingTime to now.
2025-10-15 09:53:35.303 [io.grpc.internal.KeepAliveEnforcer] Exit pingAcceptable.
2025-10-15 09:53:35.303 [io.grpc.okhttp.OkHttpServerTransport] INBOUND PING: ack=true bytes=57005
2025-10-15 09:53:45.304 [io.grpc.okhttp.OkHttpClientTransport] OUTBOUND PING: ack=false bytes=57005
2025-10-15 09:53:45.307 [io.grpc.internal.KeepAliveEnforcer] Enter pingAcceptable.
2025-10-15 09:53:45.307 [io.grpc.internal.KeepAliveEnforcer] lastValidPingTime + minTimeNanos =170995462804309, now=171004968117452, difference=9.505313s, valid=true.
2025-10-15 09:53:45.307 [io.grpc.internal.KeepAliveEnforcer] Valid. Setting lastValidPingTime to now.
2025-10-15 09:53:45.308 [io.grpc.internal.KeepAliveEnforcer] Exit pingAcceptable.
2025-10-15 09:53:45.308 [io.grpc.okhttp.OkHttpServerTransport] INBOUND PING: ack=false bytes=-1500843950609553728
2025-10-15 09:53:45.308 [io.grpc.okhttp.OkHttpClientTransport] OUTBOUND PING: ack=true bytes=-1500843950609553728
2025-10-15 09:53:45.308 [io.grpc.internal.KeepAliveEnforcer] Enter pingAcceptable.
2025-10-15 09:53:45.309 [io.grpc.internal.KeepAliveEnforcer] lastValidPingTime + minTimeNanos =171005468117452, now=171004969718407, difference=-0.498399s, valid=false.
2025-10-15 09:53:45.309 [io.grpc.internal.KeepAliveEnforcer] Not valid. pingStrikes=1. Returning true
2025-10-15 09:53:45.309 [io.grpc.internal.KeepAliveEnforcer] Exit pingAcceptable.
2025-10-15 09:53:45.309 [io.grpc.okhttp.OkHttpServerTransport] INBOUND PING: ack=true bytes=57005
2025-10-15 09:53:55.310 [io.grpc.okhttp.OkHttpClientTransport] OUTBOUND PING: ack=false bytes=57005
2025-10-15 09:53:55.313 [io.grpc.internal.KeepAliveEnforcer] Enter pingAcceptable.
2025-10-15 09:53:55.313 [io.grpc.internal.KeepAliveEnforcer] lastValidPingTime + minTimeNanos =171005468117452, now=171014974021992, difference=9.505905s, valid=true.
2025-10-15 09:53:55.313 [io.grpc.internal.KeepAliveEnforcer] Valid. Setting lastValidPingTime to now.
2025-10-15 09:53:55.314 [io.grpc.internal.KeepAliveEnforcer] Exit pingAcceptable.
2025-10-15 09:53:55.314 [io.grpc.okhttp.OkHttpServerTransport] INBOUND PING: ack=false bytes=-2197434397062343191
2025-10-15 09:53:55.315 [io.grpc.okhttp.OkHttpClientTransport] OUTBOUND PING: ack=true bytes=-2197434397062343191
2025-10-15 09:53:55.315 [io.grpc.internal.KeepAliveEnforcer] Enter pingAcceptable.
2025-10-15 09:53:55.316 [io.grpc.internal.KeepAliveEnforcer] lastValidPingTime + minTimeNanos =171015474021992, now=171014976829150, difference=-0.497193s, valid=false.
2025-10-15 09:53:55.316 [io.grpc.internal.KeepAliveEnforcer] Not valid. pingStrikes=2. Returning true
2025-10-15 09:53:55.316 [io.grpc.internal.KeepAliveEnforcer] Exit pingAcceptable.
2025-10-15 09:53:55.317 [io.grpc.okhttp.OkHttpServerTransport] INBOUND PING: ack=true bytes=57005
2025-10-15 09:54:05.317 [io.grpc.okhttp.OkHttpClientTransport] OUTBOUND PING: ack=false bytes=57005
2025-10-15 09:54:05.319 [io.grpc.internal.KeepAliveEnforcer] Enter pingAcceptable.
2025-10-15 09:54:05.320 [io.grpc.internal.KeepAliveEnforcer] lastValidPingTime + minTimeNanos =171015474021992, now=171024980164847, difference=9.506143s, valid=true.
2025-10-15 09:54:05.320 [io.grpc.internal.KeepAliveEnforcer] Valid. Setting lastValidPingTime to now.
2025-10-15 09:54:05.320 [io.grpc.internal.KeepAliveEnforcer] Exit pingAcceptable.
2025-10-15 09:54:05.320 [io.grpc.okhttp.OkHttpServerTransport] INBOUND PING: ack=false bytes=-4121105342737797366
2025-10-15 09:54:05.320 [io.grpc.okhttp.OkHttpClientTransport] OUTBOUND PING: ack=true bytes=-4121105342737797366
2025-10-15 09:54:05.322 [io.grpc.internal.KeepAliveEnforcer] Enter pingAcceptable.
2025-10-15 09:54:05.322 [io.grpc.internal.KeepAliveEnforcer] lastValidPingTime + minTimeNanos =171025480164847, now=171024982936299, difference=-0.497229s, valid=false.
2025-10-15 09:54:05.322 [io.grpc.internal.KeepAliveEnforcer] Not valid. pingStrikes=3. Returning false
2025-10-15 09:54:05.322 [io.grpc.internal.KeepAliveEnforcer] Exit pingAcceptable.
2025-10-15 09:54:05.323 [io.grpc.okhttp.OkHttpClientTransport] OUTBOUND GO_AWAY: lastStreamId=3 errorCode=ENHANCE_YOUR_CALM length=14 bytes=746f6f5f6d616e795f70696e6773

[mopfattn]

Why keeps the counter increasing? Isn't the option permitKeepAliveWithoutCalls meant to allow that pings if no other RPC calls are executed?

Another question regarding your log. What is the reason for "Not valid" at 09:53:45.309? The previous inbound ping was at 09:53:35, which is much more than the permitted interval. Who causes the pingAcceptable check at 09:53:45.304? Is this caused by the outbound ping?

2025-10-15 09:53:35.303 [io.grpc.okhttp.OkHttpServerTransport] INBOUND PING: ack=true bytes=57005

2025-10-15 09:53:45.304 [io.grpc.okhttp.OkHttpClientTransport] OUTBOUND PING: ack=false bytes=57005
2025-10-15 09:53:45.307 [io.grpc.internal.KeepAliveEnforcer] Enter pingAcceptable.
2025-10-15 09:53:45.307 [io.grpc.internal.KeepAliveEnforcer] lastValidPingTime + minTimeNanos =170995462804309, now=171004968117452, difference=9.505313s, valid=true.
2025-10-15 09:53:45.307 [io.grpc.internal.KeepAliveEnforcer] Valid. Setting lastValidPingTime to now.
2025-10-15 09:53:45.308 [io.grpc.internal.KeepAliveEnforcer] Exit pingAcceptable.
2025-10-15 09:53:45.308 [io.grpc.okhttp.OkHttpServerTransport] INBOUND PING: ack=false bytes=-1500843950609553728
2025-10-15 09:53:45.308 [io.grpc.okhttp.OkHttpClientTransport] OUTBOUND PING: ack=true bytes=-1500843950609553728
2025-10-15 09:53:45.308 [io.grpc.internal.KeepAliveEnforcer] Enter pingAcceptable.
2025-10-15 09:53:45.309 [io.grpc.internal.KeepAliveEnforcer] lastValidPingTime + minTimeNanos =171005468117452, now=171004969718407, difference=-0.498399s, valid=false.
2025-10-15 09:53:45.309 [io.grpc.internal.KeepAliveEnforcer] Not valid. pingStrikes=1. Returning true

[kannanjgithub]

The counter is for number of pings received too soon before the next expected ping time. You are right about ping acks from the server also going through the KeepAliveEnforcer.isPingAcceptable check, and that is what in fact is causing the invalid strike count to increase in your example code.
The client side pings arriving at 10s is not due to queuing but the client logs themselves show the outbound pings at 10s intervals.