Nodejs-pubsub: UnhandledPromiseRejectionWarning: Error: Deadline exceeded

[dfang]

Environment details

• OS: macOS 10.14.5
• Node.js version: v10.16.0
• npm version: 6.9.0
• @google-cloud/pubsub version: "^0.30.1",

Steps to reproduce

1. download this repo as zip
2. cd samples, npm i
3. node subscriptions.js list

(node:88354) UnhandledPromiseRejectionWarning: Error: Deadline exceeded
    at Http2CallStream.call.on (/Users/mj/Downloads/nodejs-pubsub-master/samples/node_modules/@grpc/grpc-js/build/src/client.js:101:45)
    at Http2CallStream.emit (events.js:203:15)
    at process.nextTick (/Users/mj/Downloads/nodejs-pubsub-master/samples/node_modules/@grpc/grpc-js/build/src/call-stream.js:71:22)
    at process._tickCallback (internal/process/next_tick.js:61:11)
(node:88354) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1)
(node:88354) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

followed this guide to config auth, tried at least 3 times.

I'm sure GOOGLE_APPLICATION_CREDENTIALS and service_account are properly configured.
because cloud-pubsub go examples works on my local laptop.

none of examples work at all. always got "Deadline exceeded"

btw, copied some code, deploy to cloud functions, can publish message to cloud pubsub

[callmehiphop]

Seems to be working fine for me, @anguillanneuf any thoughts on why we might be timing out here?

[anguillanneuf]

@dfang Do you get the same deadline exceeded error for a list subscription (can be in a project or a topic) operation?

[dfang]

point to project owner service account
λ  export GOOGLE_APPLICATION_CREDENTIALS=~/.gcloud/jdwl-9df34aca1862.json

sometimes both node subscriptions.js list and node subscriptions.js list my-topic get deadline exceeded error, sometimes they both work

but λ node storage.js list runs very fast

storage.js, copied to here to validate GOOGLE_APPLICATION_CREDENTIALS

// Imports the Google Cloud client library.
const {Storage} = require('@google-cloud/storage');

// Instantiates a client. If you don't specify credentials when constructing
// the client, the client library will look for credentials in the
// environment.
const storage = new Storage();

// Makes an authenticated API request.
storage
  .getBuckets()
  .then((results) => {
    const buckets = results[0];

    console.log('Buckets:');
    buckets.forEach((bucket) => {
      console.log(bucket.name);
    });
  })
  .catch((err) => {
    console.error('ERROR:', err);
  });

[anguillanneuf]

Sorry @dfang I wasn't able to reproduce this error. To narrow down that this is a client library issue, do you want to try gcloud pubsub subscriptions list and see if it _ever_ gets "deadline exceeded"?

[dfang]

Just tried again.

~/Downloads/nodejs-pubsub-master/samples λ  node subscriptions.js list
(node:55504) UnhandledPromiseRejectionWarning: Error: Deadline exceeded
    at Http2CallStream.call.on (/Users/mj/Downloads/nodejs-pubsub-master/samples/node_modules/@grpc/grpc-js/build/src/client.js:101:45)
    at Http2CallStream.emit (events.js:203:15)
    at process.nextTick (/Users/mj/Downloads/nodejs-pubsub-master/samples/node_modules/@grpc/grpc-js/build/src/call-stream.js:71:22)
    at process._tickCallback (internal/process/next_tick.js:61:11)
(node:55504) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1)
(node:55504) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.

^C (had to press ctrl + c to stop it)

~/Downloads/nodejs-pubsub-master/samples λ  gcloud pubsub subscriptions list

gcloud pubsub subscriptions list return results very fast and never gets 'deadline exceeded' .

run commands in the same iterm2 tab, bash shell, and source code downloaded from github, not modified.

i've rewrite my cloud function with go, but i will keep these examples, let me know if you need more details for bug fix .

[alexbonhomme]

Hi,

I got the same error since I'd bump the version to 30.1.
I think it's related to this PR https://github.com/googleapis/nodejs-pubsub/pull/658

I'm currently digging, will keep you in touch

[alexbonhomme]

I confirm that this regression appear between 29.1 and 30.1. After my first observation it seems related to the switch from grpc to grpc-js.

Error appears in waitForReady method but I didn't understand why...

[callmehiphop]

Interesting, @alexander-fenster @murgatroid99 any thoughts here?

[alexander-fenster]

There is a comment in @grpc/grpc-js call-stream.js exactly in that place:

    endCall(status) {
        if (this.finalStatus === null) {
            this.finalStatus = status;
            /* We do this asynchronously to ensure that no async function is in the
             * call stack when we return control to the application. If an async
             * function is in the call stack, any exception thrown by the application
             * (or our tests) will bubble up and turn into promise rejection, which
             * will result in an UnhandledPromiseRejectionWarning. Because that is
             * a warning, the error will be effectively swallowed and execution will
             * continue */
            process.nextTick(() => {
                this.emit('status', status);
            });
        }
    }

https://github.com/grpc/grpc-node/blob/fe2eeb6c4b9a48a015cd1dec9fd237e6a9389705/packages/grpc-js/src/call-stream.ts#L130-L144

@murgatroid99 so does that mean this unhandled rejection is expected? Can we do anything about it?

[alexander-fenster]

@dfang My first guess would be some network / firewall problem. Pub/Sub library uses gRPC (works over HTTP/2) while storage sends plain old JSONs over HTTP/1.

This does not explain why switching from grpc to @grpc/grpc-js affects it, since both use the same protocol (gRPC, HTTP/2).

But anyway, just to rule out the possible firewall problems, can you disable it temporarily (manual for OS X) and see if it works? Alternatively, try to do the same on another Mac or on Linux. The sample code likely works but something in your environment causes this timeout error (Deadline exceeded is effectively a network timeout error).

[dfang]

@alexander-fenster

after turn off firewall,

 λ  node subscriptions.js list
(node:95524) UnhandledPromiseRejectionWarning: Error: Deadline exceeded
    at Http2CallStream.<anonymous> (/Users/mj/Downloads/nodejs-pubsub-master/samples/node_modules/@grpc/grpc-js/build/src/client.js:101:45)
    at Http2CallStream.emit (events.js:208:15)
    at /Users/mj/Downloads/nodejs-pubsub-master/samples/node_modules/@grpc/grpc-js/build/src/call-stream.js:71:22
    at processTicksAndRejections (internal/process/task_queues.js:75:11)
(node:95524) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). (rejection id: 1)
(node:95524) [DEP0018] DeprecationWarning: Unhandled promise rejections are deprecated. In the future, promise rejections that are not handled will terminate the Node.js process with a non-zero exit code.
^C
 λ  env | grep -i proxy
HTTP_PROXY=http://192.168.200.166:8118
GOS_UPSTREAM_ADDRESS=https://goproxy.cn
GOPROXY=https://goproxy.io
https_proxy=http://192.168.200.166:8118
http_proxy=http://192.168.200.166:8118
no_proxy=localhost,127.0.0.0/32,192.168.0.0/16
NO_PROXY=localhost,127.0.0.1,10.96.0.0/12,192.168.99.0/24,192.168.64.111
HTTPS_PROXY=http://192.168.200.166:8118
ftp_proxy=http://192.168.200.166:8118
 λ  ifconfig en0
en0: flags=8863<UP,BROADCAST,SMART,RUNNING,SIMPLEX,MULTICAST> mtu 1500
    ether 60:03:08:99:f1:24 
    inet6 fe80::1cc6:cefc:e417:380a%en0 prefixlen 64 secured scopeid 0x5 
    inet 192.168.200.166 netmask 0xfffffe00 broadcast 192.168.201.255
    nd6 options=201<PERFORMNUD,DAD>
    media: autoselect
    status: active

btw, my proxy works well

 λ  curl -v -I https://www.google.com
* Uses proxy env variable no_proxy == 'localhost,127.0.0.0/32,192.168.0.0/16'
* Uses proxy env variable https_proxy == 'http://192.168.200.166:8118'
*   Trying 192.168.200.166:8118...
* TCP_NODELAY set
* Connected to 192.168.200.166 (192.168.200.166) port 8118 (#0)
* allocate connect buffer!
* Establish HTTP proxy tunnel to www.google.com:443
> CONNECT www.google.com:443 HTTP/1.1
> Host: www.google.com:443
> User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)
> Proxy-Connection: Keep-Alive
> 
< HTTP/1.1 200 Connection established
HTTP/1.1 200 Connection established
< 

* Proxy replied 200 to CONNECT request
* CONNECT phase completed!
* ALPN, offering http/1.1
* WARNING: disabling hostname validation also disables SNI.
* CONNECT phase completed!
* CONNECT phase completed!
* TLS 1.2 connection using TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
* Server certificate: www.google.com
* Server certificate: Google Internet Authority G3
* Server certificate: GlobalSign
> HEAD / HTTP/1.1
> Host: www.google.com
> User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0)
> Accept: */*
> Referer: 
> 
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
HTTP/1.1 200 OK
< Date: Wed, 17 Jul 2019 05:11:11 GMT
Date: Wed, 17 Jul 2019 05:11:11 GMT
< Expires: -1
Expires: -1
< Cache-Control: private, max-age=0
Cache-Control: private, max-age=0
< Content-Type: text/html; charset=UTF-8
Content-Type: text/html; charset=UTF-8
< P3P: CP="This is not a P3P policy! See g.co/p3phelp for more info."
P3P: CP="This is not a P3P policy! See g.co/p3phelp for more info."
< Server: gws
Server: gws
< X-XSS-Protection: 0
X-XSS-Protection: 0
< X-Frame-Options: SAMEORIGIN
X-Frame-Options: SAMEORIGIN
< Set-Cookie: 1P_JAR=2019-07-17-05; expires=Fri, 16-Aug-2019 05:11:11 GMT; path=/; domain=.google.com
Set-Cookie: 1P_JAR=2019-07-17-05; expires=Fri, 16-Aug-2019 05:11:11 GMT; path=/; domain=.google.com
< Set-Cookie: NID=188=EWbyFgwDFo9vDOBUWCrybT4_N_f2YbWBGRztLqNB1pg7-Y0t8qwllOj0Apbz73gkmm-QI7jr0Mg_NNVr1XcM3J4z0-nEAhivb3eRVNAiu32cTTffvVW0PSulmXLq58lGNlWmahsdX5UzgAHQtzbXMII3R2mbz_OrOh8TO9Agkn8; expires=Thu, 16-Jan-2020 05:11:11 GMT; path=/; domain=.google.com; HttpOnly
Set-Cookie: NID=188=EWbyFgwDFo9vDOBUWCrybT4_N_f2YbWBGRztLqNB1pg7-Y0t8qwllOj0Apbz73gkmm-QI7jr0Mg_NNVr1XcM3J4z0-nEAhivb3eRVNAiu32cTTffvVW0PSulmXLq58lGNlWmahsdX5UzgAHQtzbXMII3R2mbz_OrOh8TO9Agkn8; expires=Thu, 16-Jan-2020 05:11:11 GMT; path=/; domain=.google.com; HttpOnly
< Transfer-Encoding: chunked
Transfer-Encoding: chunked
< Alt-Svc: quic=":443"; ma=2592000; v="46,43,39"
Alt-Svc: quic=":443"; ma=2592000; v="46,43,39"
< Accept-Ranges: none
Accept-Ranges: none
< Vary: Accept-Encoding
Vary: Accept-Encoding

< 
* Connection #0 to host 192.168.200.166 left intact

[murgatroid99]

That code you quoted was supposed to stop these UnhandledPromiseRejectionWarnings. I genuinely don't understand how this could still be happening. I don't even know what promise it could be referring to. But to be clear, this isn't a network issue or anything like that. This is requests experiencing normal errors, in this case it looks like "Deadline exceeded", and then somehow that error is getting mishandled within the grpc-js library.

I'm actually going on vacation. Please ping me about this again when I'm back on the 29th. If you have a fix or something before that talk to Nico.

[alexbonhomme]

Hey guys,

Could it be related to proxy usage ? We got the issue only on production behind proxy. No problem in local.

[alexander-fenster]

@alexbonhomme I had this idea as well (because @dfang also uses proxy, and also because I was never able to repro this without a proxy). It's a little bit unclear for me how http_proxy variable is used in @grpc/grpc-js. One thing that I see is that the C++ grpc (the one used by grpc NPM package) knows about http_proxy environment variable (at least here https://github.com/grpc/grpc/blob/39e982a263e5c48a650990743ed398c1c76db1ac/src/core/ext/filters/client_channel/http_proxy.cc#L45), while I was not able to find anything related to http_proxy in @grpc/grpc-js or Node.js http2 implementation. So, a couple of questions then:

@nicolasnoble / @murgatroid99 (when you're back): is there a change in behavior w/r/t using http_proxy environment variable between grpc and @grpc/gprc-js? Do you think it may be related to what users see here?

@dfang Do you have a way to try the code directly, not being behind a proxy?

[dfang]

@alexander-fenster I'm in china, have to use proxy to access google api. develop on local and deployed it on google cloud functions.

btw, i use shadowsocks to bypass GFW.
self hosted on aws ec2 free instances. and ClashX as shadowsocks client.

[alexander-fenster]

Thanks @dfang, we're still trying to figure out what's going on here. I'll keep this issue updated.

[mahaben]

Hey guys,

Any fix for this issue?

Thanks,

[bcoe]

@mahaben are you getting the same exception, mind sharing a stack trace? I'm curious, are you running behind a proxy as well?

[mahaben]

@bcoe Thanks for your reply. Yes I'm running behind a proxy. Actually, this exception makes the app in a state of not receiving messages at all.

Here the exception I got:

ackIds: [ 0: "TgQhIT4wPkVTRFAGFixdRkhRNxkIaFEOT14jPzUgKEUSAAdnfjkORhoLazNcdQdRDRh0KWZza1sRVFMUWX9XWxENQGx-SgBVDR1ydGlybF8WBgFDU1bM4eqNyKT3RB1tNaO89r1ASpvFk7V0Zhs9WhJLLD5-MilFQV5AEkw5HERJUytDCypYEQ" ] code: 4 details: "Deadline exceeded"

[reco]

hey there, not behind a proxy but same issue:

error Error: 4 DEADLINE_EXCEEDED: Deadline exceeded at Object.callErrorFromStatus (/Users/reco/dev/imago.docker/imago.encoder/node_modules/@grpc/grpc-js/build/src/call.js:30:26) at Http2CallStream.<anonymous> (/Users/reco/dev/imago.docker/imago.encoder/node_modules/@grpc/grpc-js/build/src/client.js:96:33) at Http2CallStream.emit (events.js:208:15) at /Users/reco/dev/imago.docker/imago.encoder/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' }

[soubhikchatterjee]

Even I was able to replicate it when using the google ML npm module

{ Error: 4 DEADLINE_EXCEEDED: Deadline exceeded
    at Object.callErrorFromStatus (/var/www/html/test/google-ml/node_modules/@grpc/grpc-js/build/src/call.js:30:26)
    at Http2CallStream.call.on (/var/www/html/test/google-ml/node_modules/@grpc/grpc-js/build/src/client.js:96:33)
    at Http2CallStream.emit (events.js:198:15)
    at process.nextTick (/var/www/html/test/google-ml/node_modules/@grpc/grpc-js/build/src/call-stream.js:79:22)
    at processTicksAndRejections (internal/process/task_queues.js:79:9)
  code: 4,
  details: 'Deadline exceeded',
  metadata: Metadata { internalRepr: Map {}, options: {} } }

Any fix for this yet?

[feywind]

I've set up a local proxy to try to reproduce this (since it seems like a proxy was the common denominator for most of the reports) but I haven't had much luck so far. I'll keep it in my queue to look in more depth.

[feywind]

My guess right now is that this is some sort of interaction between Node's HTTP/2 implementation and user proxies, but since none of us have been able to repro it here, I'm not sure there's much we can do. :( If anyone can give us detailed info about their proxies (especially if it's something open source like Squid) then we can try with that.