UnhandledPromiseRejectionWarning: Error: Deadline exceeded #679

dfang · 2019-06-30T10:18:03Z

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

download this repo as zip
cd samples, npm i
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

The text was updated successfully, but these errors were encountered:

callmehiphop · 2019-07-01T14:00:07Z

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

anguillanneuf · 2019-07-03T17:17:01Z

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

dfang · 2019-07-04T08:04:41Z

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 · 2019-07-09T21:52:34Z

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 · 2019-07-10T13:22:54Z

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 · 2019-07-16T07:56:29Z

Hi,

I got the same error since I'd bump the version to 30.1.
I think it's related to this PR #658

I'm currently digging, will keep you in touch

alexbonhomme · 2019-07-16T12:19:20Z

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 · 2019-07-16T16:29:41Z

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

alexander-fenster · 2019-07-16T17:30:11Z

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 · 2019-07-16T17:36:50Z

@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 · 2019-07-17T05:12:28Z

@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 · 2019-07-17T05:51:01Z

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 · 2019-07-17T08:52:42Z

Hey guys,

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

alexander-fenster · 2019-07-17T17:17:31Z

@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 · 2019-07-18T07:26:53Z

@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 · 2019-07-18T07:53:36Z

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

mahaben · 2019-09-30T08:28:22Z

Hey guys,

Any fix for this issue?

Thanks,

bcoe · 2019-09-30T23:50:31Z

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

mahaben · 2019-10-03T10:14:30Z

@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 · 2019-12-02T03:33:56Z

hey there, not behind a proxy but same issue:

    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 · 2019-12-09T11:12:14Z

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 · 2019-12-20T00:59:01Z

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 · 2020-01-28T00:12:57Z

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.

hermanbanken · 2021-09-09T14:04:09Z

The real issue is that this becomes an UnhandledPromiseException. Sure, errors happen, but they should not go unhandled. This completely breaks our logging solution. Any errors we catch we tag with the service and the right teams get notified. This error completely side-tracks the logs as it is send to stdout!

Please fix this!

…oogleapis#679)

yoshi-automation added the triage me I really want to be triaged. label Jul 1, 2019

callmehiphop added help wanted We'd love to have community involvement on this issue. needs more info This issue needs more information from the customer to proceed. and removed triage me I really want to be triaged. labels Jul 1, 2019

yoshi-automation added the triage me I really want to be triaged. label Jul 1, 2019

JustinBeckwith added priority: p2 Moderately-important priority. Fix may not be included in next release. type: bug Error or flaw in code with unintended results or allowing sub-optimal usage patterns. labels Jul 1, 2019

yoshi-automation removed the triage me I really want to be triaged. label Jul 1, 2019

limenote135 mentioned this issue Sep 13, 2019

Deadline exceeding when saving updates googleapis/nodejs-firestore#739

Closed

meredithslota assigned feywind Dec 20, 2019

yoshi-automation added the 🚨 This issue needs some love. label Dec 27, 2019

This was referenced Jan 27, 2020

can publish but not receive from subscription on hosted environnement #797

Closed

Various problems seem to be happening in regards to grpc-js #868

Closed

feywind closed this as completed Jan 28, 2020

google-cloud-label-sync bot added the api: pubsub Issues related to the googleapis/nodejs-pubsub API. label Jan 31, 2020

feywind pushed a commit to feywind/nodejs-pubsub that referenced this issue Nov 12, 2024

build: set AUTOSYNTH_MULTIPLE_COMMITS=true for context aware commits (g…

6559a61

…oogleapis#679)

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

UnhandledPromiseRejectionWarning: Error: Deadline exceeded #679

UnhandledPromiseRejectionWarning: Error: Deadline exceeded #679

dfang commented Jun 30, 2019 •

edited

Loading

callmehiphop commented Jul 1, 2019

anguillanneuf commented Jul 3, 2019 •

edited

Loading

dfang commented Jul 4, 2019 •

edited

Loading

anguillanneuf commented Jul 9, 2019

dfang commented Jul 10, 2019 •

edited

Loading

alexbonhomme commented Jul 16, 2019 •

edited

Loading

alexbonhomme commented Jul 16, 2019

callmehiphop commented Jul 16, 2019

alexander-fenster commented Jul 16, 2019

alexander-fenster commented Jul 16, 2019

dfang commented Jul 17, 2019

murgatroid99 commented Jul 17, 2019

alexbonhomme commented Jul 17, 2019 •

edited

Loading

alexander-fenster commented Jul 17, 2019

dfang commented Jul 18, 2019

alexander-fenster commented Jul 18, 2019

mahaben commented Sep 30, 2019

bcoe commented Sep 30, 2019

mahaben commented Oct 3, 2019 •

edited

Loading

reco commented Dec 2, 2019

soubhikchatterjee commented Dec 9, 2019

feywind commented Dec 20, 2019

feywind commented Jan 28, 2020

hermanbanken commented Sep 9, 2021

UnhandledPromiseRejectionWarning: Error: Deadline exceeded #679

UnhandledPromiseRejectionWarning: Error: Deadline exceeded #679

Comments

dfang commented Jun 30, 2019 • edited Loading

Environment details

Steps to reproduce

callmehiphop commented Jul 1, 2019

anguillanneuf commented Jul 3, 2019 • edited Loading

dfang commented Jul 4, 2019 • edited Loading

anguillanneuf commented Jul 9, 2019

dfang commented Jul 10, 2019 • edited Loading

alexbonhomme commented Jul 16, 2019 • edited Loading

alexbonhomme commented Jul 16, 2019

callmehiphop commented Jul 16, 2019

alexander-fenster commented Jul 16, 2019

alexander-fenster commented Jul 16, 2019

dfang commented Jul 17, 2019

murgatroid99 commented Jul 17, 2019

alexbonhomme commented Jul 17, 2019 • edited Loading

alexander-fenster commented Jul 17, 2019

dfang commented Jul 18, 2019

alexander-fenster commented Jul 18, 2019

mahaben commented Sep 30, 2019

bcoe commented Sep 30, 2019

mahaben commented Oct 3, 2019 • edited Loading

reco commented Dec 2, 2019

soubhikchatterjee commented Dec 9, 2019

feywind commented Dec 20, 2019

feywind commented Jan 28, 2020

hermanbanken commented Sep 9, 2021

dfang commented Jun 30, 2019 •

edited

Loading

anguillanneuf commented Jul 3, 2019 •

edited

Loading

dfang commented Jul 4, 2019 •

edited

Loading

dfang commented Jul 10, 2019 •

edited

Loading

alexbonhomme commented Jul 16, 2019 •

edited

Loading

alexbonhomme commented Jul 17, 2019 •

edited

Loading

mahaben commented Oct 3, 2019 •

edited

Loading