googleapis / googleapis/google-cloud-node
v1.SubscriberClient#streamingPull throws DEADLINE_EXCEEDED error after 15 minutes
- Dominant language
- TypeScript
- Stars
- 3.2k
- Forks
- 712
- Avg merge
- 2d 3h
- Merged PRs (30d)
- 99
Description
We use `v1.SubscriberClient#streamingPull` method to create a bidirectional stream which we use to consume and ack Pub/Sub messages. After 15 minutes client throws the `DEADLINE_EXCEEDED` (code 4) error. We have put a lot of effort to investigate why and where this error is thrown.
There is a default 15 minute timeout for `streamingPull` RPC call which is defined in `@google-cloud/pubsub` library [here](https://github.com/googleapis/nodejs-pubsub/blob/b1069e4c05541f80b29812b391cc81b1ef0bd745/src/v1/subscriber_client_config.json#L93-L96). It is possible to override this timeout by providing a different value when calling `streamingPull` method like so:
```js
const subscriber = new v1.SubscriberClient()
const stream = subscriber.streamingPull({ timeout: 60 * 60 * 1000 /* 1 hour */ })
```
However, this only postpones the throwing of the `DEADLINE_EXCEEDED` error.
We have tracked down where this error is thrown, and it happens in `@grpc/grpc-js` library in `ResolvingCall` class in [`runDeadline` method](https://github.com/grpc/grpc-node/blob/5b44a4428fd4a9a9ee6521a3a8bd7f8bb7982841/packages/grpc-js/src/resolving-call.ts#L98-L113). This timer which is set on creation of the `ResolvingCall` class should be cleared when the response is received in the [`outputStatus` method](https://github.com/grpc/grpc-node/blob/5b44a4428fd4a9a9ee6521a3a8bd7f8bb7982841/packages/grpc-js/src/resolving-call.ts#L115-L135). The `outputStatus` method is called from [`onReceiveStatus` handler](https://github.com/grpc/grpc-node/blob/5b44a4428fd4a9a9ee6521a3a8bd7f8bb7982841/packages/grpc-js/src/resolving-call.ts#L242C11-L242C26), or from [`onReceiveMessage` handler](https://github.com/grpc/grpc-node/blob/5b44a4428fd4a9a9ee6521a3a8bd7f8bb7982841/packages/grpc-js/src/resolving-call.ts#L225) if certain conditions are true.
However, `onReceiveStatus` handler is NEVER called, which can be seen if you turn on debug logs:
```
GRPC_NODE_VERBOSITY=DEBUG
GRPC_NODE_TRACE=resolving_call # only focus on resolving_call class
```
Then you can clearly see that `resolving_call` is instantiated and that timer is created.
```
D 2024-02-08T14:46:36.689Z | v1.9.14 54511 | resolving_call | [0] Created
D 2024-02-08T14:46:36.689Z | v1.9.14 54511 | resolving_call | [0] Deadline: 2024-02-08T15:01:36.688Z
D 2024-02-08T14:46:36.689Z | v1.9.14 54511 | resolving_call | [0] Deadline will be reached in 899999ms
```
When message is received you also see:
```
D 2024-02-08T14:50:18.370Z | v1.9.14 54731 | resolving_call | [0] Received message
D 2024-02-08T14:50:18.371Z | v1.9.14 54731 | resolving_call | [0] Finished filtering received message
```
But you never see [`Received status` log](https://github.com/grpc/grpc-node/blob/5b44a4428fd4a9a9ee6521a3a8bd7f8bb7982841/packages/grpc-js/src/resolving-call.ts#L243), which means that `outputStatus` method never gets called to reset the DEADLINE_EXCEEDED timer.
I believe that this is a bug, and keep in mind that this only happens with `v1.SubscriberClient`, but works correctly with latest `Subscription` class. When using that class, grpc debug output looks different, and you see 'Received status' logs, which means that timer gets restarted every time you receive the message.
```
D 2024-02-08T14:58:18.115Z | v1.9.14 55006 | resolving_call | [20] Received metadata
D 2024-02-08T14:58:18.115Z | v1.9.14 55006 | resolving_call | [20] Received message
D 2024-02-08T14:58:18.115Z | v1.9.14 55006 | resolving_call | [20] Finished filtering received message
D 2024-02-08T14:58:18.119Z | v1.9.14 55006 | resolving_call | [20] Received status
D 2024-02-08T14:58:18.119Z | v1.9.14 55006 | resolving_call | [20] ended with status: code=0 details=""
```
#### Environment details
- OS: MacOS 14.2.1
- Node.js version: 20.11.0
- npm version: 10.2.4
- `@google-cloud/pubsub` version: 4.3.0
#### Steps to reproduce
Check the repository with the code and instructions to reproduce the issue:
https://github.com/emartech/pub-sub-deadline-exceeded-repro
Contributor guide
Assessment
This issue has not been assessed yet.