gRPC retry behave weird when timeout is set along with retry policy

[ranavivek04]

Using below retry config:

{
  "methodConfig": [
    {
      "name": [
        {
          "service": "helloworld.Greeter",
          "method": "SayHello"
        }
      ],
      "timeout": "2.000s",
      "retryPolicy": {
        "maxAttempts": 5,
        "initialBackoff": "0.5s",
        "maxBackoff": "30s",
        "backoffMultiplier": 2,
        "retryableStatusCodes": [
          "UNAVAILABLE"
        ]
      }
    }
  ]
}

Expected: grpc client should stop retrying after "timeout": "2.000s" is over but client keeps running for infinite time i.e. kind of stuck in gRPC call to server.

[ejona86]

What version of gRPC are you using? Since you are mentioning retries being a cause, does that mean If you remove the retryPolicy the timeout works?

[ejona86]

I see you saw #10314. Are you using Netty or OkHttp?

[ranavivek04]

What version of gRPC are you using? Since you are mentioning retries being a cause, does that mean If you remove the retryPolicy the timeout works?

<grpc.version>1.53.0</grpc.version>
Retry works fine when I either remove timeout or I set timeout to a value that is greater than the combined time of retry attempts.

[ranavivek04]

I see you saw #10314. Are you using Netty or OkHttp?

using Netty

[ranavivek04]

This can be easily reproduced with below config on io.grpc.examples.retrying.RetryingHelloWorldClient example.

{
  "methodConfig": [
    {
      "name": [
        {
          "service": "helloworld.Greeter",
          "method": "SayHello"
        }
      ],
      "timeout": "2.000s",
      "retryPolicy": {
        "maxAttempts": 5,
        "initialBackoff": "0.5s",
        "maxBackoff": "30s",
        "backoffMultiplier": 2,
        "retryableStatusCodes": [
          "UNAVAILABLE"
        ]
      }
    }
  ]
}

Just change below method in io.grpc.examples.retrying.RetryingHelloWorldServer to return Status.UNAVAILABLE for all requests as below.

 @Override
    public void sayHello(HelloRequest request, StreamObserver<HelloReply> responseObserver) {
      int count = retryCounter.incrementAndGet();
//      if (random.nextFloat() < UNAVAILABLE_PERCENTAGE) {
        logger.info("Returning stubbed UNAVAILABLE error. count: " + count);
        responseObserver.onError(Status.UNAVAILABLE
            .withDescription("Greeter temporarily unavailable...").asRuntimeException());
//      } else {
//        logger.info("Returning successful Hello response, count: " + count);
//        HelloReply reply = HelloReply.newBuilder().setMessage("Hello " + request.getName()).build();
//        responseObserver.onNext(reply);
//        responseObserver.onCompleted().
//      }
    }

[ejona86]

I've reproduced this on master. It is broken at least since 1.52.0. I didn't test further back. And yes, removing retryPolicy fixes timeout.

diff --git a/examples/src/main/java/io/grpc/examples/retrying/RetryingHelloWorldServer.java b/examples/src/main/java/io/grpc/examples/retrying/RetryingHelloWorldServer.java
index 165cc72ff..a22980d76 100644
--- a/examples/src/main/java/io/grpc/examples/retrying/RetryingHelloWorldServer.java
+++ b/examples/src/main/java/io/grpc/examples/retrying/RetryingHelloWorldServer.java
@@ -97,16 +97,16 @@ public class RetryingHelloWorldServer {
     @Override
     public void sayHello(HelloRequest request, StreamObserver<HelloReply> responseObserver) {
       int count = retryCounter.incrementAndGet();
-      if (random.nextFloat() < UNAVAILABLE_PERCENTAGE) {
+      //if (random.nextFloat() < UNAVAILABLE_PERCENTAGE) {
         logger.info("Returning stubbed UNAVAILABLE error. count: " + count);
         responseObserver.onError(Status.UNAVAILABLE
             .withDescription("Greeter temporarily unavailable...").asRuntimeException());
-      } else {
-        logger.info("Returning successful Hello response, count: " + count);
-        HelloReply reply = HelloReply.newBuilder().setMessage("Hello " + request.getName()).build();
-        responseObserver.onNext(reply);
-        responseObserver.onCompleted();
-      }
+      //} else {
+      //  logger.info("Returning successful Hello response, count: " + count);
+      //  HelloReply reply = HelloReply.newBuilder().setMessage("Hello " + request.getName()).build();
+      //  responseObserver.onNext(reply);
+      //  responseObserver.onCompleted();
+      //}
     }
   }
 }
diff --git a/examples/src/main/resources/io/grpc/examples/retrying/retrying_service_config.json b/examples/src/main/resources/io/grpc/examples/retrying/retrying_service_config.json
index ff115a9ad..9d202d77b 100644
--- a/examples/src/main/resources/io/grpc/examples/retrying/retrying_service_config.json
+++ b/examples/src/main/resources/io/grpc/examples/retrying/retrying_service_config.json
@@ -8,6 +8,7 @@
         }
       ],
 
+      "timeout": "2.000s",
       "retryPolicy": {
         "maxAttempts": 5,
         "initialBackoff": "0.5s",

[burk]

As commented in the closed issue, we had the same problem, and I'm pretty sure the problem was introduced between versions 1.51.3 and 1.52.0.

[ejona86]

@turchenkoalex did some detailed investigation in #10838, which I think is related to this. @larry-safran, please look at the text in #10838. I didn't read it carefully but the things it mentioned were highly likely to be related to this issue, so I'm hopeful the root cause has been found.