Repository: GoogleCloudPlatform/cloud-bigtable-client (java)

Issue:
Client will retry until max timeout is reached, even if deadline is exceeded
I've been experimenting with using gRPC itself to set my per-call timeouts.  I've noticed that if I set my per-call deadline low, lets say in this example to 1 second, I can end up in a situation where the client submits "requests" even though they'll never actually be sent to bigtable (since the deadline is already exceeded).

Example log:
```
2018-06-24 19:22:36,317 INF AbstractRetryingOperation Retrying failed call. Failure #1, got: Status{code=DEADLINE_EXCEEDED, description=deadline exceeded after 739333109ns, cause=null} on channel 14
2018-06-24 19:22:36,325 INF AbstractRetryingOperation Retrying failed call. Failure #2, got: Status{code=DEADLINE_EXCEEDED, description=deadline exceeded: -16434248 ns from now, cause=null} on channel 15
2018-06-24 19:22:36,341 INF AbstractRetryingOperation Retrying failed call. Failure #3, got: Status{code=DEADLINE_EXCEEDED, description=deadline exceeded: -31615089 ns from now, cause=null} on channel 16
2018-06-24 19:22:36,366 INF AbstractRetryingOperation Retrying failed call. Failure #4, got: Status{code=DEADLINE_EXCEEDED, description=deadline exceeded: -56484939 ns from now, cause=null} on channel 17
2018-06-24 19:22:36,396 INF AbstractRetryingOperation Retrying failed call. Failure #5, got: Status{code=DEADLINE_EXCEEDED, description=deadline exceeded: -86724983 ns from now, cause=null} on channel 18
```

It'll then retry until it reaches the max-retry limit based on the retry policy.  It seems like the client should stop retrying once the deadline has been exceeded here.

Pull request:
The Deadline timeout is now the max backoff timeout
This fixes #1858 

This should hopeuflly be the last PR before the next release.

Patch:
diff --git a/bigtable-client-core-parent/bigtable-client-core/src/main/java/com/google/cloud/bigtable/grpc/async/AbstractRetryingOperation.java b/bigtable-client-core-parent/bigtable-client-core/src/main/java/com/google/cloud/bigtable/grpc/async/AbstractRetryingOperation.java
index 448b1a0cd..7f0cf1cc1 100644
--- a/bigtable-client-core-parent/bigtable-client-core/src/main/java/com/google/cloud/bigtable/grpc/async/AbstractRetryingOperation.java
+++ b/bigtable-client-core-parent/bigtable-client-core/src/main/java/com/google/cloud/bigtable/grpc/async/AbstractRetryingOperation.java
@@ -42,6 +42,7 @@ import com.google.common.util.concurrent.ListenableFuture;
 
 import io.grpc.CallOptions;
 import io.grpc.ClientCall;
+import io.grpc.Deadline;
 import io.grpc.Metadata;
 import io.grpc.Status;
 import io.grpc.Status.Code;
@@ -336,7 +337,12 @@ public abstract class AbstractRetryingOperation<RequestT, ResponseT, ResultT>
    * @return a {@link ExponentialRetryAlgorithm} object.
    */
   private ExponentialRetryAlgorithm createRetryAlgorithm(ApiClock clock) {
-    int timeoutMs = retryOptions.getMaxElapsedBackoffMillis();
+    long timeoutMs = retryOptions.getMaxElapsedBackoffMillis();
+
+    Deadline deadline = getOperationCallOptions().getDeadline();
+    if (deadline != null) {
+      timeoutMs = deadline.timeRemaining(TimeUnit.MILLISECONDS);
+    }
 
     RetrySettings retrySettings = RetrySettings.newBuilder()
 
@@ -351,7 +357,7 @@ public abstract class AbstractRetryingOperation<RequestT, ResponseT, ResultT>
         // What is the maximum amount of sleep time between retries?
         // There needs to be some sane number for max retry delay, and it's unclear what that
         // number ought to be.  1 Minute time was chosen because some number is needed.
-        .setMaxRetryDelay( Duration.of(1, ChronoUnit.MINUTES))
+        .setMaxRetryDelay(Duration.of(1, ChronoUnit.MINUTES))
 
         // How long should we wait before giving up retries after the first failure?
         .setTotalTimeout(toDuration(timeoutMs))


Test patch:
diff --git a/bigtable-client-core-parent/bigtable-client-core/src/test/java/com/google/cloud/bigtable/grpc/TestCallOptionsFactory.java b/bigtable-client-core-parent/bigtable-client-core/src/test/java/com/google/cloud/bigtable/grpc/TestCallOptionsFactory.java
index 114983be1..5d6e1ac17 100644
--- a/bigtable-client-core-parent/bigtable-client-core/src/test/java/com/google/cloud/bigtable/grpc/TestCallOptionsFactory.java
+++ b/bigtable-client-core-parent/bigtable-client-core/src/test/java/com/google/cloud/bigtable/grpc/TestCallOptionsFactory.java
@@ -18,6 +18,7 @@ package com.google.cloud.bigtable.grpc;
 import com.google.bigtable.v2.MutateRowRequest;
 import com.google.bigtable.v2.MutateRowsRequest;
 import com.google.cloud.bigtable.config.CallOptionsConfig;
+import com.google.cloud.bigtable.grpc.async.OperationClock;
 import io.grpc.CallOptions;
 import io.grpc.Context;
 import io.grpc.Deadline;
@@ -57,7 +58,8 @@ public class TestCallOptionsFactory {
 
   @Test
   public void testDefaultWithContext() {
-    final Deadline deadline = DeadlineUtil.deadlineWithFixedTime(1, TimeUnit.SECONDS, NOW);
+    final Deadline deadline =
+        DeadlineUtil.deadlineWithFixedTime(1, TimeUnit.SECONDS, new OperationClock());
     Context.CancellableContext context = Context.current().withDeadline(deadline, mockExecutor);
     context.run(new Runnable() {
       @Override
@@ -94,7 +96,8 @@ public class TestCallOptionsFactory {
 
   @Test
   public void testConfiguredWithContext() {
-    Deadline deadline = DeadlineUtil.deadlineWithFixedTime(1, TimeUnit.SECONDS, NOW);
+    Deadline deadline =
+        DeadlineUtil.deadlineWithFixedTime(1, TimeUnit.SECONDS, new OperationClock());
     Context.CancellableContext context = Context.current().withDeadline(deadline, mockExecutor);
     context.run(new Runnable() {
       @Override
diff --git a/bigtable-client-core-parent/bigtable-client-core/src/test/java/com/google/cloud/bigtable/grpc/async/TestRetryingUnaryOperation.java b/bigtable-client-core-parent/bigtable-client-core/src/test/java/com/google/cloud/bigtable/grpc/async/TestRetryingUnaryOperation.java
index e70209345..453a7a275 100644
--- a/bigtable-client-core-parent/bigtable-client-core/src/test/java/com/google/cloud/bigtable/grpc/async/TestRetryingUnaryOperation.java
+++ b/bigtable-client-core-parent/bigtable-client-core/src/test/java/com/google/cloud/bigtable/grpc/async/TestRetryingUnaryOperation.java
@@ -27,6 +27,7 @@ import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicInteger;
 
 import com.google.cloud.bigtable.config.RetryOptions;
+import io.grpc.DeadlineUtil;
 import org.junit.Assert;
 import org.junit.Before;
 import org.junit.Test;
@@ -136,7 +137,18 @@ public class TestRetryingUnaryOperation {
   }
 
   @Test
-  public void testCompleteFailure() throws Exception {
+  public void testCompleteFailure_DEFAULT() throws Exception {
+    testTimeout(RETRY_OPTIONS.getMaxElapsedBackoffMillis(), CallOptions.DEFAULT);
+  }
+
+  @Test
+  public void testCompleteFailure_Deadline() throws Exception {
+    CallOptions options = DeadlineUtil.optionsWithDeadline(1, TimeUnit.SECONDS, clock);
+    testTimeout(TimeUnit.SECONDS.toMillis(1), options);
+  }
+
+  private void testTimeout(long expectedTimeoutMs, CallOptions options)
+      throws InterruptedException, java.util.concurrent.TimeoutException {
     final Status errorStatus = Status.UNAVAILABLE;
     Answer<Void> answer = new Answer<Void>() {
       @Override
@@ -153,15 +165,14 @@ public class TestRetryingUnaryOperation {
             any(Metadata.class),
             any(ClientCall.class));
     try {
-      createOperation(CallOptions.DEFAULT).getAsyncResult().get(1, TimeUnit.SECONDS);
+      createOperation(options).getAsyncResult().get(1, TimeUnit.SECONDS);
       Assert.fail();
     } catch (ExecutionException e) {
       Assert.assertEquals(BigtableRetriesExhaustedException.class, e.getCause().getClass());
       Assert.assertEquals(errorStatus.getCode(), Status.fromThrowable(e).getCode());
     }
 
-    clock.assertTimeWithinExpectations(
-        TimeUnit.MILLISECONDS.toNanos(RETRY_OPTIONS.getMaxElapsedBackoffMillis()));
+    clock.assertTimeWithinExpectations(TimeUnit.MILLISECONDS.toNanos(expectedTimeoutMs));
   }
 
   private RetryingUnaryOperation createOperation(CallOptions options) {
diff --git a/bigtable-client-core-parent/bigtable-client-core/src/test/java/com/google/cloud/bigtable/grpc/scanner/RetryingReadRowsOperationTest.java b/bigtable-client-core-parent/bigtable-client-core/src/test/java/com/google/cloud/bigtable/grpc/scanner/RetryingReadRowsOperationTest.java
index 4d748f485..97a528d1c 100644
--- a/bigtable-client-core-parent/bigtable-client-core/src/test/java/com/google/cloud/bigtable/grpc/scanner/RetryingReadRowsOperationTest.java
+++ b/bigtable-client-core-parent/bigtable-client-core/src/test/java/com/google/cloud/bigtable/grpc/scanner/RetryingReadRowsOperationTest.java
@@ -36,6 +36,7 @@ import java.util.concurrent.ScheduledExecutorService;
 import java.util.concurrent.ScheduledFuture;
 import java.util.concurrent.TimeUnit;
 
+import io.grpc.DeadlineUtil;
 import org.junit.Assert;
 import org.junit.Before;
 import org.junit.Test;
@@ -209,7 +210,18 @@ public class RetryingReadRowsOperationTest {
   }
 
   @Test
-  public void testFailure() throws Exception {
+  public void testFailure_default() throws Exception {
+    testFailure(RETRY_OPTIONS.getMaxElapsedBackoffMillis(), CallOptions.DEFAULT);
+  }
+
+  @Test
+  public void testFailure_deadline() throws Exception {
+    CallOptions options = DeadlineUtil.optionsWithDeadline(1, TimeUnit.SECONDS, clock);
+    testFailure(TimeUnit.SECONDS.toMillis(1), options);
+  }
+
+  private void testFailure(long expectedTimeMs, CallOptions options)
+      throws InterruptedException, java.util.concurrent.TimeoutException {
     doAnswer(new Answer<Void>() {
       @Override public Void answer(InvocationOnMock invocation) {
         invocation.getArgumentAt(1, ClientCall.Listener.class)
@@ -221,7 +233,7 @@ public class RetryingReadRowsOperationTest {
             any(ClientCall.class));
 
     RetryingReadRowsOperation underTest =
-        createOperation(CallOptions.DEFAULT, mockFlatRowObserver);
+        createOperation(options, mockFlatRowObserver);
     try {
       underTest.getAsyncResult().get(100, TimeUnit.MILLISECONDS);
     } catch (ExecutionException e) {
@@ -229,8 +241,6 @@ public class RetryingReadRowsOperationTest {
       Assert.assertEquals(Status.DEADLINE_EXCEEDED.getCode(), Status.fromThrowable(e).getCode());
     }
 
-    int expectedTimeMs = RETRY_OPTIONS.getMaxElapsedBackoffMillis();
-
     clock.assertTimeWithinExpectations(TimeUnit.MILLISECONDS.toNanos(expectedTimeMs));
     verify(mockFlatRowObserver, times(0)).onCompleted();
     verify(mockFlatRowObserver, times(1)).onError(any(Throwable.class));
diff --git a/bigtable-client-core-parent/bigtable-client-core/src/test/java/io/grpc/DeadlineUtil.java b/bigtable-client-core-parent/bigtable-client-core/src/test/java/io/grpc/DeadlineUtil.java
index c3f91acc2..b631922e6 100644
--- a/bigtable-client-core-parent/bigtable-client-core/src/test/java/io/grpc/DeadlineUtil.java
+++ b/bigtable-client-core-parent/bigtable-client-core/src/test/java/io/grpc/DeadlineUtil.java
@@ -15,6 +15,8 @@
  */
 package io.grpc;
 
+import com.google.api.core.ApiClock;
+
 import java.util.concurrent.TimeUnit;
 
 /**
@@ -22,11 +24,15 @@ import java.util.concurrent.TimeUnit;
  */
 public class DeadlineUtil {
 
-  public static Deadline deadlineWithFixedTime(int duration, TimeUnit unit, final long timeNs) {
+  public static CallOptions optionsWithDeadline(int duration, TimeUnit unit, final ApiClock clock) {
+    return CallOptions.DEFAULT.withDeadline(deadlineWithFixedTime(duration, unit, clock));
+  }
+
+  public static Deadline deadlineWithFixedTime(int duration, TimeUnit unit, final ApiClock clock) {
     return Deadline.after(duration, unit, new Deadline.Ticker() {
       @Override
       public long read() {
-        return timeNs;
+        return clock.nanoTime();
       }
     });
   }