grpc / grpc-java

The Java gRPC implementation. HTTP/2 based RPC
https://grpc.io/docs/languages/java/
Apache License 2.0
11.48k stars 3.85k forks source link

Java client does not respect deadline #11643

Closed kv83821-yb closed 3 weeks ago

kv83821-yb commented 3 weeks ago

What version of gRPC-Java are you using?

1.63.1

What is your environment?

Linux Java: openjdk 17.0.8.1 2023-08-24 LTS

What did you expect to see?

The client should fail with a StatusRuntimeException and DEADLINE_EXCEEDED in the error message.

What did you see instead?

The deadline I set was for 1200 seconds or 20 minutes.

bkpSvcBlockingStub.withDeadlineAfter(1200000L, TimeUnit.MILLISECONDS);

The call just hangs:

"TaskPool-CreateBackup(82807b65-0600-478e-9a8b-501b37e79216)-0" #31887 prio=5 os_prio=0 cpu=135.57ms elapsed=1661.96s allocated=34249K defined_classes=1 tid=0x00007f7470345ab0 nid=0x503 waiting on condition  [0x00007f73c3d4e000]
   java.lang.Thread.State: WAITING (parking)
    at jdk.internal.misc.Unsafe.park(java.base@17.0.8.1/Native Method)
    - parking to wait for  <0x00000007fd67abe0> (a io.grpc.stub.ClientCalls$ThreadlessExecutor)
    at java.util.concurrent.locks.LockSupport.park(java.base@17.0.8.1/LockSupport.java:211)
    at io.grpc.stub.ClientCalls$ThreadlessExecutor.waitAndDrain(ClientCalls.java:717)
    at io.grpc.stub.ClientCalls.blockingUnaryCall(ClientCalls.java:159)
    at org.yb.ybc.BkpSvcGrpc$BkpSvcBlockingStub.backupServiceTaskProgress(BkpSvcGrpc.java:634)
    at org.yb.client.YbcClient.sendRequest(YbcClient.java:228)
    - locked <0x00000007fda60878> (a org.yb.client.YbcClient)
    at org.yb.client.YbcClient.backupServiceTaskProgress(YbcClient.java:362)
    at com.yugabyte.yw.commissioner.YbcTaskBase.pollTaskProgress(YbcTaskBase.java:49)
    at com.yugabyte.yw.commissioner.tasks.subtasks.BackupTableYbc.run(BackupTableYbc.java:208)
    at com.yugabyte.yw.commissioner.TaskExecutor$AbstractRunnableTask.run(TaskExecutor.java:935)
    at com.yugabyte.yw.commissioner.TaskExecutor$RunnableSubTask.run(TaskExecutor.java:1366)
    at java.util.concurrent.Executors$RunnableAdapter.call(java.base@17.0.8.1/Executors.java:539)
    at java.util.concurrent.FutureTask.run(java.base@17.0.8.1/FutureTask.java:264)
    at com.yugabyte.yw.common.logging.MDCAwareRunnable.run(MDCAwareRunnable.java:46)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@17.0.8.1/ThreadPoolExecutor.java:1136)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@17.0.8.1/ThreadPoolExecutor.java:635)
    at java.lang.Thread.run(java.base@17.0.8.1/Thread.java:833)

As evident the time elapsed is 1661.96s. The client should kill the current request.

Steps to reproduce the bug

kv83821-yb commented 3 weeks ago

Found the problem, I was using the ongoing stub with the deadline instead of using the new stub that is returned.