DEADLINE_EXCEEDED makes application not receiving messages at all

Environment details

Node.js version: v12.7.0
npm version: 6.10.0
@google-cloud/pubsub version: "^1.0.0",

Error:

insertId: "gnr3q1fz7eerd" jsonPayload: { level: "error" message: "unhandledRejection" originalError: { ackIds: [1] code: 4 details: "Deadline exceeded" } }

After receiving this error, the app does not receive messages anymore and we have to exit the application to recreate the kubernetes pod.

Any help would be appreciated!

@mahaben

Hey @mahaben did this issue recently start happening?

@bcoe

Hey @bcoe, first time after upgrading googlecloud/pubsub to ^1.0.0. Any workaround to recreate subsciption after this error?

We used to see these error messages, we now see these errors in all our projects that use it:

Error: Failed to connect to channel. Reason: Failed to connect before the deadline
    at MessageStream._waitForClientReady (/src/node_modules/@google-cloud/pubsub/build/src/message-stream.js:318:19)

I can confirm this after upgrading to PubSub ^1.0.0, all our services stop sending pubsubs after the error occurs.

The full stacktrace is

Retry total timeout exceeded before any response was received Error: Retry total timeout exceeded before any response was received
    at repeat (/app/node_modules/@google-cloud/pubsub/node_modules/google-gax/build/src/normalCalls/retries.js:80:31)
    at Timeout.setTimeout [as _onTimeout] (/app/node_modules/@google-cloud/pubsub/node_modules/google-gax/build/src/normalCalls/retries.js:113:25)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10)

Can I suggest raising the priority on this issue?

Non of our services using pubsub is working anymore either. We are using version 1.1.0 Getting this:

Error: Retry total timeout exceeded before any response was received
    at repeat (/var/www/app/node_modules/google-gax/build/src/normalCalls/retries.js:80:31)
    at Timeout.setTimeout [as _onTimeout] (/var/www/app/node_modules/google-gax/build/src/normalCalls/retries.js:113:25)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10)

And this:

Error: Failed to connect to channel. Reason: Failed to connect before the deadline
  File "/var/www/app/node_modules/@google-cloud/pubsub/build/src/message-stream.js", line 318, col 19, in MessageStream._waitForClientReady
    throw new ChannelError(e);

We have to restart our services every 10 minutes because of that.

It also seems til it is storing more and more to disk as disk usage goes up over time.

We also are hitting this. It happens after an hour or two and our publishing stops completely.

My only suspicion was that since we created and cached the topic in our constructor, the topic was timing out. we changed our implementation to to call publish like this:

pubsub.topic('xx').publish()

Now I running some tests to see if that was it or not. If not I am out of ideas since our code matches the examples in this repo.

Our platform is node 12 on alpine on GKE.

Seeing the same error Error: Failed to connect to channel. Reason: Failed to connect before the deadline at MessageStream._waitForClientReady with @google-cloud/pubsub 0.31.1, same outcome application cannot receive messages. Does subscription.close().then(() => subscription.open()); help in this case?

Same error here with "@google-cloud/storage": "^3.3.1".

Having

const storage = new Storage({
  projectId: config.googleCloud.projectId
});
const bucket = storage.bucket(config.googleCloud.storage.publicBucketName);

and leaving the nodejs process running, raises the error from time to time.

{ Error: Retry total timeout exceeded before any response was received
    at repeat (/home/deploy/app/node_modules/google-gax/build/src/normalCalls/retries.js:80:31)
    at Timeout.setTimeout [as _onTimeout] (/home/deploy/app/node_modules/google-gax/build/src/normalCalls/retries.js:113:25)
    at ontimeout (timers.js:436:11)
    at tryOnTimeout (timers.js:300:5)
    at listOnTimeout (timers.js:263:5)
    at Timer.processTimers (timers.js:223:10) code: 4 }

Nope. That didn't work. ;-( still getting this.

GoogleError: Retry total timeout exceeded before any response was received
    at repeat (/var/www/app/node_modules/google-gax/src/normalCalls/retries.ts:98:23)
    at Timeout._onTimeout (/var/www/app/node_modules/google-gax/src/normalCalls/retries.ts:140:13)
    at listOnTimeout (internal/timers.js:531:17)
    at processTimers (internal/timers.js:475:7) {
  code: 4
}

Getting similar total timeout exceeded before any response was received errors with subscription.close().then(() => subscription.get());
What is the best approach, should we retry the operation ourselves until it goes through or better tweak the default GAX retry options? (https://googleapis.github.io/gax-nodejs/interfaces/BackoffSettings.html)

To me it seems google pubsub servers have a bug or degraded to a point that it makes them not respond within the expected deadlines.

@bcoe

@bcoe
We run on GKE using credentials passed to PubSub and GoogleAuth (not the GKE service account). Most services run 0.30.1 with google-gax: 1.1.4 & @grpc/grpc-js: 0.4.3 without issues since 0.30.1 was released in Jun. One service was updated to google-gax: 1.6.4 & @grpc/grpc-js: 0.6.6 started observing the issues last week.
We have this solution for token auto-refresh also

this._client = new PubSub({ ...queueConfig, auth: new GoogleAuth(queueConfig) });

Issue doesn't start exactly one hour after start for us so I suspect it is related to connectivity to pubsub servers and how those are rolled in and out of service for updates.
Re-creating the PubSub client (thus the underlying channel) definitely solves this, so I suggest adding this fix to pubsub itself.
We occasionally see deadline exceeded messages in the old services running @grpc/grpc-js: 0.4.3 but those seem to recover all right.
For people that see this happen every hour it may be related to token expiry - unable to refresh the token once it expires - we used to have unauthorised errors without passing that auth parameter.

I'd like to 👍 this going back to a P1. Providing a workaround isn't an acceptable response. Indeed, we have implemented the workaround and rolled out to Prod to see that while it successfully mitigated the lost pub/sub connection, it also introduces a memory leak that requires periodic restart of our k8s pods regardless.

As mentioned on grpc/grpc-node#1064 , this is also an issue that is surfacing when using scheduled Firebase Functions, which you do not have access to the grcp config value. When the connection bridge drops the entire suite of firebase functions hosted also begin to fail. The only workaround is to not have the scheduled function deployed, which is not an acceptable solution.

Error: No connection established at Http2CallStream.call.on (/srv/node_modules/@grpc/grpc-js/build/src/call.js:68:41) at emitOne (events.js:121:20) at Http2CallStream.emit (events.js:211:7) at process.nextTick (/srv/node_modules/@grpc/grpc-js/build/src/call-stream.js:75:22) at _combinedTickCallback (internal/process/next_tick.js:132:7) at process._tickDomainCallback (internal/process/next_tick.js:219:9)

Has there been any progress? If not, and the work around is the official way forward are all the docs updated?

Everytime there has been a new version of @google-cloud/pubsub we've updated, but since grpc-js, we've had increased latency in sending and/or receiving (dependant on version used) or memory leaks. In the past weeks we've been pinning versions to work around various bugs.

We've made the decision to go back to "@google-cloud/pubsub": "0.29.1", as this fixes the problem for us with no code changes.

Could we have a newer pubsub release which enables grpc-js as an option? as this seems the most unstable part of this eco system.

@murgatroid99

I just wanted to give an update before the weekend, we do have a version of @grpc/grpc-js (0.6.9), that all signs are indicating is stable:

the timeout issue, that we had managed to reproduce on one system, are no longer occurring.
folks running this version of the API have, so far, indicated that they're not seeing any issues.
my colleague @murgatroid99 is feeling confident that he addressed the issues that were leading to the known behavior in this thread.

The reason I was holding off on this update, was that we were doing more stress testing on the system that we had managed to reproduce this issue on.

If anyone is still bumping into issues on 0.6.9, please:

open a new issue on PubSub, so that we can debug your issue in isolation (just in case there's more than one thing being debugged in this thread).
run your environment with the following environment variables set:

GRPC_TRACE=all
GRPC_VERBOSITY=DEBUG

provide your logs to us with the gRPC output immediately before an error occurred

So far, with debug information, @murgatroid99 has been able to address issues almost immediately.

If you do not want to share your logs publicly (understandably) you can open an issue through our issue tracker, and also email me (bencoe [at] google.com so that I can make sure it's escalated immediately):

https://issuetracker.google.com/savedsearches/559741

Now, if folks start using @grpc/grpc-js@0.6.9, and it becomes apparent that it is not in fact stable, I will take steps to move us back to grpc immediately in @google-cloud/pubsub (until such time that we are confident).

@bcoe

@bcoe I don't fully understand the fix.

In order to get my system working, a rollback of pubsub to 29.1 wasn't enough. I had to roll back a bunch of other google projects I'm using (logging, storage, kms etc) also. I don't know what combination of rollbacks fixed the problem and so I'm worried about rolling forward now.

What exactly is the proposed fix please?

Which projects do I need to apply the fix to?

I've done a fresh install of 1.1.2 (which now is pulling @grpc/grpc-js@0.6.9) in a project and can confirm it looks stable. I will keep it under observation for the next 24 hours and upgrade the remaining projects based on the results.

After a few more hours of testing, the behaviour has improved but I'm still seeing the odd message being lost and nacked back into the queue, which results in latency spikes. This does not happen with 0.29.1.

This means0.29.1 is still the latest version that is giving us consistently predictable latency and 1.1.2 + @grpc/grpc-js@0.6.9 is still not performing as well as 0.29.1.

@pmcnr-hx

👋 as mentioned Friday, we're testing early this week with @grpc/grpc-js@0.6.9 as a stable release candidate for @grpc/grpc-js.

We ask that folks upgrade to @grpc/grpc-js@0.6.9, and let us know if you have any trouble doing so.

If you continue to run into issues with this new version of the dependency, I ask that we:

1. create a new issue on this repo, which I will prioritize as P1

@pmcnr-hx, I have already done so for the memory issue you've raised.

2. run your system with debugging enabled, so that we can ship logs to the gRPC folks

GRPC_TRACE=all
GRPC_VERBOSITY=DEBUG

3. share the logs with the engineers debugging this issue

You can open an issue on the issue tracker here to deliver the logs, if there's anything you wish to keep private.

https://issuetracker.google.com/savedsearches/559741

You can also send an email to bencoe [at] google.com, so that he can make sure things get escalated appropriately.

If it becomes obvious that things are stable, we will start working on a more significant rollback early this week.

Navigation Menu

Repository navigation

DEADLINE_EXCEEDED makes application not receiving messages at all #770

84 remaining items

1. create a new issue on this repo, which I will prioritize as P1

2. run your system with debugging enabled, so that we can ship logs to the gRPC folks

3. share the logs with the engineers debugging this issue

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

DEADLINE_EXCEEDED makes application not receiving messages at all #770

Description

Activity

bcoe commented on Oct 4, 2019

mahaben commented on Oct 5, 2019

hx-markterry commented on Oct 6, 2019

WaldoJeffers commented on Oct 7, 2019

maxmoeschinger commented on Oct 7, 2019

ddehghan commented on Oct 7, 2019

pworkpop commented on Oct 7, 2019

Tolgor commented on Oct 7, 2019

ddehghan commented on Oct 8, 2019

pworkpop commented on Oct 8, 2019

84 remaining items

pworkpop commented on Oct 16, 2019

ringzhz commented on Oct 17, 2019

mrmodelo commented on Oct 18, 2019

npomfret commented on Oct 18, 2019

hx-markterry commented on Oct 18, 2019

bcoe commented on Oct 18, 2019

npomfret commented on Oct 21, 2019

pmcnr-hx commented on Oct 21, 2019

pmcnr-hx commented on Oct 21, 2019

bcoe commented on Oct 21, 2019

1. create a new issue on this repo, which I will prioritize as P1

2. run your system with debugging enabled, so that we can ship logs to the gRPC folks

3. share the logs with the engineers debugging this issue

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions