Understanding ETIMEDOUT logs

[rarkins]

If we see a 60000ms timeout logged like either of the below:

    "code": "ETIMEDOUT",
    "timings": {
      "start": 1661933000729,
      "socket": 1661933000945,
      "lookup": 1661933108895,
      "error": 1661933108935,
      "phases": {
        "wait": 216,
        "dns": 107950,
        "total": 108206
      }
    },

or

    "code": "ETIMEDOUT",
    "timings": {
      "start": 1661931980128,
      "socket": 1661931980332,
      "error": 1661932081516,
      "phases": {
        "wait": 204,
        "total": 101388
      }
    },

Does this imply that the problem is occurring very early, e.g. during DNS lookup?

And considering that the host is api.github.com and there are other concurrent requests succeeding at the same time.. can we conclude anything from this?

Also is there any got timeout settings we could adjust to fail this faster and retry?

[viceice]

We're still stuck got v11¹

Footnotes

1. https://github.com/renovatebot/renovate/blob/7c056534e7e85c4b230a2a5177d55e680fc62b7b/package.json#L180 ↩

[viceice]

maybe related to

• Getting occasional dns lookup timeouts when load testing, which are not being retried #1605

[rarkins]

@williamcoates you seemed to have similar problems last year. Were you able to resolve them?

[szmarczak]

https://github.com/szmarczak/http-timer

Looking at the first one, it seems that it took 107.95 seconds to get the reply from DNS. The latter timed out after 101 seconds with no DNS reply.

I suggest that you set the lookup timeout to 500 or 1000.

there are other concurrent requests succeeding at the same time.

You could try using https://github.com/szmarczak/cacheable-lookup

[szmarczak]

Is there a way to set the lookup timeout to be low while keeping everything else to 60s? I want to try lowering them one by one to avoid unforeseen problems.

await got({
	...,
	timeout: {
		request: 60 * 1000,
		lookup: 1000,
	}
});

[rarkins]

Because we're not using CacheableLookup directly, I'm not sure that code snippet works for us. IIRC the reason for a custom cache was because GitHub returned a zero second TTL, which meant it wasn't cached at all.

[szmarczak]

What's the GitHub domain?

[rarkins]

api.github.com

[szmarczak]

Are you sure api.github.com has 0 TTL? Here it returns 60.

[rarkins]

We switched to http2 so maybe now skip the lookup stage, but still fail:

  "err": {
    "name": "TimeoutError",
    "code": "ETIMEDOUT",
    "timings": {
      "start": 1662177845433,
      "socket": 1662177845567,
      "upload": 1662177946760,
      "error": 1662177946789,
      "phases": {
        "wait": 134,
        "request": null,
        "total": 101356
      }
    },
    "event": "request",
    "message": "Timeout awaiting 'request' for 60000ms",

What does the above indicate if the URL is a POST to https://api.github.com/graphql. Does "upload" mean the POST submission essentially times out and the response hasn't even started?

[rarkins]

Unfortunately we can't reproduce the problem locally. It's only occurring in our hosted app, which is Node.js 14/Ubuntu 20.04 running inside Docker containers on EC2 on AWS. Happens to certain repos consistently but not always. Typically ones needing a lot of GitHub graphql API queries. Similar problem with some large (10s of MB) npm registry fetches. Both scenarios it seems like querying multiple in parallel is to blame. Not sure if there's memory pressure, socket exhaustion, or simply a low level bug where they overwrite each other.

Any thoughts on what we could debug log at times when we catch such timeouts?

[szmarczak]

Definitely please try Node.js 16 & 18. HTTP/2 in Node.js <16 is extremely buggy. The timings could be also incorrect due to Node.js stream bugs (e.g. it could say that it finished uploading when it actually didn't), not sure if this is the case though. Let me know what's the result.

[rarkins]

FYI the timeouts have been happening since before we enabled http2, so it seems unrelated.

[viceice]

@rarkins should we try node v16 anyways?

[szmarczak]

FYI the timeouts have been happening since before we enabled http2, so it seems unrelated.

I'm aware of that, however it could possibly reveal the underlying issue. I think there could be a deadlock somewhere, but without trying we can't do anything.

[rarkins]

Here's a summary of what we found so far:

• We fixed the GitHub API GraphQL timeouts by rolling back to an earlier solution which uses REST and no caching tricks. We don't know yet if the problem was GraphQL-related or our tricks, but will eventually confirm that as we add it back step by step
• Enabling http2 with Node 14 for npmjs resulted in strange problems, including ECONNRESET. Reverting http2 fixed them. We have subsequently upgraded to Node 16 but not yet tested http2 again

[szmarczak]

We fixed the GitHub API GraphQL timeouts by rolling back to an earlier solution which uses REST and no caching tricks. We don't know yet if the problem was GraphQL-related or our tricks, but will eventually confirm that as we add it back step by step

Can you send me a commit link? I'm curious what has changed.

Enabling http2 with Node 14 for npmjs resulted in strange problems, including ECONNRESET. Reverting http2 fixed them. We have subsequently upgraded to Node 16 but not yet tested http2 again

Please do try it out and let me know.

[rarkins]

This was the PR where we changed our github tags/releases fetching: renovatebot/renovate#17685