unhandled rejections when enabling http2

[rarkins]

In an attempt to improve performance of our hosted Renovate Bot service, we have enabled http2 for github.com, registry.npmjs.org and registry.yarnpkg.com. We are now seeing occasional unhandled rejections thrown:

{
  "err": {
    "code": "HTTP2WRAPPER_NOSETTINGS",
    "message": "Session closed without receiving a SETTINGS frame",
    "stack": "Error: Session closed without receiving a SETTINGS frame\n at ClientHttp2Session.<anonymous> (/home/ubuntu/renovateapp/node_modules/http2-wrapper/source/agent.js:396:22)\n at Object.onceWrapper (events.js:519:28)\n at ClientHttp2Session.emit (events.js:400:28)\n at ClientHttp2Session.emit (domain.js:475:12)\n at emitClose (internal/http2/core.js:1052:8)\n at internal/http2/core.js:1090:7\n at TLSSocket.onfinish (internal/streams/writable.js:689:5)\n at TLSSocket.emit (events.js:400:28)\n at TLSSocket.emit (domain.js:475:12)\n at finish (internal/streams/writable.js:657:10)\n at finishMaybe (internal/streams/writable.js:644:9)\n at ShutdownWrap.callback (internal/streams/writable.js:617:7)\n at ShutdownWrap.afterShutdown [as oncomplete] (net.js:446:8)"
  }
}

and

{
  "err": {
    "message": "The `onCancel` handler was attached after the promise settled.",
    "stack": "Error: The `onCancel` handler was attached after the promise settled.\n at onCancel (/home/ubuntu/renovateapp/node_modules/p-cancelable/index.js:48:12)\n at makeRequest (/home/ubuntu/renovateapp/node_modules/got/dist/source/as-promise/index.js:38:13)\n at Request.<anonymous> (/home/ubuntu/renovateapp/node_modules/got/dist/source/as-promise/index.js:143:17)\n at Object.onceWrapper (events.js:520:26)\n at Request.emit (events.js:400:28)\n at Request.emit (domain.js:475:12)\n at Timeout.retry (/home/ubuntu/renovateapp/node_modules/got/dist/source/core/index.js:1278:30)\n at listOnTimeout (internal/timers.js:557:17)\n at processTimers (internal/timers.js:500:7)"
  }
}

I see that sometimes both these rejections occur for the same repo, meaning they seem to be related.

Does the fact that these are unhandled imply that we are missing some asynchronous error handling in our code which wraps got? Or is it expected that these are impossible to catch normally?

[szmarczak]

The first error means that the socket got closed before there was any communication. What domain is that? You can try logging error.options.url as well.

The latter is another occurence of #1489 - is this the first time you got this error?

[rarkins]

For the first HTTP2WRAPPER_NOSETTINGS type of error, I also saw this exception handling in the regular logs:

{
  "hostType": "npm",
  "packageName": "just-logger",
  "err": {
    "event": "request",
    "name": "TimeoutError",
    "code": "ETIMEDOUT",
    "message": "Timeout awaiting 'request' for 60000ms",
    "stack": "TimeoutError: Timeout awaiting 'request' for 60000ms\n    at Timeout.timeoutHandler [as _onTimeout] (/home/ubuntu/renovateapp/node_modules/got/dist/source/core/utils/timed-out.js:36:25)\n    at listOnTimeout (internal/timers.js:559:11)\n    at processTimers (internal/timers.js:500:7)"
  },
  "msg": "Host error",
}

This implies it's registry.npmjs.org which has had this problem.

For the second one, we just turned on http2 today and the errors like this started immediately. In total we sends hundreds of thousands of requests through got to GitHub per hour.

[szmarczak]

This implies it's registry.npmjs.org which has had this problem.

IIRC the npm servers are known to time out. I even saw GH Actions timing out on npm install. You could try contacting them, I'm not much to help here.

For the second one, we just turned on http2 today and the errors like this started immediately.

Interesting. Looking into this.