Deadline exceeded error in dgraph4j

Users Dgraph
1

What I want to do

I want to be able to set request deadlines in dgraph4j. I want to create a single gRPC connection to Dgraph and then make requests without having DEADLINE_EXCEEDED errors.

  1. The gRPC website (https://grpc.io/blog/deadlines/) explains how to set deadlines but that doesn’t work the way I expect it.
  2. Dgraph4j docs covers how to set deadlines, but that doesn’t work for me.

My main question is How come the official way to do gRPC deadlines doesn’t work for dgraph4j?

What I did

Following the gRPC docs

I followed the official gRPC documentation on setting deadlines on gRPC requests: calling withDeadline on the stub object (https://grpc.io/blog/deadlines/):

ManagedChannel channel = ManagedChannelBuilder.forTarget(this.grpcEndPoint.get()).usePlaintext().build();
DgraphGrpc.DgraphStub stub = DgraphGrpc.newStub(channel);
stub.withDeadlineAfter(60, TimeUnit.MINUTES);
DgraphClient dgraphClient = new DgraphClient(stub);

Based on my tests, If I don’t call withDeadlineAfter, then my gRPC connection fails immediately. And, if I do set it, then my connection fails with DEADLINE_EXCEEDED error after an hour.

What I expect is that withDeadlineAfter is just the deadline on the first reply (based on the gRPC blog post linked earlier):

As a client you should always set a deadline for how long you are willing to wait for a reply from the server.

So, I don’t expect the DgraphClient to start failing requests with a deadline error.

java.lang.RuntimeException: java.util.concurrent.CompletionException: java.lang.RuntimeException: The doRequest encountered an execution exception:
	at io.dgraph.AsyncTransaction.lambda$doRequest$2(AsyncTransaction.java:222)
	at java.base/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:930)
	at java.base/java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:907)
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
	at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1705)
	at java.base/java.lang.Thread.run(Thread.java:834)
Caused by: java.util.concurrent.CompletionException: java.lang.RuntimeException: The doRequest encountered an execution exception:
	at java.base/java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:314)
	at java.base/java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:319)
	at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1702)
	... 1 more
Caused by: java.lang.RuntimeException: The doRequest encountered an execution exception:
	at io.dgraph.DgraphAsyncClient.lambda$runWithRetries$2(DgraphAsyncClient.java:227)
	at java.base/java.util.concurrent.CompletableFuture$AsyncSupply.run(CompletableFuture.java:1700)
	... 1 more
Caused by: java.util.concurrent.ExecutionException: io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: ClientCall started after deadline exceeded: -1367.378295121s from now
	at java.base/java.util.concurrent.CompletableFuture.reportGet(CompletableFuture.java:395)
	at java.base/java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1999)
	at io.dgraph.DgraphAsyncClient.lambda$runWithRetries$2(DgraphAsyncClient.java:195)
	... 2 more
Caused by: io.grpc.StatusRuntimeException: DEADLINE_EXCEEDED: ClientCall started after deadline exceeded: -1367.378295121s from now
	at io.grpc.Status.asRuntimeException(Status.java:534)
	at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:478)
	at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:553)
	at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:68)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInternal(ClientCallImpl.java:739)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:718)
	at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
	at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	... 1 more

Following the dgraph4j docs

The dgraph4j docs for setting deadlines mention using an interceptor to apply a deadline timeout to each individual request. But, this doesn’t work for me. If I do this, then requests fail immediately when setting it like this exactly how it’s covered in the docs:

channel = ManagedChannelBuilder.forAddress("localhost", 9080).usePlaintext(true).build();
DgraphGrpc.DgraphStub stub = DgraphGrpc.newStub(channel);
ClientInterceptor timeoutInterceptor = new ClientInterceptor(){
    @Override
    public <ReqT, RespT> ClientCall<ReqT, RespT> interceptCall(
            MethodDescriptor<ReqT, RespT> method, CallOptions callOptions, Channel next) {
        return next.newCall(method, callOptions.withDeadlineAfter(500, TimeUnit.MILLISECONDS));
    }
};
stub.withInterceptors(timeoutInterceptor);
DgraphClient dgraphClient = new DgraphClient(stub);

Other gRPC services

When I make gRPC requests for my other gRPC services, I can set it the way explained in the gRPC website and I never get any deadline errors: I call withDeadlineAfter on a single stub object and make the gRPC request.

Dgraph metadata

Dgraph v20.11.2

3

I tried reproducing this, didn’t happen for me.

This expectation is not correct, as explained in this issue in grpc-java: How does deadline work? · Issue #1495 · grpc/grpc-java · GitHub. It is a deadline and not a timeout, so it is a fixed point in time when the requests will start erroring out.
The second post in the above issue explains how to use deadlines to behave as timeouts. But, that is not feasible with the Java Client as a DgraphClient object takes in a stub during construction, and so the stub that an instance of the client is using can’t be modified after that. That is the reason, the approach of ClientInterceptor mentioned in the docs is the suggested way to handle per request timeouts with the Java Client.

Now, the reason this didn’t work is because of this line:

stub.withInterceptors(timeoutInterceptor);

returns a new stub, it doesn’t change the stub on which it is called and for constructing the DgraphClient we are using the old stub.
Our docs need to be corrected here with this:

stub = stub.withInterceptors(timeoutInterceptor);
DgraphClient dgraphClient = new DgraphClient(stub);

I have tested the per-request timeout as suggested in the dgraph4j README after the correction and it works perfectly fine.

A point to note is that the Alter operation does take at least 2secs, if not run in background. So, it may be a good idea to configure different timeouts based on the service method being called, like this:

ClientInterceptor timeoutInterceptor = new ClientInterceptor(){
      @Override
      public <ReqT, RespT> ClientCall<ReqT, RespT> interceptCall(
          MethodDescriptor<ReqT, RespT> method, CallOptions callOptions, Channel next) {
        if ("Alter".equals(method.getBareMethodName())) {
          return next.newCall(method, callOptions.withDeadlineAfter(2500, TimeUnit.MILLISECONDS));
        }
        return next.newCall(method, callOptions.withDeadlineAfter(500, TimeUnit.MILLISECONDS));
      }
    };

Some useful threads:

1 Like
4

Oops. That was a mistake on my end. I meant to use the returned stub with the deadline which is what was actually used in my tests.