Nodejs-pubsub: DEADLINE_EXCEEDED makes application not receiving messages at all

Created on 4 Oct 2019  ·  99Comments  ·  Source: googleapis/nodejs-pubsub

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!

pubsub needs more info p1 bug
Source
picture mahaben
👍12

Most helpful comment

@pwrkpop @npomfret @xoraingroup, rather than rolling back to 0.29.1 of @google-cloud/pubsub I recommend one of the following workarounds:

Using grpc, rather than @grpc/grpc-js

  1. inside your project which uses @google-cloud/pubsub, add the dependency grpc (this is the old gRPC transport layer).

  2. use the following code when creating your library:

    const {PubSub} = require('@google-cloud/pubsub');
const grpc = require('grpc');
const pubsub = new PubSub({grpc});

:point_up: this same approach can be used for other libraries that use gRPC, e.g.,

const grpc = require('grpc');
const {Logging} = require('@google-cloud/logging');
const logger = new Logging({grpc});

Using the workaround recommended by @Redgwell


const initSubscriber = () => {
  const pubsub = new PubSub();
  const subscription = pubsub.subscription(topic, options);
  subscription.on('message', handler.handleMessage);
  subscription.on('error', e => {
    initSubscriber();  });
};

initSubscriber();

We potentially have a reproduction of the issue described in this thread (thanks @Redgwell for pointing us in the right direction), and will hopefully have a fix out soon that makes either of these workaround unnecessary.

picture bcoe on 11 Oct 2019
🎉9

All 99 comments

Hey @mahaben did this issue recently start happening?

bcoe picture bcoe on 4 Oct 2019

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

mahaben picture mahaben on 5 Oct 2019
👍2

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)
hx-markterry picture hx-markterry on 6 Oct 2019
👍5

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?

WaldoJeffers picture WaldoJeffers on 7 Oct 2019
👍5

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.

maxmoeschinger picture maxmoeschinger on 7 Oct 2019
👍2

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.

ddehghan picture ddehghan on 7 Oct 2019

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?

pworkpop picture pworkpop on 7 Oct 2019

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 }
Tolgor picture Tolgor on 7 Oct 2019

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
}
ddehghan picture ddehghan on 8 Oct 2019
👍3

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.

pworkpop picture pworkpop on 8 Oct 2019

I have now downgraded to @google-cloud/pubsub version 0.31.0 and added this to my package.json:

"resolutions": {
        "google-gax": "1.3.0"
}

Seems like things are working for longer than 10 minutes now.

maxmoeschinger picture maxmoeschinger on 8 Oct 2019

Hello,
We hit the same problem here since 10/02.
We tried upgrading to 0.32.1, and even to 1.1.0.
Didn't solve a thing.
We are running in App Engine, so when one of the instances starts hitting the error, it snowballs and errors flow like crazy until the instance gets killed and another instance starts. Then, errors stop flowing for a bit.

FabianHutin picture FabianHutin on 8 Oct 2019
👍2

Since https://github.com/grpc/grpc-node/issues/1064#issuecomment-539432287

Using

"resolutions": {
    "@grpc/grpc-js": "^0.6.6"
}

as a temporary fix, works for me.

Tolgor picture Tolgor on 8 Oct 2019

I'm putting this issue at the top of my list. Would anyone be able to re-test with the latest version of gRPC? A release (v0.6.6) went out yesterday and it may or may not have a fix for this. All that should be needed is to delete any lock files you might have and re-install the PubSub client with the same version you currently have pinned.

callmehiphop picture callmehiphop on 8 Oct 2019

I believe we are hitting this one as well. After the application runs fine for several hours, we get the following logged from the subscription error handler. New messages that usually arrive once a minute have stopped arriving 5 minutes earlier.

image

wondering if this issue is related to this @bcoe are you thinking the same?

Here are some environment details:

GKE: 1.14.3-gke.11
nodejs: FROM node:10.14-alpine

# yarn list | grep google
├─ @axelspringer/[email protected]
│  ├─ @google-cloud/[email protected]
│  ├─ @google-cloud/pubsub@^0.28.1
│  ├─ @google-cloud/[email protected]
│  │  ├─ @google-cloud/paginator@^0.2.0
│  │  ├─ @google-cloud/precise-date@^0.1.0
│  │  ├─ @google-cloud/projectify@^0.3.0
│  │  ├─ @google-cloud/promisify@^0.4.0
│  │  ├─ google-auth-library@^3.0.0
│  │  ├─ google-gax@^0.25.0
│  ├─ [email protected]
│  ├─ [email protected]
│  │  ├─ google-auth-library@^3.0.0
│  │  ├─ google-proto-files@^0.20.0
│  ├─ [email protected]
│  │  ├─ @google-cloud/promisify@^0.4.0
├─ @google-cloud/[email protected]
│  ├─ @google-cloud/common@^2.0.0
│  ├─ @google-cloud/[email protected]
│  │  ├─ @google-cloud/projectify@^1.0.0
│  │  ├─ @google-cloud/promisify@^1.0.0
│  │  ├─ google-auth-library@^5.0.0
│  ├─ @google-cloud/projectify@^1.0.0
│  ├─ @google-cloud/promisify@^1.0.0
│  ├─ @google-cloud/[email protected]
├─ @google-cloud/[email protected]
│  ├─ @google-cloud/projectify@^0.3.3
│  ├─ @google-cloud/[email protected]
│  ├─ @google-cloud/promisify@^0.4.0
│  ├─ google-auth-library@^3.1.1
│  ├─ [email protected]
├─ @google-cloud/[email protected]
│  └─ google-gax@^1.0.0
├─ @google-cloud/[email protected]
│  ├─ [email protected]
│  ├─ google-gax@^0.17.1
│  ├─ [email protected]
│  │  ├─ google-auth-library@^1.6.1
│  │  ├─ google-proto-files@^0.16.0
├─ @google-cloud/[email protected]
│  ├─ @google-cloud/logging@^5.3.1
│  ├─ google-auth-library@^5.2.2
├─ @google-cloud/[email protected]
│  ├─ @google-cloud/common-grpc@^1.0.5
│  ├─ @google-cloud/paginator@^2.0.0
│  ├─ @google-cloud/[email protected]
│  ├─ @google-cloud/projectify@^1.0.0
│  ├─ @google-cloud/promisify@^1.0.0
│  ├─ @google-cloud/[email protected]
│  ├─ google-auth-library@^5.2.2
│  ├─ google-gax@^1.0.0
├─ @google-cloud/[email protected]
├─ @google-cloud/[email protected]
├─ @google-cloud/[email protected]
├─ @google-cloud/[email protected]
├─ @google-cloud/[email protected]
│  ├─ @google-cloud/paginator@^2.0.0
│  ├─ @google-cloud/[email protected]
│  ├─ @google-cloud/precise-date@^1.0.0
│  ├─ @google-cloud/[email protected]
│  ├─ @google-cloud/projectify@^1.0.0
│  ├─ @google-cloud/promisify@^1.0.0
│  ├─ @google-cloud/[email protected]
│  ├─ google-auth-library@^5.0.0
│  ├─ google-gax@^1.0.0
├─ @google-cloud/[email protected]
│  ├─ @google-cloud/common@^0.32.0
│  ├─ @google-cloud/paginator@^0.2.0
│  ├─ @google-cloud/promisify@^0.4.0
├─ @google/[email protected]
│  ├─ @google-cloud/[email protected]
│  ├─ @google-cloud/[email protected]
│  ├─ @google-cloud/[email protected]
│  ├─ @google-cloud/[email protected]
│  ├─ @google-cloud/[email protected]
│  ├─ @google-cloud/[email protected]
│  ├─ @google/[email protected]
│  ├─ @types/[email protected]
├─ @types/[email protected]
│  ├─ google-libphonenumber@^3.1.6
│  ├─ google-auth-library@^3.0.0
│  ├─ [email protected]
├─ [email protected]
│  ├─ [email protected]
│  │  ├─ google-p12-pem@^2.0.0
├─ [email protected]
│  ├─ google-auth-library@^5.0.0
├─ [email protected]
├─ [email protected]
├─ [email protected]
│  ├─ google-p12-pem@^1.0.0
├─ [email protected]
│  ├─ [email protected]
│  └─ [email protected]
├─ [email protected]
├─ [email protected]
gae123 picture gae123 on 8 Oct 2019

@gae123 mind adding grpc to that grep? The specific dependency having issues is a sub-dependency of pubsub.

One thing that is jumping out at me immediately though, is that you're not running [email protected]? So it would appear you're actually having issues with the < 1.0.0 version of PubSub?

bcoe picture bcoe on 8 Oct 2019

@gae123 I would, if possible, suggest trying out [email protected] as (outside of the rough week of hot fixes we've had) we've been working hard to improve stability.

@mahaben are you able to ry out 0.6.6 of grpc-js as well, sounds like this fix might be on the right track.

bcoe picture bcoe on 8 Oct 2019

@gae123 mind adding grpc to that grep? The specific dependency having issues is a sub-dependency of pubsub.

@bcoe I have modified the original post to add the information you asked for

gae123 picture gae123 on 8 Oct 2019

@mahaben closing this for now, as we believe it is fixed with the latest version of PubSub we've released.

@gae123 could I bother you to open a new issue. The dependency graph you're using is using PubSub in a variety of places, as a deep dependency, but none of the versions linked are up-to-date. I believe you are running into different issues related to older versions of the grpc library.

bcoe picture bcoe on 8 Oct 2019

@bcoe @callmehiphop I don't think this issue should be closed. It still doesn't work after upgrading to "@google-cloud/pubsub": "^1.1.1"

mahaben picture mahaben on 9 Oct 2019

@mahaben have you tried running against the latest version (v1.1.1)?

callmehiphop picture callmehiphop on 9 Oct 2019

@callmehiphop yes I tried with (v1.1.1) after deleting lock file..

mahaben picture mahaben on 9 Oct 2019

@mahaben well that's no good, could you run npm ls and give me a print out of your dependency tree?

callmehiphop picture callmehiphop on 9 Oct 2019 
├─┬ @google-cloud/[email protected]
│ ├─┬ @google-cloud/[email protected]
│ │ ├── [email protected] deduped
│ │ └── [email protected] deduped
│ ├── @google-cloud/[email protected]
│ ├── @google-cloud/[email protected]
│ ├── @google-cloud/[email protected]
│ ├─┬ @grpc/[email protected]
│ │ └── [email protected]
│ ├── @sindresorhus/[email protected]
│ ├─┬ @types/[email protected]
│ │ └── @types/[email protected]
│ ├── @types/[email protected]
│ ├── [email protected]
│ ├── [email protected]
│ ├── [email protected]
│ ├─┬ [email protected]
│ │ ├── [email protected] deduped
│ │ ├── [email protected]
│ │ ├── [email protected]
│ │ ├─┬ [email protected]
│ │ │ ├── [email protected] deduped
│ │ │ ├── [email protected] deduped
│ │ │ ├─┬ [email protected]
│ │ │ │ ├─┬ [email protected]
│ │ │ │ │ └─┬ [email protected]
│ │ │ │ │   └── [email protected]
│ │ │ │ └─┬ [email protected]
│ │ │ │   └── [email protected] deduped
│ │ │ └── [email protected] deduped
│ │ ├─┬ [email protected]
│ │ │ ├── [email protected] deduped
│ │ │ └─┬ [email protected]
│ │ │   └── [email protected]
│ │ ├─┬ [email protected]
│ │ │ ├── [email protected] deduped
│ │ │ ├─┬ [email protected]
│ │ │ │ └── [email protected]
│ │ │ ├── [email protected] deduped
│ │ │ └── [email protected]
│ │ ├─┬ [email protected]
│ │ │ ├─┬ [email protected]
│ │ │ │ ├── [email protected]
│ │ │ │ ├─┬ [email protected]
│ │ │ │ │ └── [email protected] deduped
│ │ │ │ └── [email protected] deduped
│ │ │ └── [email protected]
│ │ └─┬ [email protected]
│ │   └── [email protected]
│ ├─┬ [email protected]
│ │ ├─┬ @grpc/[email protected]
│ │ │ └── [email protected] deduped
│ │ ├─┬ @grpc/[email protected]
│ │ │ ├── [email protected]
│ │ │ └── [email protected] deduped
│ │ ├─┬ [email protected]
│ │ │ └── [email protected]
│ │ ├─┬ [email protected]
│ │ │ ├─┬ [email protected]
│ │ │ │ └─┬ [email protected]
│ │ │ │   └── [email protected]
│ │ │ ├── [email protected]
│ │ │ ├─┬ [email protected]
│ │ │ │ ├── [email protected]
│ │ │ │ ├── [email protected] deduped
│ │ │ │ ├── [email protected]
│ │ │ │ ├── [email protected]
│ │ │ │ ├── [email protected]
│ │ │ │ ├─┬ [email protected]
│ │ │ │ │ └── [email protected]
│ │ │ │ └── [email protected]
│ │ │ └── [email protected]
│ │ ├── [email protected] deduped
│ │ ├── [email protected] deduped
│ │ ├── [email protected]
│ │ ├── [email protected]
│ │ ├── [email protected]
│ │ ├── [email protected] deduped
│ │ ├─┬ [email protected]
│ │ │ ├─┬ [email protected]
│ │ │ │ └── [email protected]
│ │ │ └─┬ [email protected]
│ │ │   └── [email protected] deduped
│ │ ├── [email protected] deduped
│ │ └── [email protected]
│ ├── [email protected]
│ ├── [email protected]
│ ├── [email protected]
│ └─┬ [email protected]
│   ├── @protobufjs/[email protected]
│   ├── @protobufjs/[email protected]
│   ├── @protobufjs/[email protected]
│   ├── @protobufjs/[email protected]
│   ├─┬ @protobufjs/[email protected]
│   │ ├── @protobufjs/[email protected] deduped
│   │ └── @protobufjs/[email protected] deduped
│   ├── @protobufjs/[email protected]
│   ├── @protobufjs/[email protected]
│   ├── @protobufjs/[email protected]
│   ├── @protobufjs/[email protected]
│   ├── @protobufjs/[email protected]
│   ├── @types/[email protected] deduped
│   ├── @types/[email protected]
│   └── [email protected]
├── [email protected]
└─┬ [email protected]
  └── [email protected]
mahaben picture mahaben on 9 Oct 2019

@mahaben thanks! Are you still experiencing the same exact issue you mentioned in the issue overview? After re-reading the thread, I have reason to believe that the issue you are experiencing might be different than what the other users here are seeing.

callmehiphop picture callmehiphop on 9 Oct 2019

@callmehiphop An earlier suggestion in this thread to use the latest @grpc/grpc-js (v0.6.6) didn't quite work for some customers. They reported the same error with high volume of incoming messages unless they restarted the affected instances.

Error: Retry total timeout exceeded before any response was received

      1. at repeat (
      /app/node_modules/google-gax/build/src/normalCalls/retries.js:80)
      2. at Timeout._onTimeout (
      /app/node_modules/google-gax/build/src/normalCalls/retries.js:113)

I see a new release of @grpc/grpc-js (v0.6.7) but is that where the issue is?

anguillanneuf picture anguillanneuf on 9 Oct 2019

@anguillanneuf that is a good question, I'm still trying to play catch up from last week. @alexander-fenster @bcoe do either of you have any insight here? I didn't look very deeply into this yet but it seems like either grpc isn't the problem or 0.6.6 did not contain a fix for this particular issue.

callmehiphop picture callmehiphop on 9 Oct 2019

I am able to replicate this issue by deploying a GAE Standard service that pulls messages from PubSub at a rate of about 40/s. Instances need to be redeployed.

MichaelMarkieta picture MichaelMarkieta on 9 Oct 2019

Using the following did not work for us. The issue came back after several hours of starting a deployment like before.

"resolutions": {
    "@grpc/grpc-js": "^0.6.6"
}
gae123 picture gae123 on 9 Oct 2019

I'm attempting to work on a reproduction case right now, but if anyone could enable gRPC logging and supply us with the output that might prove helpful.

Just need to enable the following environment variables

GRPC_TRACE=all 
GRPC_VERBOSITY=DEBUG
callmehiphop picture callmehiphop on 9 Oct 2019

Someone suggested in https://github.com/grpc/grpc-node/issues/1064#issuecomment-538512609 downgrading @grpc/grpc-js to 0.5.4 so we are pinning google-gax to 1.6.2 until a working solution is provided

"resolutions": {
  "google-gax": "1.6.2"
}
pworkpop picture pworkpop on 10 Oct 2019

I'm attempting to work on a reproduction case right now, but if anyone could enable gRPC logging and supply us with the output that might prove helpful.

Just need to enable the following environment variables

GRPC_TRACE=all 
GRPC_VERBOSITY=DEBUG

@callmehiphop can these be simply added to the GAE Standard environmental variables? I've tried that but don't see any additional logs in stackdriver.

MichaelMarkieta picture MichaelMarkieta on 10 Oct 2019

@MichaelMarkieta I believe so. Can you confirm if you have @grpc/grpc-js >= 0.6.5 installed? I think these are a pretty new addition.

callmehiphop picture callmehiphop on 10 Oct 2019 
$ npm ls --depth=1
...
├─┬ @google-cloud/[email protected]
│ ├── @google-cloud/[email protected]
│ ├── @google-cloud/[email protected]
│ ├── @google-cloud/[email protected]
│ ├── @google-cloud/[email protected]
│ ├── @grpc/[email protected]
│ ├── @sindresorhus/[email protected]
│ ├── @types/[email protected]
│ ├── @types/[email protected]
│ ├── [email protected]
│ ├── [email protected]
│ ├── [email protected]
│ ├── [email protected]
│ ├── [email protected]
│ ├── [email protected]
│ ├── [email protected]
│ ├── [email protected]
│ └── [email protected]
...
MichaelMarkieta picture MichaelMarkieta on 10 Oct 2019 
$ cat app.yaml
runtime: nodejs10
instance_class: F4
env_variables:
  GRPC_TRACE: ALL
  GRPC_VERBOSITY: DEBUG
MichaelMarkieta picture MichaelMarkieta on 10 Oct 2019

@MichaelMarkieta I think it works, although it didn't show up in the stack driver UI for me, I did have success using the gcloud tool with gcloud app logs tail -s default

callmehiphop picture callmehiphop on 10 Oct 2019

Hello,
Just a followup.
We upgraded to pubsub 1.1.1 and we don't have errors anymore.
However, latency to push messages to pub sub is incredibly high. (between 5s and 50s)

FabianHutin picture FabianHutin on 10 Oct 2019

@google-cloud/[email protected] definitely not working for me. I regularly see {"code":4,"details":"Failed to connect before the deadline","metadata":{"internalRepr":{},"options":{}}} and then my entire app stops working. The subscribers stop processing messages.

Is there an _agreed on_ workaround in any of the above?

[EDIT]. I'm also seeing this error from time to time

{"ackIds":["KlgRTgQhIT4wPkVTRFAGFixdRkhRNxkIaFEOT14jPzUgKEUSASBuFSFCXhliaFxcdQdQC00geTQnYltFVQhCUnRfcysvV1tbdAVRDR56e2Z0aF8XCSr75KDd7KSXWUZgTbTgwcVHXbKv4JoiZh49WxJLLD5-MDxFQV5AEkw7CURJUytDCw"],"code":4,"details":"Deadline exceeded","metadata":{"internalRepr":{},"options":{}}}

Don't know if it's related though.

Errors started happening at 2019-10-09 17:35:28.252 BST (Wed Oct 09 16:35:28 UTC)

npomfret picture npomfret on 10 Oct 2019
👍2

I can confirm that we still get "Failed to connect before the deadline" with version 1.1.1 and latest version of google-gax and grpc-js

paksu picture paksu on 10 Oct 2019

Downgrading to 0.31.0 hasn't worked for me.

Also, downgrading to 0.31.0 AND adding "resolutions": {"google-gax": "1.6.2"} hasn't worked for me.

...and downgrading to 0.31.0 AND adding "resolutions": "{"google-gax": "1.6.2", "@grpc/grpc-js": "0.5.2"}} hasn't worked for me.

[edit] anyone got any sort of fix? I've tried all I can think of including reverting back to before I got the error for the first time but I cannot get my app working.

npomfret picture npomfret on 10 Oct 2019

Downgrading to 0.29.1 should do the trick @npomfret

This is the last working version

MatthieuLemoine picture MatthieuLemoine on 10 Oct 2019

@MatthieuLemoine what can I say, I tried and it also doesn't work. I still get the errors and no messages are being sent or delivered.

I've downgraded, deleted my _lock_ files and reinstalled, deleted _node_modules_ and reinstalled. I've even deleted and recreated my subscriptions. Nothing works. My app has been broken for a day almost and I can't get it working.

npomfret picture npomfret on 10 Oct 2019

I haven't changed anything since last night (eastern time zone), and the last time I received an error in GAE was 10/10/19 2:32 AM EST. Not sure what's changed... Instance counts across the service's that use pubsub are steady, and messages are ack'd at a steady rate. I would say, things became a lot more stable around 4:00 AM EST.

image

Majors blips in memory usage are when rolling out changes to the GAE services. Nothings been touched since ~2:00 AM.

MichaelMarkieta picture MichaelMarkieta on 10 Oct 2019

Combing through the logs and GRPC debugging output I see some errors that line up with the Unack' count blips (bottom left graph in the previous message's attachment):

image

MichaelMarkieta picture MichaelMarkieta on 10 Oct 2019

One more interesting log bunch that looks quite different than the rest, from earlier in the night around 3:45 AM EST

image

MichaelMarkieta picture MichaelMarkieta on 10 Oct 2019

Observed a new error just now:

{"code":16,"metadata":{"_internal_repr":{"www-authenticate":["Bearer realm=\"https://accounts.google.com/\", error=\"invalid_token\""]},"flags":0}}

npomfret picture npomfret on 10 Oct 2019

Looks like there are 3 errors in my playground that come up over and over:

Error: Failed to "acknowledge" for XX message(s). Reason: Deadline exceeded

Error: Failed to "modifyAckDeadline" for XX message(s). Reason: Retry total timeout exceeded before any response was received

Error: Failed to connect to channel. Reason: Failed to connect before the deadline
MichaelMarkieta picture MichaelMarkieta on 10 Oct 2019

@murgatroid99 does anything in the provided logs stick out to you?

callmehiphop picture callmehiphop on 10 Oct 2019

This problem is getting worse and worse for me. I've downgraded to "@google-cloud/pubsub": "0.29.1" and deleted all my subscriptions before recreating them but I'm still getting thousands of errors. Is anyone at google making any progress on this?

npomfret picture npomfret on 10 Oct 2019

@npomfret we're definitely making efforts here to resolve this as quickly as we can. Any additional info you can provide about your environment and application would be very helpful.

callmehiphop picture callmehiphop on 10 Oct 2019

@callmehiphop is there anything in particular?

I'm running a node app with (some node 11 version) on a basic GCE instance (f1-micro). It's been running fine for a long time and at 16:35:28 Oct 09 (UTC) i started getting a variety of pubsub errors (listed above). The impact is that most of my subscribers aren't receiving any messages. Sending seems to be ok, I can see a build up of messages via the console. I've had a few messages consumed after a restart but it fails pretty quickly after that (like in a few seconds).

npomfret picture npomfret on 10 Oct 2019

@npomfret 's experience would line up with my attempt to replicate the issue in GAE. However, since the instances in GAE are restarting or new instances come online when the service is unhealthy this deployment method is impacted slightly less.

MichaelMarkieta picture MichaelMarkieta on 10 Oct 2019

@npomfret could you tell me a little more about your subscribers, like

  • How many messages would you approximate are in the queue?
  • What kind of flow control settings do you have configured?
  • What is your ack deadline set to?
  • How many subscription instances are you creating?
  • How long on average does it take to ack a message?
callmehiphop picture callmehiphop on 10 Oct 2019

Note: I have a playground environment that I can tune using Locust to simulate load.

  1. GAE Standard publisher service
  2. GAE Standard puller service
  3. Locust on GCE putting load on (1) publisher and (2) puller

  • How many messages would you approximate are in the queue?
    This doesn't matter, errors present at ~50 messages per second or ~500 messages per second

  • What kind of flow control settings do you have configured?
    I am loading GAE Standard with Locust to have an appropriate number of instances to pull messages at a rate that matches the publisher.

  • What is your ack deadline set to?
    Defaults

  • How many subscription instances are you creating?
    Depends on the load generated on the publisher service (for 500 mps to PubSub, I have 5 GAE Standard F4 instances in the puller service)

  • How long on average does it take to ack a message?
    < 1 second, until it doesn't

image

MichaelMarkieta picture MichaelMarkieta on 10 Oct 2019

Here are my observations with latest libraries, in case they help anybody to reproduce. Rest of the stack same as I described in other messages in this thread.

We have a regional k8s cluster with 3 pods---if you do not understand k8s these are basically three nodejs processes running the same code. Each pod receives messages from the same subscription, about 10 messages arrive almost simultaneously at the beginning of each minute. Before latest changes, and this issue, ie when things were working fine, this was load balancing arriving messages among the three pods perpetually, no errors observed, each message was randomly processed by one pod/instance.

Here is the reconstruction of events from the log, similar to what we have observed the past few days:

  • 2019-10-09, 20:46:43: cluster restarts with 3 instances: f746s,7pdnd,tx7lq
  • Confirmed that all three pods are receiving and processing pubsub messages
  • 2019-10-09 21:52:00.759 Last message successfully received by 7pdnd
  • 2019-10-09 21:52:41.470 pod 7pdnd receives errors in multiple subscriptions:
    error: "{ Error: Failed to connect to channel. Reason: Failed to connect before the deadline at MessageStream._waitForClientReady (/mgmt/node_modules/@google-cloud/pubsub/build/src/message-stream.js:318:19) code: 4, details: 'Failed to connect before the deadline', metadata: Metadata { internalRepr: Map {}, options: {} } }"
    Around the same time all other subscriptions report errors in the same pod
    No message ever received again by this pod
  • 2019-10-10 03:21:00.836 Last message ever pulled by pod tx7lq
  • 2019-10-10 03:22:41.506 pod tx7lq receives error in subscription
    error: "{ Error: Failed to connect to channel. Reason: Failed to connect before the deadline at MessageStream._waitForClientReady (/mgmt/node_modules/@google-cloud/pubsub/build/src/message-stream.js:318:19) code: 4, details: 'Failed to connect before the deadline', metadata: Metadata { internalRepr: Map {}, options: {} } }"
    Around the same time many other subscriptions report errors in the same pod
  • 2019-10-10 12:40:01.138 Right now all messages go to only to f746s which is the only instance receiving messages, when the same happens to it customers start calling.... @bcoe I am not rebooting the deployment because I am also testing your fix for https://github.com/googleapis/nodejs-logging/issues/596 here and want to let it run as much as possible....
  • 2019-10-11 09:48:00 No change, the one pod is still fine handling all incoming messages...
  • 2019-10-11 09:52:01 Third pod also stops receiving messages
  • 2019-10-11 09:57:19.276 Similar timeout errors appear in the logs for the third pod
  • 2019-10-11 21:36 I am restarting the pods...

This whole story is consistent to what we have seen the past few days.

gae123 picture gae123 on 10 Oct 2019

@gae123 there's a chance we have a reproduction, we're working towards testing on a few @grpc/grpc-js versions, so that we can better isolate where the breakage occurs. Will keep you updated.

bcoe picture bcoe on 10 Oct 2019
👍1

I've hit this issue too - for now, I'm using this workaround:


const initSubscriber = () => {
  const pubsub = new PubSub();
  const subscription = pubsub.subscription(topic, options);
  subscription.on('message', handler.handleMessage);
  subscription.on('error', e => {
    console.error('Subscriber error handler caught exception. Restarting subscription.', e);
    initSubscriber();
  });
};

initSubscriber();
Redgwell picture Redgwell on 11 Oct 2019

@Redgwell what environment are you running PubSub in (Kubernetes Engine? App Engine?).

bcoe picture bcoe on 11 Oct 2019

@bcoe Running in GKE.

"@google-cloud/pubsub": "^1.1.0",
Redgwell picture Redgwell on 11 Oct 2019

@Redgwell a couple more follow up questions:

  1. how many messages/minute is your subscriber handling would you guesstimate?
  2. how often are you seeing the subscriber issue in your logs?
bcoe picture bcoe on 11 Oct 2019

@bcoe

  1. Really low throughput. Probably less than 10 a day at this point.
  2. We just released our service last night, and when we checked the logs this morning, we saw this error. The service was happy for about 3-4 hours before the error showed up in the logs.

I did a quick google and landed here.
Locally, I was able to replicate the same error message and behaviour (that is, no longer receiving messages after the error) by:

  1. Start app, subscribe, verify messages are being received.
  2. Disconnect from internet, and wait for the deadline exceeded error
  3. Reconnect to internet, publish messages

To make this a little faster to replicate, I set the streamingOptions timeout value in the pubsub options object to have a shorter streaming connection timeout:

   streamingOptions: {
      timeout: 5000
    }

One thing that might be useful for fixing this issue - if you look at my workaround, inside the initSubscriber function, I create a new PubSub() object. I found that if I didn't do this inside the initSubscriber function, and instead did it just once when the app starts, the application just kept getting deadline exceeded messages over and over again, even once I'd reconnected to the internet.

That makes me thing there is some state being set in the PubSub object that puts it in a faulted state until it's recreated. Sorry, I don't have the time right now to dig into that assertion any further.

Redgwell picture Redgwell on 11 Oct 2019
👍2

@Redgwell thank you this is very thorough, and gives us a good starting point for debugging.

bcoe picture bcoe on 11 Oct 2019

@Redgwell, could I bother you to test with @grpc/[email protected], if you delete your node_modules and package-lock.json, and run npm install @google-cloud/pubsub, you should get it now. (you can run npm ls post install to confirm).

We believe we've potentially addressed the bug requiring you to resubscribe.

bcoe picture bcoe on 11 Oct 2019
👍1

Okay, I grabbed the latest as you said - here's the pubsub dependency tree from npm ls:

├─┬ @google-cloud/[email protected]
│ ├─┬ @google-cloud/[email protected]
│ │ ├── [email protected] deduped
│ │ └── [email protected] deduped
│ ├── @google-cloud/[email protected]
│ ├── @google-cloud/[email protected]
│ ├── @google-cloud/[email protected]
│ ├── @sindresorhus/[email protected]
│ ├─┬ @types/[email protected]
│ │ └── @types/[email protected]
│ ├── @types/[email protected]
│ ├── [email protected]
│ ├── [email protected]
│ ├── [email protected]
│ ├─┬ [email protected]
│ │ ├── [email protected] deduped
│ │ ├── [email protected]
│ │ ├── [email protected]
│ │ ├─┬ [email protected]
│ │ │ ├── [email protected] deduped
│ │ │ ├── [email protected] deduped
│ │ │ ├─┬ [email protected]
│ │ │ │ ├─┬ [email protected]
│ │ │ │ │ └─┬ [email protected]
│ │ │ │ │   └── [email protected]
│ │ │ │ └── [email protected] deduped
│ │ │ └── [email protected] deduped
│ │ ├─┬ [email protected]
│ │ │ ├── [email protected] deduped
│ │ │ └─┬ [email protected]
│ │ │   └── [email protected]
│ │ ├─┬ [email protected]
│ │ │ ├── [email protected] deduped
│ │ │ ├─┬ [email protected]
│ │ │ │ └── [email protected]
│ │ │ ├── [email protected] deduped
│ │ │ └── [email protected]
│ │ ├─┬ [email protected]
│ │ │ ├─┬ [email protected]
│ │ │ │ ├── [email protected]
│ │ │ │ ├─┬ [email protected]
│ │ │ │ │ └── [email protected] deduped
│ │ │ │ └── [email protected] deduped
│ │ │ └── [email protected] deduped
│ │ └─┬ [email protected]
│ │   └── [email protected]
│ ├─┬ [email protected]
│ │ ├─┬ @grpc/[email protected]
│ │ │ └── [email protected] deduped
│ │ ├─┬ @grpc/[email protected]
│ │ │ ├── [email protected]
│ │ │ └── [email protected] deduped
│ │ ├─┬ [email protected]
│ │ │ └── [email protected]
│ │ ├─┬ [email protected]
│ │ │ ├─┬ [email protected]
│ │ │ │ └── [email protected] deduped
│ │ │ ├── [email protected] deduped
│ │ │ ├── [email protected] deduped
│ │ │ └── [email protected]
│ │ ├── [email protected] deduped
│ │ ├── [email protected] deduped
│ │ ├── [email protected]
│ │ ├── [email protected]
│ │ ├── [email protected]
│ │ ├── [email protected] deduped
│ │ ├─┬ [email protected]
│ │ │ ├─┬ [email protected]
│ │ │ │ └── [email protected] deduped
│ │ │ └─┬ [email protected]
│ │ │   └── [email protected] deduped
│ │ ├── [email protected] deduped
│ │ └── [email protected]
│ ├── [email protected]
│ ├── [email protected]
│ ├── [email protected]
│ └─┬ [email protected]
│   ├── @protobufjs/[email protected]
│   ├── @protobufjs/[email protected]
│   ├── @protobufjs/[email protected]
│   ├── @protobufjs/[email protected]
│   ├─┬ @protobufjs/[email protected]
│   │ ├── @protobufjs/[email protected] deduped
│   │ └── @protobufjs/[email protected] deduped
│   ├── @protobufjs/[email protected]
│   ├── @protobufjs/[email protected]
│   ├── @protobufjs/[email protected]
│   ├── @protobufjs/[email protected]
│   ├── @protobufjs/[email protected]
│   ├── @types/[email protected] deduped
│   ├── @types/[email protected]
│   └── [email protected]

I tried my test loop again - with this code:


const initSubscriber = () => {
  const pubsub = new PubSub();
  const subscription = pubsub.subscription(topic, options);
  subscription.on('message', handler.handleMessage);
  subscription.on('error', e => {
    console.error('Subscriber error handler caught exception. Restarting subscription.', e);
    //initSubscriber(); <------ commented out this, because I'm expecting that the fix means we don't need to do this anymore right?
  });
};

initSubscriber();

So with that running, I pushed some messages, saw the the app was handling them, then disconnected wifi and waited for the deadline exceeded error.
I reconnected wifi, pushed some more messages and waited for about 2 minutes. The app didn't process the messages. After restarting the app, it immediately processed the messages.

So unfortunately, it doesn't seem that this has fixed things, at least for my test loop of disconnecting the internet connection.

Redgwell picture Redgwell on 11 Oct 2019
👍1

We found one service that happily didn't observe these failures and we are now downgrading our affected services to this version until a confirmed working solution is provided:
@google-cloud/pubsub: 0.30.1
google-gax: 1.1.4
@grpc/grpc-js: ^0.4.3

You have to pin the google-gax version as it would pick the latest 1.x.x (check your lock file)

  "resolutions": {
    "google-gax": "1.1.4"
  }

We are also adding the initSubscriber workaround suggested by @Redgwell - it does seem to help. Also adding initPublisher to recreate the PubSub client in case publish fails with code 4.

pworkpop picture pworkpop on 11 Oct 2019 
SMP Debian 4.9.144-3.1 (2019-02-19) x86_64
~$ nvm --version
0.34.0
~$ npm --version
6.7.0
~$ yarn --version
1.19.1
~$ node --version
v11.15.0

How many messages would you approximate are in the queue?

The queues are normally empty, some messages take a few hundred seconds to process but most happen within a second or so. Sometimes the subscribers have maybe 10 messages backed up. These are not busy queues.

What kind of flow control settings do you have configured?

I have two types of subscriber. The first has flowControl: { maxMessages: 1, allowExcessMessages: false }, the second doesn't have any flow control settings. The both suffer from the problems described.

What is your ack deadline set to?

5 minutes for both.

How many subscription instances are you creating?

Each topic has one subscription instance, and each subscription has one nodejs consumer. I have a hundred or so in total.

How long on average does it take to ack a message?

It varies greatly. The first type (with flow control settings) can take a long time to process and then ack a message, like over 100 seconds, but usually it's around 1 second. The 2nd type (with no flow control) are ack'd immediately, so as soon as the message arrives it's ack'd.

npomfret picture npomfret on 11 Oct 2019

@pworkpop pinning the version of google-gax to 1.1.4 didn't work in my case. The key management api blew up:

nodeapp     at new KeyManagementServiceClient (node_modules/@google-cloud/kms/src/v1/key_management_service_client.js:130:28)
nodeapp     at GrpcClient.loadProto (node_modules/google-gax/build/src/grpc.js:145:21)
nodeapp     at GrpcClient.loadFromProto (node_modules/google-gax/build/src/grpc.js:118:44)
nodeapp     at Object.loadSync (node_modules/@grpc/proto-loader/build/src/index.js:230:27)
nodeapp     at Root.loadSync (node_modules/protobufjs/src/root.js:235:17)
nodeapp     at Root.load (node_modules/protobufjs/src/root.js:192:44)
nodeapp TypeError: Cannot read property 'length' of undefined

Same error with google-logging and a bunch of others. I see this in the logs:

nodeapp warning Resolution field "[email protected]" is incompatible with requested version "google-gax@^1.6.3"

... however, I think I have a working app now by downgrading a whole bunch of stuff. Don't know what the magic change was in the end but I'm running the following:

"@google-cloud/kms": "1.3.2",
"@google-cloud/logging": "5.2.2",
"@google-cloud/logging-bunyan": "^1.2.3",
"@google-cloud/pubsub": "0.29.1",
"@google-cloud/storage": "3.3.0",
npomfret picture npomfret on 11 Oct 2019

@npomfret I think this "@google-cloud/pubsub": "0.29.1", has done magic. I have had the same issue. Only 0.29.1 is the working version.

xoraingroup picture xoraingroup on 11 Oct 2019
👍1

Rolling back to 0.29.1 on it's own was definitely not enough in my case. I had to rollback a lot of the other google dependencies before it started working. I will gradually start to roll forward to see if I can find the culprit.

npomfret picture npomfret on 11 Oct 2019

@pwrkpop @npomfret @xoraingroup, rather than rolling back to 0.29.1 of @google-cloud/pubsub I recommend one of the following workarounds:

Using grpc, rather than @grpc/grpc-js

  1. inside your project which uses @google-cloud/pubsub, add the dependency grpc (this is the old gRPC transport layer).

  2. use the following code when creating your library:

    const {PubSub} = require('@google-cloud/pubsub');
const grpc = require('grpc');
const pubsub = new PubSub({grpc});

:point_up: this same approach can be used for other libraries that use gRPC, e.g.,

const grpc = require('grpc');
const {Logging} = require('@google-cloud/logging');
const logger = new Logging({grpc});

Using the workaround recommended by @Redgwell


const initSubscriber = () => {
  const pubsub = new PubSub();
  const subscription = pubsub.subscription(topic, options);
  subscription.on('message', handler.handleMessage);
  subscription.on('error', e => {
    initSubscriber();  });
};

initSubscriber();

We potentially have a reproduction of the issue described in this thread (thanks @Redgwell for pointing us in the right direction), and will hopefully have a fix out soon that makes either of these workaround unnecessary.

bcoe picture bcoe on 11 Oct 2019
🎉9

will try the first workaround (using the old gRPC transport layer) and will report results soon.

rvillane picture rvillane on 12 Oct 2019

I am not seeing any errors using this method for more than 6 hours:

const {PubSub} = require('@google-cloud/pubsub');
const grpc = require('grpc');
const pubsub = new PubSub({grpc});
MichaelMarkieta picture MichaelMarkieta on 12 Oct 2019

@bcoe Seems your trick worked. I have made some tests that are running last 24 hours and no such issue appeared. When can we expect a permanent fix than the above work around?

xoraingroup picture xoraingroup on 13 Oct 2019

google-gax: 1.1.4
@grpc/grpc-js: 0.4.3
seem to be stable for us - we have those in production since May

@npomfret sorry about that, we only use pubsub (no kms & logging libs). "@google-cloud/pubsub": "0.29.1" uses built-in grpc as @grpc/grpc-js was added in "@google-cloud/pubsub": "0.30.0" so bcoe's workaround is effectively the same - use built-in.

I sure wish the @grpc/grpc-js devs write more tests before pushing changes to prod.

pworkpop picture pworkpop on 15 Oct 2019

@pwrkpop @npomfret @xoraingroup, rather than rolling back to 0.29.1 of @google-cloud/pubsub I recommend one of the following workarounds:

Using grpc, rather than @grpc/grpc-js

  1. inside your project which uses @google-cloud/pubsub, add the dependency grpc (this is the old gRPC transport layer).
  2. use the following code when creating your library:
const {PubSub} = require('@google-cloud/pubsub');
const grpc = require('grpc');
const pubsub = new PubSub({grpc});

this same approach can be used for other libraries that use gRPC, e.g.,

const grpc = require('grpc');
const {Logging} = require('@google-cloud/logging');
const logger = new Logging({grpc});

Using the workaround recommended by @Redgwell

const initSubscriber = () => {
  const pubsub = new PubSub();
  const subscription = pubsub.subscription(topic, options);
  subscription.on('message', handler.handleMessage);
  subscription.on('error', e => {
    initSubscriber();  });
};

initSubscriber();

We potentially have a reproduction of the issue described in this thread (thanks @Redgwell for pointing us in the right direction), and will hopefully have a fix out soon that makes either of these workaround unnecessary.

Cant find anyting on creating PubSub with options includeing grpc? I use projectId, and tried to add grpc, but typescript rejects this.

https://googleapis.dev/nodejs/pubsub/1.1.1/PubSub.html

gberth picture gberth on 15 Oct 2019
👍2

A peculiar regularity shows here. Every hour it seems that the pubsub stops for a peridod of approximately 5 minutes. Not seen the regularity like this until today. The node app runs as normal, other type of events are showing that. Running the latest version og node pub-sub.

Screenshot from 2019-10-15 13-49-40

gberth picture gberth on 15 Oct 2019

@bcoe I wanted to confirm the workaround, so I did a quick scan of the source. Neither does the PubSub constructor nor the google_auth_library_1.GoogleAuth constructor inside of it seem to consume the grpc object that's passed into them. I'm not sure how this would work. This applies to versions 0.30.3 (the version our project is currently using) and the latest 1.1.2.

RaptDept picture RaptDept on 15 Oct 2019

My bad, I see it now. It gets passed to GrpcClient in google-gax eventually!

RaptDept picture RaptDept on 15 Oct 2019

@gberth (as you noticed @RaptDept, the ClientOptions accepted by new PubSub extends gax.GrpcClientOptions), which is where the grpc parameter is defined:

export interface ClientConfig extends gax.GrpcClientOptions {
  apiEndpoint?: string;
  servicePath?: string;
  port?: string | number;
  sslCreds?: ChannelCredentials;
}

export interface GrpcClientOptions extends GoogleAuthOptions {
  auth?: GoogleAuth;
  promise?: PromiseConstructor;
  grpc?: GrpcModule;
}

I've tested setting grpc and can confirm it toggles the transport layer.

bcoe picture bcoe on 15 Oct 2019

I've downgraded this to p2, not because it's not top of mind, but because the grpc workaround seems to be working for most folks. We're continuing to dig into things on our end, and are attempting to figure out the root causes of the issues we've seen with @grpc/grpc-js.

bcoe picture bcoe on 15 Oct 2019

Have issues been logged in all other client libraries that depend on
grpc-js that are affected, for tracking purposes, and to ensure all users
can find this bug if they're searching online for help?

>

MichaelMarkieta picture MichaelMarkieta on 15 Oct 2019

@bcoe Why not releasing a new version using the grpc workaround? Every developer upgrading @google-cloud/pubsub will encounter this issue.

This issue is hard to catch on dev environments as you have to wait one hour for the error to be triggered. Therefore we can assume that at least some of them will end up pushing broken code to production.

MatthieuLemoine picture MatthieuLemoine on 15 Oct 2019

@MatthieuLemoine @MichaelMarkieta I have been running a PubSub consumer for 4d15h now, on Kubernetes Engine, without a single issue.

NAME                          READY   STATUS    RESTARTS   AGE
good-reader-8f5fbb755-jbf28   1/1     Running   0          4d15h

This is an issue hitting a percentage of our users, but is not hitting 100% of library users, and we are continuing to attempt to find the actual root cause.

This is why we haven't opted to switch the grpc dependency.

bcoe picture bcoe on 15 Oct 2019

This is an issue hitting a percentage of our users, but is not hitting 100% of library users

this comment makes no sense from optics and I totally agree with @MatthieuLemoine release a proper fix for this or one with this 'workaround' built in, asking customers to change their production code with some speculative 'fix' is irresponsible

what happens when this is actually fixed and this ends up causing more problems later

the updated documentation does not even mention what kind of workloads would be better to use native or not making the mere suggestion of using it even more confusing and bug prone potentially

ericpearson picture ericpearson on 16 Oct 2019
👍4

This has been a workaround for us too, no issues in the last 24 hours. I ll keep monitoring....

const {PubSub} = require('@google-cloud/pubsub');
const grpc = require('grpc');
const pubsub = new PubSub({grpc});
gae123 picture gae123 on 16 Oct 2019

Asking customers to change their production code with some speculative 'fix' is irresponsible

We're very much trying to avoid this, I realize how frustrating the string of patches to @grpc/grpc-js was last week. Which is why we've taken a step back, and asked folks to opt for the grpc library instead, since we've seen this consistently address the issues that people are experiencing.

Our libraries were designed to allow grpc as an alternative to @grpc/grpc-js, specifically in case a situation like this arose (where we saw inconsistencies between the two libraries impacting users).

_Now, even though we are advising that folks running into immediate issues switch to grpc,_

We are continuing to try to ascertain a consistent reproduction of the issue effecting users. What has made this difficult, is that we see the default configuration (with @grpc/grpc-js) running effectively for many people -- I've had a cluster running for 5 days now, without the behavior reported, and we haven't been able to recreate the issue consistently with various attempts at stress testing in various environments.

Rather than continuing to float patches to @grpc/grpc-js speculatively (which I agree is irresponsible), we are taking the following approach:

  • we have been asking people for detailed information about their runtime environments, and are looking for patterns.
  • we have also been asking people to run with the environment variables GRPC_TRACE=all and GRPC_VERBOSITY=DEBUG, which is allowing us to deliver to the gRPC team the info they need to figure out what the heck is happening to some people.
  • If we're not happy that we've reached a reasonable resolution soon, we will consider switching the default library back to grpc.
bcoe picture bcoe on 16 Oct 2019

Have run with grpc since 10.30 AM today. App. 400' msgs read. No errors, no hangups. For information - messages like these below (had app 200 of them during 46 hours) has also disappeared

(node:16) Error: Failed to add metadata entry A...: Mon, 14 Oct 2019 11:40:19 GMT. Metadata key "a..." contains illegal characters

gberth picture gberth on 16 Oct 2019

@gberth Thanks for letting us know! Just to give you some details, the metadata warnings are caused not by @grpc/grpc-js but by some (unknown) bug in Node.js http2 implementation. The bug is here https://github.com/nodejs/node/issues/28632 for tracking purposes but no useful debug info is there yet.

grpc uses its own http2 stack, so the Node.js http2 module bug does not affect it - that's why those messages disappeared.

alexander-fenster picture alexander-fenster on 16 Oct 2019

just adding some observations in case it helps. have two services both running pubsub 1.0.0. One is older, and have no issues, one is newer and have the issue. have not tried to roll back the new service, using the workaround for now.

Here are the differences when running "npm ls @grpc/grpc-js"

old:
├─┬ @google-cloud/[email protected]
│ └─┬ [email protected]
│ └── @grpc/[email protected]
├─┬ @google-cloud/[email protected]
│ ├── @grpc/[email protected] deduped
│ └─┬ [email protected]
│ └── @grpc/[email protected] deduped
└── @grpc/[email protected]

new
└─┬ @google-cloud/[email protected]
├── @grpc/[email protected]
└─┬ [email protected]
└── @grpc/[email protected]

yanzit picture yanzit on 16 Oct 2019

@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.

pworkpop picture pworkpop on 16 Oct 2019

I'd like to :+1: 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.

ringzhz picture ringzhz on 18 Oct 2019
👍3

As mentioned on https://github.com/grpc/grpc-node/issues/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)

mrmodelo picture mrmodelo on 18 Oct 2019

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

npomfret picture npomfret on 18 Oct 2019

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.

hx-markterry picture hx-markterry on 18 Oct 2019

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:

  1. 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).

  2. run your environment with the following environment variables set:

GRPC_TRACE=all
GRPC_VERBOSITY=DEBUG
  1. 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/[email protected], 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 picture bcoe on 19 Oct 2019
❤3

@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?

npomfret picture npomfret on 21 Oct 2019

I've done a fresh install of 1.1.2 (which now is pulling @grpc/[email protected]) 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.

pmcnr-hx picture pmcnr-hx on 21 Oct 2019

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/[email protected] is still not performing as well as 0.29.1.

pmcnr-hx picture pmcnr-hx on 21 Oct 2019

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

We ask that folks upgrade to @grpc/[email protected], 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.

bcoe picture bcoe on 21 Oct 2019
Was this page helpful?
0 / 5 - 0 ratings

Related issues

osrecki picture osrecki  ·  7Comments
ncjones picture ncjones  ·  4Comments
ThomWright picture ThomWright  ·  6Comments
sombizbuzzz picture sombizbuzzz  ·  4Comments
davidtom picture davidtom  ·  3Comments