The onCancel handler was attached after the promise settled

[myfreeer]

Describe the bug

• Node.js version: 12.16.2 x64 (LTS)
• OS & version: Windows 10 LTSC x64
• got version: v11.0.2

Using Promise API with socket timeout and retry, this does not reproduce on Node.js 14.0.0.

Actual behavior

Promise rejected before retry, and stderr printed message like below:

(node:9792) UnhandledPromiseRejectionWarning: Error: The `onCancel` handler was attached after the promise settled.
    at onCancel (D:\TEMP\test-case\node_modules\p-cancelable\index.js:46:12)
    at makeRequest (D:\TEMP\test-case\node_modules\got\dist\source\as-promise\index.js:39:13)
    at Timeout.retry [as _onTimeout] (D:\TEMP\test-case\node_modules\got\dist\source\as-promise\index.js:182:25)
    at listOnTimeout (internal/timers.js:549:17)
    at processTimers (internal/timers.js:492:7)
(node:9792) 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(). To terminate the node process on unhandled promise rejection, use the CLI flag `--unhandled-rejections=strict` (see https://nodejs.org/api/cli.html#cli_unhandled_rejections_mode). (rejection id: 1)
(node:9792) [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.

Edited: some logs showing the timestamp.

1587995291087 response event fired
1587995291088 before await getStream.buffer(request)
1587995291117 error event fired
1587995291118 catch block after await getStream.buffer(request)
1587995291119 promise rejected in catch block
1587995292181 retry

Expected behavior

Retryed.

Code to reproduce

const http = require('http');

const got = require('got').extend({
  timeout: {
    socket: 20
  },
  retry: {
    limit: 5
  }
});

let requested = false;

let server = http.createServer(((req, res) => {
  if (requested) {
    res.writeHead(200, {
      'Content-Length': 8
    });
    res.write('ok123456');
    return;
  }
  req.socket.pause();
  setTimeout(() => {
    res.writeHead(200, {
      'Content-Length': 8
    });
    res.write('ok');
  }, 10);
  setTimeout(() => {
      res.write('123');
  }, 20);
  setTimeout(() => {
      requested = true;
      res.write('456');
      res.end();
  }, 41);
}));


server.listen(45678, 'localhost', async () => {
  try {
    let r = await got('http://localhost:45678/');
    console.log(r && r.body);
  } catch (e) {
    console.log('promise rejected', e);
  }
  setTimeout(() => server.close(), 400);
});

Checklist

• I have read the documentation.
• I have tried my code with the latest version of Node.js and Got.

[yodhcn]

The same error.

[szmarczak]

Simplest repro:

const http = require('http');

const got = require('.').extend({
	timeout: 20,
	retry: {
		limit: 1
	}
});

const server = http.createServer((_request, response) => {
	response.write('ok');
});


server.listen(45678, 'localhost', async () => {
	try {
		const {body} = await got('http://localhost:45678/');
		console.log(body);
	} catch (error) {
		console.log('promise rejected', error);
	}
});

[szmarczak]

Wow, in fact there are 3 unhandled errors when running inside tests.

[cjroebuck]

Still getting this error on 11.3.0

[szmarczak]

@cjroebuck Can you post reproducible code please?

[cjroebuck]

Hmm. It's happening about once per 12-24 hours, in production, Sorry I'm not sure how to repro.

These are the options I'm using though:

const gotOpts = {
    form: query,
    timeout: 10000,
    throwHttpErrors: false,
    retry: {
      limit: 2,
      calculateDelay: ({ attemptCount, retryOptions, error, computedValue }) => {
        if (computedValue) {
          // let retryIn = 1000 * Math.pow(2, attemptCount) + Math.random() * 100;
          logger.warn("Got an error from engine, retry in", computedValue, longRequestId, { attemptCount, error: error.message });
          return computedValue;
        }
        logger.info("Do not retry", error.message, longRequestId)
        return 0;
      },
      methods: ['POST'] as Method[]
    }
  };
let response = await got.post(someUrl, gotOpts);

stack trace:

"Error: The `onCancel` handler was attached after the promise settled. 
at onCancel (/usr/src/app/node_modules/p-cancelable/index.js:46:12)
at makeRequest (/usr/src/app/node_modules/got/dist/source/as-promise/index.js:39:13)
at Timeout.retry [as _onTimeout] (/usr/src/app/node_modules/got/dist/source/as-promise/index.js:178: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)

[szmarczak]

@cjroebuck Thanks. What Node.js version are you using?

[szmarczak]

Using node 10. Under what conditions is request.destroy() called?

When there's a timeout. I think I know how to reproduce this. Thanks for the info.

[szmarczak]

@cjroebuck Is the error an unhandled promise or you caught it in the catch clause?

[cjroebuck]

Unhandled rejection.

[cjroebuck]

The query variable is a query string object, next time it happens I'll try and grab the contents. I have updated to node 14 in prod though based on what myfreer said initially.

[szmarczak]

@cjroebuck Can you replace

let response = await got.post(someUrl, gotOpts);

with

let response = await got.post(someUrl, gotOpts).on('request', request => {
	const timestamp = Date.now();

	request.once('error', error => {
		console.log(`${timestamp} Received error:`, error);
	});

	request.once('response', response => {
		console.log(`${timestamp} Got response`);

		response.on('readable', () => {
			console.log(`${timestamp} Response is readable`, response.complete);
		});

		response.once('end', () => {
			console.log(`${timestamp} Response ended`);
		});
	});
});

If you could send me the logs, it would be great.

[szmarczak]

@cjroebuck Does setting retry.limit to 1 fix the issue?

[szmarczak]

@cjroebuck What's the status of the let response = await got.post(someUrl, gotOpts); promise? Is it resolved or rejected? If rejected, what error does it give?

[szmarczak]

You can also make calculateDelay log the error.

[szmarczak]

Related: #1308

[szmarczak]

This should be fixed in 11.4.0.

[foxundermoon]

i meet the issue on version: 11.8.5

This should be fixed in 11.4.0.

/Users/fox/.nvm/versions/node/v18.0.0/lib/node_modules/serverless/node_modules/p-cancelable/index.js:48
					throw new Error('The `onCancel` handler was attached after the promise settled.');
					      ^

Error: The `onCancel` handler was attached after the promise settled.
    at onCancel (/Users/fox/.nvm/versions/node/v18.0.0/lib/node_modules/serverless/node_modules/p-cancelable/index.js:48:12)
    at makeRequest (/Users/fox/.nvm/versions/node/v18.0.0/lib/node_modules/serverless/node_modules/got/dist/source/as-promise/index.js:38:13)
    at Request.<anonymous> (/Users/fox/.nvm/versions/node/v18.0.0/lib/node_modules/serverless/node_modules/got/dist/source/as-promise/index.js:143:17)
    at Object.onceWrapper (node:events:642:26)
    at Request.emit (node:events:527:28)
    at Timeout.retry (/Users/fox/.nvm/versions/node/v18.0.0/lib/node_modules/serverless/node_modules/got/dist/source/core/index.js:1278:30)
    at listOnTimeout (node:internal/timers:564:17)
    at process.processTimers (node:internal/timers:507:7)

Node.js v18.0.0

[szmarczak]

That's probably #1489