Add more information on "Retry total timeout exceeded before any response was received" error.

[tanishiking]

Hi, gax-nodejs team, I'd like to propose to add some more information on error message for "Retry total timeout error" so that GCP users can easily debug which GCP library and which API calls are hitting "retry total timeout" error.

(I've already contacted GCP Support Team, they created an issue on public issue tracker, and suggested me to create an issue here).

Is your feature request related to a problem? Please describe. (background)

We are running Google Cloud Function with node10, and we occasionally hit the "Retry total timeout exceeded before any response was received" error.

FYI my piece of yarn.lock related to google-gax

"@google-cloud/datastore@^4.5.2":
  version "4.5.2"
  resolved "https://registry.yarnpkg.com/@google-cloud/datastore/-/datastore-4.5.2.tgz#b1f9300ca2de91bcfd5783f54354411ece1446bc"
  integrity sha512-dILePgHiA14/6l47XrsTjQqGhZVtznrqg3Q3ent5jOhL+0QGGokY+Y3OtYTQ1yCAfUg/ZcwjLY1s2MBbrHqnog==
  dependencies:
    "@google-cloud/projectify" "^1.0.0"
    "@google-cloud/promisify" "^1.0.0"
    "@grpc/grpc-js" "0.6.11"
    "@types/duplexify" "^3.6.0"
    "@types/long" "^4.0.0"
    arrify "^2.0.1"
    concat-stream "^2.0.0"
    extend "^3.0.2"
    google-auth-library "^5.0.0"
    google-gax "^1.7.5"
    is "^3.3.0"
    split-array-stream "^2.0.0"
    stream-events "^1.0.5"

"@google-cloud/logging@^7.0.0":
  version "7.2.3"
  resolved "https://registry.yarnpkg.com/@google-cloud/logging/-/logging-7.2.3.tgz#499f04bb57c607e28c426566853e632eab13b8cf"
  integrity sha512-MLAlYVBihCs0e581n9VUYOPJcrSpwSdL7KAjy2wgQidmRD9aWjvg97F22JMCtvrUiFBmAjiJVtn1JyNIXlv0Yw==
  dependencies:
    "@google-cloud/common" "^2.2.2"
    "@google-cloud/paginator" "^2.0.0"
    "@google-cloud/projectify" "^1.0.0"
    "@google-cloud/promisify" "^1.0.0"
    "@opencensus/propagation-stackdriver" "0.0.20"
    arrify "^2.0.0"
    dot-prop "^5.1.0"
    eventid "^1.0.0"
    extend "^3.0.2"
    gcp-metadata "^3.1.0"
    google-auth-library "^5.2.2"
    google-gax "^1.11.0"
    is "^3.3.0"
    on-finished "^2.3.0"
    pumpify "^2.0.0"
    snakecase-keys "^3.0.0"
    stream-events "^1.0.4"
    through2 "^3.0.0"
    type-fest "^0.11.0"

"@google-cloud/pubsub@^1.5.0":
  version "1.5.0"
  resolved "https://registry.yarnpkg.com/@google-cloud/pubsub/-/pubsub-1.5.0.tgz#0ce5a60a90c87af9e9dcd28433a0da74c223007b"
  integrity sha512-SCuNClo/xDGjYmciExxVjX78WPY1Ul6MK5Qn5eX2tsILqxXpf5Lan+XU/jnL53pirAIFgcxt8I2CWibSdSqRww==
  dependencies:
    "@google-cloud/paginator" "^2.0.0"
    "@google-cloud/precise-date" "^1.0.0"
    "@google-cloud/projectify" "^1.0.0"
    "@google-cloud/promisify" "^1.0.0"
    "@types/duplexify" "^3.6.0"
    "@types/long" "^4.0.0"
    arrify "^2.0.0"
    async-each "^1.0.1"
    extend "^3.0.2"
    google-auth-library "^5.5.0"
    google-gax "^1.7.5"
    is-stream-ended "^0.1.4"
    lodash.snakecase "^4.1.1"
    p-defer "^3.0.0"
    protobufjs "^6.8.1"

"@google-cloud/vision@^1.7.2":
  version "1.9.0"
  resolved "https://registry.yarnpkg.com/@google-cloud/vision/-/vision-1.9.0.tgz#3dd9708a2d87c5a2ab46c104f2a320ee99cd51fb"
  integrity sha512-6ka0MggI8u4WgGJe1wAIdxIAKE9gRp1CQ5ADXNM+JmSUniEZfbeNwOG8twFCxyWBlUqC+cQJaG4Amd6SLXzk/w==
  dependencies:
    "@google-cloud/promisify" "^1.0.0"
    google-gax "^1.7.5"
    is "^3.2.1"

gaxios@^2.0.1, gaxios@^2.1.0:
  version "2.3.1"
  resolved "https://registry.yarnpkg.com/gaxios/-/gaxios-2.3.1.tgz#52bd832b5d6a252072783b9afd9742bde835b2f4"
  integrity sha512-DQOesWEx59/bm63lTX0uHDDXpGTW9oKqNsoigwCoRe2lOb5rFqxzHjLTa6aqEBecLcz69dHLw7rbS068z1fvIQ==
  dependencies:
    abort-controller "^3.0.0"
    extend "^3.0.2"
    https-proxy-agent "^5.0.0"
    is-stream "^2.0.0"
    node-fetch "^2.3.0"

gcp-metadata@^3.0.0, gcp-metadata@^3.1.0, gcp-metadata@^3.4.0:
  version "3.4.0"
  resolved "https://registry.yarnpkg.com/gcp-metadata/-/gcp-metadata-3.4.0.tgz#dfcbb6abe2c262c86c8eb01e4729d46b44e21484"
  integrity sha512-fizmBtCXHp8b7FZuzbgKaixO8DzsSYoEVmMgZIna7x8t6cfBF3eqirODWYxVbgmasA5qudCAKiszfB7yVwroIQ==
  dependencies:
    gaxios "^2.1.0"
    json-bigint "^0.3.0"

google-auth-library@^5.0.0, google-auth-library@^5.2.2, google-auth-library@^5.5.0, google-auth-library@^5.6.1, google-auth-library@^5.9.0:
  version "5.10.1"
  resolved "https://registry.yarnpkg.com/google-auth-library/-/google-auth-library-5.10.1.tgz#504ec75487ad140e68dd577c21affa363c87ddff"
  integrity sha512-rOlaok5vlpV9rSiUu5EpR0vVpc+PhN62oF4RyX/6++DG1VsaulAFEMlDYBLjJDDPI6OcNOCGAKy9UVB/3NIDXg==
  dependencies:
    arrify "^2.0.0"
    base64-js "^1.3.0"
    ecdsa-sig-formatter "^1.0.11"
    fast-text-encoding "^1.0.0"
    gaxios "^2.1.0"
    gcp-metadata "^3.4.0"
    gtoken "^4.1.0"
    jws "^4.0.0"
    lru-cache "^5.0.0"

google-gax@^1.11.0, google-gax@^1.7.5:
  version "1.14.2"
  resolved "https://registry.yarnpkg.com/google-gax/-/google-gax-1.14.2.tgz#ce4f9a42c1bc2ca4a4ed8e8cc70c6f7a3548b790"
  integrity sha512-Nde+FdqALbV3QgMA4KlkxOHfrj9busnZ3EECwy/1gDJm9vhKGwDLWzErqRU5g80OoGSAMgyY7DWIfqz7ina4Jw==
  dependencies:
    "@grpc/grpc-js" "^0.6.18"
    "@grpc/proto-loader" "^0.5.1"
    "@types/fs-extra" "^8.0.1"
    "@types/long" "^4.0.0"
    abort-controller "^3.0.0"
    duplexify "^3.6.0"
    google-auth-library "^5.0.0"
    is-stream-ended "^0.1.4"
    lodash.at "^4.6.0"
    lodash.has "^4.5.2"
    node-fetch "^2.6.0"
    protobufjs "^6.8.8"
    retry-request "^4.0.0"
    semver "^6.0.0"
    walkdir "^0.4.0"

googleapis-common@^3.2.0:
  version "3.2.1"
  resolved "https://registry.yarnpkg.com/googleapis-common/-/googleapis-common-3.2.1.tgz#1c81dfce74876948fb1e68a2a99f842da6123877"
  integrity sha512-lPAJXYpZLvY4AZp57RWj1eUXS2D5LxS3y6W0n9Jbl6eKOWmyLgz99f84XVCxVnyq8DcgV/ZAxt1lpFEzGZkVvQ==
  dependencies:
    extend "^3.0.2"
    gaxios "^2.0.1"
    google-auth-library "^5.6.1"
    qs "^6.7.0"
    url-template "^2.0.8"
    uuid "^3.3.2"

gtoken@^4.1.0:
  version "4.1.4"
  resolved "https://registry.yarnpkg.com/gtoken/-/gtoken-4.1.4.tgz#925ff1e7df3aaada06611d30ea2d2abf60fcd6a7"
  integrity sha512-VxirzD0SWoFUo5p8RDP8Jt2AGyOmyYcT/pOUgDKJCK+iSw0TMqwrVfY37RXTNmoKwrzmDHSk0GMT9FsgVmnVSA==
  dependencies:
    gaxios "^2.1.0"
    google-p12-pem "^2.0.0"
    jws "^4.0.0"
    mime "^2.2.0"

I believe this error happens when google cloud library (technically its underlying library, "gax-nodejs") tries to access GCP API and didn't get a response from the server within the deadline here

gax-nodejs/src/normalCalls/retries.ts

Lines 82 to 89 in 4b9a35e

	if (deadline && now.getTime() >= deadline) {
	const error = new GoogleError(
	'Retry total timeout exceeded before any response was received'
	);
	error.code = Status.DEADLINE_EXCEEDED;
	callback(error);
	return;
	}

I tried to debug which API call and which library emit this error message, but I couldn't because the error message and stack trace don't provide any information other than 'Retry total timeout exceeded before any response was received'.

Here's the full stack-trace when we hit the error.

Error: Retry total timeout exceeded before any response was received
    at repeat (/srv/functions/node_modules/google-gax/build/src/normalCalls/retries.js:65:31)
    at Timeout.setTimeout [as _onTimeout] (/srv/functions/node_modules/google-gax/build/src/normalCalls/retries.js:100: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)

Describe the solution you'd like

Therefore, I'd like to propose that gax shows some more information on DEADLINE_EXCEEDED error so that the GCP users can easily debug and where's the root cause of this issue.

For example:

• Which library, or API didn't respond within the deadline.
• How long the API call took.
• What is the retry settings?

Unfortunately, since I'm not familiar with GRPC and GCP internal endpoints, I'm not sure is it possible.

Additional context

I guess an informative error message would be helpful for a lot of GCP users because as far as I know, there're quite a few people who are suffering from this issue:

• DEADLINE_EXCEEDED makes application not receiving messages at all nodejs-pubsub#770
• Auth error: ETIMEDOUT google-auth-library-nodejs#283

Anyway, thank you so much for maintaining this fundamental library for GCP, you always save my days :)

[zkenstein]

Faced some problem, any suggestions how to solved this

[abhirathod]

@tanishiking :
I am also facing the similar issue for Publishing PubSub messages in bulk.
Did you get any solution to this problem?
If any, please share.

[yossi-eynav]

@hkdevandla @alexander-fenster can you please assist?
we're facing the same problem while using node-tasks -
googleapis/nodejs-tasks#397

[yossi-eynav]

when node-tasks uses gax-nodejs fallback we get no errors, when we use the regular flow we get many "4- DEADLINE_EXCEEDED" errors - can you share some more info about that?

[alexander-fenster]

Folks, let's not bring different problems into the same issue. This particular issue asks to add library name to the valid "total timeout exceeded" error messages so that the users knew which API hit the timeout from the error message.

@yossi-eynav If you folks are getting a lot of deadline exceeded errors in nodejs-tasks with gRPC but not getting it with HTTP fallback that's surely something different, and something we'd like to take a look at. Let's keep talking in googleapis/nodejs-tasks#397.

[mvergarair]

@tanishiking :
I am also facing the similar issue for Publishing PubSub messages in bulk.
Did you get any solution to this problem?
If any, please share.

I'm having the same problem for PubSub, did you find a fix?

[tanishiking]

As @alexander-fenster mentioned, this issue just asked to add the library name or some actionable information on error massages so that users can easily debug the error.
This is not a bug report, and I think here's not the right place to ask about the errors around the GCP products or libraries.

FYI @abhirathod @mvergarair
In my case, the root cause of the error is just I forgot to add an await keyword on Promise object returned from pubsub-nodejs on Cloud Functions. However, the cause of your case might be different from mine, and it's better to have a further discussion on https://github.com/googleapis/nodejs-pubsub instead.

[mvergarair]

@tanishiking thanks! That was it, wasn't handling promises correctly. (Sry for commenting here)