HttpJson Unary Callables not following RetrySetting's TotalTimeout value

[lqiu96]

Sample Code run against Gapic-Showcase:

Initialize the Echo Client

    EchoSettings httpjsonEchoSettings =
        EchoSettings.newHttpJsonBuilder()
            .setCredentialsProvider(NoCredentialsProvider.create())
            .setTransportChannelProvider(
                EchoSettings.defaultHttpJsonTransportProviderBuilder()
                    .setHttpTransport(
                        new NetHttpTransport.Builder().doNotValidateCertificate().build())
                    .setEndpoint("http://localhost:7469")
                    .build())
            .build();
    httpjsonClient = EchoClient.create(httpjsonEchoSettings);

Make the call:

    // Default timeout for UnaryCall is 5 seconds -- We want to ensure a long enough delay for
    // this test
    int delayInSeconds = 10;
    assertThrows(
        DeadlineExceededException.class,
        () ->
            httpjsonClient.block(
                BlockRequest.newBuilder()
                    .setSuccess(
                        BlockResponse.newBuilder().setContent("httpjsonBlockContent_10SecDelay1"))
                    .setResponseDelay(
                        com.google.protobuf.Duration.newBuilder()
                            .setSeconds(delayInSeconds)
                            .build())
                    .build()));
    try {
      httpjsonClient.block(
          BlockRequest.newBuilder()
              .setSuccess(BlockResponse.newBuilder().setContent("httpjsonBlockContent_10SecDelay2"))
              .setResponseDelay(
                  com.google.protobuf.Duration.newBuilder().setSeconds(delayInSeconds).build())
              .build());
    } catch (DeadlineExceededException e) {
      assertThat(e.getStatusCode().getCode()).isEqualTo(StatusCode.Code.DEADLINE_EXCEEDED);
    }

Error Message:

[ERROR] Tests run: 10, Failures: 1, Errors: 0, Skipped: 1, Time elapsed: 45.797 s <<< FAILURE! - in com.google.showcase.v1beta1.it.ITEcho
[ERROR] com.google.showcase.v1beta1.it.ITEcho.testBlockHttpJson_throwsDeadlineExceededException  Time elapsed: 10.019 s  <<< FAILURE!
java.lang.AssertionError: expected com.google.api.gax.rpc.DeadlineExceededException to be thrown, but nothing was thrown
	at org.junit.Assert.assertThrows(Assert.java:1028)
	at org.junit.Assert.assertThrows(Assert.java:981)
	at com.google.showcase.v1beta1.it.ITEcho.testBlockHttpJson_throwsDeadlineExceededException(ITEcho.java:299)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
	at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
	at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
	at org.junit.runners.Suite.runChild(Suite.java:128)
	at org.junit.runners.Suite.runChild(Suite.java:27)
	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
	at org.apache.maven.surefire.junitcore.JUnitCore.run(JUnitCore.java:55)
	at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.createRequestAndRun(JUnitCoreWrapper.java:137)
	at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.executeLazy(JUnitCoreWrapper.java:119)
	at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:87)
	at org.apache.maven.surefire.junitcore.JUnitCoreWrapper.execute(JUnitCoreWrapper.java:75)
	at org.apache.maven.surefire.junitcore.JUnitCoreProvider.invoke(JUnitCoreProvider.java:158)
	at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:456)
	at org.apache.maven.surefire.booter.ForkedBooter.execute(ForkedBooter.java:169)
	at org.apache.maven.surefire.booter.ForkedBooter.run(ForkedBooter.java:595)
	at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:581)

[lqiu96]

I believe a possible fix to this is in the deliver() loop inside HttpJsonClientCallImpl.java:

if (callOptions.getDeadline() != null
    && Instant.now().isAfter(callOptions.getDeadline())) {
  close(
      StatusCode.Code.DEADLINE_EXCEEDED.getHttpStatusCode(),
      "Deadline exceeded",
      new HttpJsonStatusRuntimeException(
          StatusCode.Code.DEADLINE_EXCEEDED.getHttpStatusCode(),
          "Deadline exceeded",
          null),
      true);
}

[lqiu96]

I believe gRPC ClientCallsImpl.java does the same thing:

    Deadline effectiveDeadline = effectiveDeadline();
    boolean deadlineExceeded = effectiveDeadline != null && effectiveDeadline.isExpired();
    if (!deadlineExceeded) {
      logIfContextNarrowedTimeout(
          effectiveDeadline, context.getDeadline(), callOptions.getDeadline());
      stream = clientStreamProvider.newStream(method, callOptions, headers, context);
    } else {
      ClientStreamTracer[] tracers =
          GrpcUtil.getClientStreamTracers(callOptions, headers, 0, false);
      String deadlineName =
          isFirstMin(callOptions.getDeadline(), context.getDeadline()) ? "CallOptions" : "Context";
      String description = String.format(
          "ClientCall started after %s deadline was exceeded .9%f seconds ago", deadlineName,
          effectiveDeadline.timeRemaining(TimeUnit.NANOSECONDS) / NANO_TO_SECS);
      stream = new FailingClientStream(DEADLINE_EXCEEDED.withDescription(description), tracers);
    }

[lqiu96]

I believe a possible fix to this is in the deliver() loop inside HttpJsonClientCallImpl.java:

if (callOptions.getDeadline() != null
    && Instant.now().isAfter(callOptions.getDeadline())) {
  close(
      StatusCode.Code.DEADLINE_EXCEEDED.getHttpStatusCode(),
      "Deadline exceeded",
      new HttpJsonStatusRuntimeException(
          StatusCode.Code.DEADLINE_EXCEEDED.getHttpStatusCode(),
          "Deadline exceeded",
          null),
      true);
}

Issue with this approach is that the deliver() loop doesn't constantly run. It gets invoked on events (i.e. setting result, starting a call, etc). If there is no event after the call starts (i.e. start a call and wait for a response, but no response ever comes), then it will not trigger a close(). We need a separate thread to keep track of the timeout.

[lqiu96]

Instead, I think the better option is to mimic the gRPC implementation by adding a separate scheduler to invoke close() when the timeout reaches its value.