Nodejs-pubsub: Errors in ack and modAck possibly causing UnhandledPromiseRejectionWarning outside of user defined handlers

[benmadany]

Environment details

• @google-cloud/pubsub version: 1.5.0
  Running in a container based on the node 10.19.0-slim image

Steps to reproduce

It may be difficult to reproduce, I encountered this in a couple cases, first during the outage of gcp services around 7:30am PST on April 8th (gcp incident) and then again a day later around 11:15am PST on April 9th without any accompanying gcp outage.

In both cases, I received several errors that resulted in an UnhandledPromiseRejectionWarning. The cause of the errors differed, with the gcp incident explaining the first day's issues and an "RST_STREAM with code 2" error on the second day. However my main issue is with the fact that these errors appeared to be happening completely separately from the message and error handlers I had included on the subscription. I noticed that the errors were often occurring in attempts to either ack or modAck a message. However this would happen before any code I had written attempted to do either (I have several log statements before the only possible ack and nack calls I make, and none were hit) and would not trigger any logs in the error handler either. On searching through the source here, it seemed possible to me that the _onData method of subscriber.ts here could be the source of the modAck call that was experiencing the error.

I'm hoping I can get some clarification on the issue here and any suggestions on what to do to mitigate. Handling the errors themselves with restarts of the subscription is fine, but because they appear to be happening outside of the handlers I have written it makes it more difficult to deal with.

Thanks very much!

[feywind]

@benmadany I wonder if this is related to this issue... https://github.com/googleapis/nodejs-pubsub/issues/979

The 1.5.0 version of the library is where those defaults were changed.

[feywind]

I've been looking at this a bit, and I think there might just need to be a few extra catch handlers to direct things into the error handler. Still looking today.

[feywind]

@benmadany Is this still an issue for you? I think I might've found a way those errors could escape into an unhandled promise error, but I'd love to get some more details of how you're calling the library to verify that my fix actually fixes the issue for you.

[benmadany]

I don't think I've seen it happen much since, it seemed to be related to other transient problems at the time.

I've just been creating a subscription, adding various handlers for message, error, etc, and then subscribing to it. I can try to be more detailed if necessary. Thanks for looking into this.

[jhon0010]

Hi there, I'm also facing this issue, this started to happen yesterday when I try to create a new topic with 2 subscriptions.

My versions:

"@google-cloud/pubsub": "^2.3.0"
"ts-node": "^8.6.2"

It could be a limit on handling subscriptions from NodeJS, I am also using Typescript ?

[feywind]

The specific thing I was looking at today might happen under heavy load. Basically if a message gets added to the ack or modAck queues, and it exceeds the maxMessages setting, it's possible for an exception to escape without a catch handler. It's not totally clear to me if that's a new thing because of Node promise handling changes over the years, because it relies on someone calling resolve() on a deferred promise, and having that subsequent async code run immediately.

Anyhow! I've got a really simple test to show that that can happen outside of Pub/Sub, and I'm working on a new unit test to see if I can get it to fail in the library. If that's the problem, it should be pretty straightforward to fix.

[feywind]

I thought I had a handle on this, but I don't seem to be able to reproduce it in the unit tests still, and after studying all the async/await logic, I'm not completely sure how it would escape catch handlers. If either of you are still having this problem, can you try running your app with the environment variable DEBUG_GRPC set to 1 and then capture the full stack traces?

[feywind]

I'm going to go ahead and close this for now, but please feel free to re-open it with stack traces and such. I'm still interested to see if there's an issue there.