nodejs-pubsub: "Failed to connect before the deadline" errors being seen

Since upgrading to the latest pubsub ("@google-cloud/pubsub": "1.1.5") my node is still getting occasional errors from the underlying grpc library. My app is using grpc-js@0.6.9:

$ npm ls | grep grpc-js │ │ ├─┬ @grpc/grpc-js @0.6.9

It’s not as bad as it was. When I first upgraded to pubsub 1.x it simply didn’t work at all, I’d get an error within a few seconds of the app starting and from then no messages would get delivered.

Now the problem is much less bad (my app is working), but I still see the following errors in my logs:

From subscription.on(error, (err) => { I see this:

{"code":4,"details":"Failed to connect before the deadline","metadata":{"internalRepr":{},"options":{}}}

And in my logs I’ve also noticed these (excuse the formatting):

Error: Failed to add metadata entry @��: Wed, 13 Nov 2019 07:13:16 GMT. Metadata key "@��" contains illegal characters at validate (/home/nodeapp/apps/crypto-trader-prototype/shared-code/node_modules/@grpc/grpc-js/build/src/metadata.js:35:15) at Metadata.add (/home/nodeapp/apps/crypto-trader-prototype/shared-code/node_modules/@grpc/grpc-js/build/src/metadata.js:87:9) at values.split.forEach.v (/home/nodeapp/apps/crypto-trader-prototype/shared-code/node_modules/@grpc/grpc-js/build/src/metadata.js:226:63) at Array.forEach (<anonymous>) at Object.keys.forEach.key (/home/nodeapp/apps/crypto-trader-prototype/shared-code/node_modules/@grpc/grpc-js/build/src/metadata.js:226:43) at Array.forEach (<anonymous>) at Function.fromHttp2Headers (/home/nodeapp/apps/crypto-trader-prototype/shared-code/node_modules/@grpc/grpc-js/build/src/metadata.js:200:30) at ClientHttp2Stream.stream.on (/home/nodeapp/apps/crypto-trader-prototype/shared-code/node_modules/@grpc/grpc-js/build/src/call-stream.js:211:56) at ClientHttp2Stream.emit (events.js:193:13) at emit (internal/http2/core.js:244:8) at processTicksAndRejections (internal/process/task_queues.js:81:17)

… but the two don’t seem to be related.

I will start running with the debug flags enabled and report back

About this issue

Original URL
State: closed
Created 5 years ago
Comments: 22 (9 by maintainers)

Most upvoted comments

I may be speaking too soon, but it looks like the latest release may have fixed this issue.

Recent releases seem to have steadily reduced the number of errors, but until recently I was getting one or two errors per day. I’ve had zero for five days now. The upgrade in question took my deps from:

"@google-cloud/firestore": "^3.4.1",
"@google-cloud/logging": "7.1.0",
"@google-cloud/logging-bunyan": "^2.0.3",
"@google-cloud/pubsub": "^1.4.1",

to …

"@google-cloud/firestore": "^3.5.0",
"@google-cloud/logging": "7.1.0",
"@google-cloud/logging-bunyan": "^2.0.3",
"@google-cloud/pubsub": "^1.5.0",

npomfret on Feb 17, 2020

[update] I’ve had zero errors since the 24th November.

npomfret on Dec 2, 2019

would you be able to provide the detailed debug output when this connection error occurs?

I have (above). I tuned on GRPC_TRACE=all and GRPC_VERBOSITY=DEBUG as instructed. The only output I saw in stackdriver that was at a similar time to the error occurring is:

E 2019-11-13T12:40:23.450999975Z 2019-11-13T12:40:23.451Z | subchannel | 172.217.203.95:443 IDLE -> TRANSIENT_FAILURE

All other logging at that time came from my app.

npomfret on Nov 15, 2019