DEADLINE_EXCEEDED description reports a smaller timeout than the configured responseTimeoutMillis when RetryingClient is used

[dajung-mun]

Description

When a gRPC client is decorated with RetryingClient and responseTimeoutMillis is set to 3000, a response timeout produces a status description that reports a value smaller than the configured timeout:

DEADLINE_EXCEEDED: deadline exceeded after 2999000000ns.

Neither TimeoutMode nor ResponseTimeoutMode was set explicitly.

Analysis

1. AbstractRetryingClient.execute() captures the retry deadline once, from the configured response timeout:

   armeria/core/src/main/java/com/linecorp/armeria/client/retry/AbstractRetryingClient.java

   Line 85 in a72a0ca

   final State state = new State(config, ctx.responseTimeoutMillis());

   final State state = new State(config, ctx.responseTimeoutMillis());

   which stores deadlineNanos = System.nanoTime() + MILLISECONDS.toNanos(3000).

2. RetryingClient.doExecute0() then applies the timeout to the root context, before the derived context for the attempt is created:

   armeria/core/src/main/java/com/linecorp/armeria/client/retry/RetryingClient.java

   Line 293 in a72a0ca

   if (!setResponseTimeout(ctx)) {

   if (!setResponseTimeout(ctx)) { ... }
   // ...
   derivedCtx = newDerivedContext(ctx, duplicateReq, ctx.rpcRequest(), initialAttempt);

   and setResponseTimeout() does SET_FROM_NOW with the remaining time:

   armeria/core/src/main/java/com/linecorp/armeria/client/retry/AbstractRetryingClient.java

   Line 188 in a72a0ca

   ctx.setResponseTimeoutMillis(TimeoutMode.SET_FROM_NOW, responseTimeoutMillis);

   ctx.setResponseTimeoutMillis(TimeoutMode.SET_FROM_NOW, responseTimeoutMillis);

   where the remaining time is computed as:

   armeria/core/src/main/java/com/linecorp/armeria/client/retry/AbstractRetryingClient.java

   Line 327 in a72a0ca

   return TimeUnit.NANOSECONDS.toMillis(deadlineNanos - System.nanoTime());

   return TimeUnit.NANOSECONDS.toMillis(deadlineNanos - System.nanoTime());

   The sub-millisecond time elapsed between step 1 and step 2 is floored away by NANOSECONDS.toMillis(), so the root context's responseTimeoutMillis ends up as 2999 instead of 3000.

3. ArmeriaClientCall.close() builds the status description from the root context's current responseTimeoutMillis:

   armeria/grpc/src/main/java/com/linecorp/armeria/internal/client/grpc/ArmeriaClientCall.java

   Lines 557 to 559 in a72a0ca

   	if (status.getCode() == Code.DEADLINE_EXCEEDED) {
   	status = status.augmentDescription("deadline exceeded after " +
   	MILLISECONDS.toNanos(ctx.responseTimeoutMillis()) + "ns.");

   if (status.getCode() == Code.DEADLINE_EXCEEDED) {
       status = status.augmentDescription("deadline exceeded after " +
                                          MILLISECONDS.toNanos(ctx.responseTimeoutMillis()) + "ns.");
   }

   so the user-visible message reports 2999000000ns rather than the configured 3000000000ns.

Expected behavior

The DEADLINE_EXCEEDED description should report the response timeout that was actually configured (3000 ms in this example).

Notes

The description is built inside Armeria, so an application has no way to correct it.

Environment

• Armeria: reproduced on 1.38.0; the same code is present in 1.40.0 and main (a72a0ca)

[adityaanikam]

All three files you cited (AbstractRetryingClient, RetryingClient, ArmeriaClientCall) are unchanged at those exact lines between the commit you linked and current main, 25 commits apart with zero touches to any of them. Nice catch isolating it to the second NANOSECONDS.toMillis() call specifically, since the deadline itself is stored correctly in nanoseconds throughout, it's only the millisecond conversion used for the description that loses the fraction. I'd frame the fix as reporting from the originally configured responseTimeoutMillis rather than the value recomputed from time remaining. That calculation of time remaining is fine for actually enforcing the timeout, it just shouldn't double as the number shown to the caller. Want me to put up a PR along those lines?