Nodejs-pubsub: user witnessing timeouts on @grpc/[email protected]

[bcoe]

_@ericpearson, I went ahead and opened this issue in reference to the discussion in #790._

I'd like start delving in a bit deeper, so that we can hopefully figure out a pattern in the timeouts you're seeing.

Environment details

• OS/platform: What are you running @google-cloud/pubsub on, Google App Engine, Kubernetes Engine, other infrastructure?
• Node.js version: ?
• npm version: ?
• @google-cloud/pubsub version: ?? (Is PubSub a good place for us to start with debugging, you'd mentioned you'd seen the issue with some other grpc libs, but PubSub tends to be people's highest workload).

Getting us debug information

If you run one of your clients with the following environment variables set:

export GRPC_TRACE=all
export GRPC_VERBOSITY=DEBUG

or in your application run the following (before your pubsub import):

process.env.GRPC_TRACE = 'all';
process.env.GRPC_VERBOSITY = 'DEBUG';
const {PubSub} = require('@google-cloud/pubsub');

:point_up: we will start seeing detailed grpc logs, and should be able to identify exactly what happened immediately before a message timing out.

To get the logs over to me, you can both open an issue:

https://issuetracker.google.com/savedsearches/559741, and send an email my way so that I can make sure the grpc team gets the logs immediately (I'm ben [at] google.com).

[bcoe]

ericpearson reports that they are continuing to see unstable behavior and memory issues

@ericpearson I believe that you are continuing to see some issues, but could I bother you to start providing some debug information here :+1:

Alternatively, if grpc is an acceptable workaround for your use-case, we can close out this issue.

[oande]

Heya. Not sure I'm experiencing the same timeout you're referring to, but client.pull(request) throws the below error for me after a few seconds of no messages in PubSub (works fine when handling new messages):

Pulling pubsub message...
2019-10-25T08:09:04.223Z | resolving_load_balancer | pubsub.googleapis.com:443 IDLE -> IDLE
2019-10-25T08:09:04.223Z | connectivity_state | pubsub.googleapis.com:443 IDLE -> IDLE
2019-10-25T08:09:04.224Z | dns_resolver | Resolver constructed for target pubsub.googleapis.com:443
2019-10-25T08:09:04.228Z | dns_resolver | Resolution update requested for target pubsub.googleapis.com:443
2019-10-25T08:09:04.230Z | resolving_load_balancer | pubsub.googleapis.com:443 IDLE -> CONNECTING
2019-10-25T08:09:04.230Z | connectivity_state | pubsub.googleapis.com:443 IDLE -> CONNECTING
2019-10-25T08:09:04.230Z | resolving_load_balancer | pubsub.googleapis.com:443 CONNECTING -> CONNECTING
2019-10-25T08:09:04.230Z | connectivity_state | pubsub.googleapis.com:443 CONNECTING -> CONNECTING
2019-10-25T08:09:04.231Z | resolving_load_balancer | pubsub.googleapis.com:443 IDLE -> IDLE
2019-10-25T08:09:04.231Z | connectivity_state | pubsub.googleapis.com:443 IDLE -> IDLE
2019-10-25T08:09:04.231Z | dns_resolver | Resolver constructed for target pubsub.googleapis.com:443
2019-10-25T08:09:04.392Z | dns_resolver | Resolved addresses for target pubsub.googleapis.com:443: 74.125.71.95:443
2019-10-25T08:09:04.392Z | pick_first | IDLE -> IDLE
2019-10-25T08:09:04.393Z | resolving_load_balancer | pubsub.googleapis.com:443 CONNECTING -> IDLE
2019-10-25T08:09:04.393Z | connectivity_state | pubsub.googleapis.com:443 CONNECTING -> IDLE
2019-10-25T08:09:04.393Z | pick_first | Connect to address list 74.125.71.95:443
2019-10-25T08:09:04.393Z | pick_first | Start connecting to subchannel with address 74.125.71.95:443
2019-10-25T08:09:04.393Z | pick_first | IDLE -> CONNECTING
2019-10-25T08:09:04.393Z | resolving_load_balancer | pubsub.googleapis.com:443 IDLE -> CONNECTING
2019-10-25T08:09:04.393Z | connectivity_state | pubsub.googleapis.com:443 IDLE -> CONNECTING
2019-10-25T08:09:04.394Z | subchannel | 74.125.71.95:443 IDLE -> CONNECTING
2019-10-25T08:09:04.402Z | pick_first | CONNECTING -> CONNECTING
2019-10-25T08:09:04.402Z | resolving_load_balancer | pubsub.googleapis.com:443 CONNECTING -> CONNECTING
2019-10-25T08:09:04.402Z | connectivity_state | pubsub.googleapis.com:443 CONNECTING -> CONNECTING
2019-10-25T08:09:04.484Z | subchannel | 74.125.71.95:443 CONNECTING -> READY
2019-10-25T08:09:04.485Z | pick_first | Pick subchannel with address 74.125.71.95:443
2019-10-25T08:09:04.485Z | pick_first | CONNECTING -> READY
2019-10-25T08:09:04.485Z | resolving_load_balancer | pubsub.googleapis.com:443 CONNECTING -> READY
2019-10-25T08:09:04.494Z | connectivity_state | pubsub.googleapis.com:443 CONNECTING -> READY
Error: 4 DEADLINE_EXCEEDED: Deadline exceeded
    at Object.callErrorFromStatus (/Users/oskara/Code/pubsub-test/node_modules/@grpc/grpc-js/build/src/call.js:30:26)
    at Http2CallStream.<anonymous> (/Users/oskara/Code/pubsub-test/node_modules/@grpc/grpc-js/build/src/client.js:96:33)
    at Http2CallStream.emit (events.js:208:15)
    at /Users/oskara/Code/pubsub-test/node_modules/@grpc/grpc-js/build/src/call-stream.js:75:22
    at processTicksAndRejections (internal/process/task_queues.js:75:11) {
  code: 4,
  details: 'Deadline exceeded',
  metadata: Metadata { internalRepr: Map {}, options: {} },
  note: 'Exception occurred in retry method that was not classified as transient'
}

OS/platform: GKE 1.12.9-gke.15 (image based on node:12.13-slim), and MacOS 10.14.6
Node.js version: 12.13 & 12.6.0
npm version: 6.9.0
@google-cloud/pubsub: 1.5.1
@grpc/grpc-js: 0.6.9

[bcoe]

@oande thank you for the debug information, I'll share with with folks on the grpc team 👍

How frequently is this happening to you?

[callmehiphop]

@oande do you know if you see the deadline error when there are messages waiting to be consumed? I ask because I am pretty sure that pull will give a deadline error in the event that it finds no messages after a certain period of time (1 minute)

[oande]

I had another look today, turns out all timeouts occur after 5s of no messages. Seems to be by design, from this config value? https://github.com/googleapis/nodejs-pubsub/blob/master/src/v1/subscriber_client_config.json#L29

However if I increase the timeout, I get an empty array back after ~20s

{"receivedMessages":[]}

I've found two ways (below) to change the timeout...

client.pull(request, {retry: {}})

...where 60s from the config will be used: https://github.com/googleapis/nodejs-pubsub/blob/master/src/v1/subscriber_client_config.json#L81

Or setting it directly (though still seem to require a retry object):

client.pull(request, {timeout: 30000, retry: {}})

Any recommendations?

[callmehiphop]

@oande I would probably just increase the timeout myself. It looks like you're finding yourself with an empty queue and IMO it would be better to wait than to make additional requests that will likely timeout as well.

[bcoe]

@oande, did increasing the timeout help. @callmehiphop is this perhaps something we could document in the README, in a section on increasing timeouts timeout errors?

I'm wondering if this might be the underlying cause of a few of these reports.

[callmehiphop]

@bcoe pull is exclusively a gapic method, we don't support it in the veneer, so I'm not really sure what the best way for us to document this is.

It's also worth noting that pull behaves a little bit differently than most rpcs, in that if there are no messages in the queue the rpc itself will attempt to wait until there are. If no messages show up, then eventually we'll hit a deadline error. This is because gax applies a deadline to every rpc with no way to opt out of it.

That being said, I think we should always expect to see questions about deadline errors because they can actually prevent streams from closing gracefully via the server.

[oande]

@bcoe yeah it helps -- and I agree it would be helpful to include in the README!

[bcoe]

@oande I've created a tracking issue to add tuning documentation to our README.md:

https://github.com/googleapis/nodejs-pubsub/issues/810

---

I'm closing this issue for the time being, due to lack of information about the original underlying bug. @ericpearson, please don't hesitate to re-open if you're continuing to bump into issue,s and can provide some specific debugging information about the timeouts you're seeing.

[npomfret]

The "Deadline exceeded" bug is back for me using:

  "dependencies": {
    "@google-cloud/firestore": "^2.6.0",
    "@google-cloud/logging": "5.5.5",
    "@google-cloud/logging-bunyan": "^2.0.0",
    "@google-cloud/pubsub": "1.1.5",

I thought it was fixed? This is the error:

{"ackIds":["KlgRTgQhIT4wPkVTRFAGFixdRkhRNxkIaFEOT14jPzUgKEUaAiBuFD1CWhoOB1xcdQdRDB8neDB2a1xHUwFPU3RfcysvV1RYcgBWCRtye2d0bFsVAyrBuOnH3ZuSWUZgTc3pmMdHXbXW3-giZh49WxJLLD5-MzVFQV5AEkw4AERJUytDCw"],"code":4,"details":"Deadline exceeded","metadata":{"internalRepr":{},"options":{}}}

Is there any more information I can provide?

[JasperWoo]

@npomfret Hi, in which API call are you getting this Deadline Exceeded error?

[npomfret]

pubsub

[bcoe]

@npomfret as @callmehiphop mentions in this thread, one thing that can happen is that a pull occurs, and it times out because there are no messages available (it getting close to the holiday season, I wonder if it could potentially be less messages in the pipeline as an example).

Have you tried increasing the timeout, like @oande suggests in this thread:

client.pull(request, {timeout: 300000, retry: {}}) // as an example.

[npomfret]

I'm not using the pull api.

[bcoe]

@npomfret bother you to open a new issue with a specific breakdown of the bug you're seeing. I think useful additional information would be:

1. @grpc/grpc-js version you're on.

2. if you're able to run with debug enabled, I've found this has helped a ton in isolating issues.

   export GRPC_TRACE=all
   export GRPC_VERBOSITY=DEBUG
   

3. frequency with which you're seeing this issue; _is it happening periodically in your logs? all the time?_

Thanks for your patience.