Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Unhandled promise rejections #189

Closed
alcuadrado opened this issue Jun 1, 2018 · 22 comments
Closed

Unhandled promise rejections #189

alcuadrado opened this issue Jun 1, 2018 · 22 comments
Assignees
Labels
bug Verified to be an issue. help-wanted Looking for others' assistance or input.

Comments

@alcuadrado
Copy link

Hi,

I've noticed that issues #180 and #185 are due to unhandled promise rejections, so I analyzed the whole codebase (manually and using this eslint plugin) to find the root of these problems.

Note that this problems may be ignorable for now, but in the future node will kill the entire app if a promise rejection is unhandled. See: https://nodejs.org/dist/latest-v8.x/docs/api/deprecations.html#deprecations_dep0018_unhandled_promise_rejections

I identified the following Promises with a then() and no catch(), nor being returned:

Most of them are present in places where HTTP requests are done, and their failures are not managed.

There's also these cases, where a unhandledRejection handled is set, but you may want to fix them
anyway to avoid the bad patter:

Finally, these functions look suspicious. They have a try {} catch{} and a throw inside a then(). Not sure which was the intention, but the throw from the then() never gets to the catch clause`:

@ricmoo
Copy link
Member

ricmoo commented Jun 3, 2018

I will definitely get these fixed, but have you seen them in node? I’ve only seen these errors in the browser, which doesn’t seem as effective at detecting that promises are actually handled in a promise above them.

@alcuadrado
Copy link
Author

I haven't reproduced them in node yet. I'll try to do it later today/tomorrow. Simulating network latency or instability should work.

But except for the last to links, these promises are not returned nor assigned, so there's no promise above/bellow them in the promise chain.

For example, https://github.com/ethers-io/ethers.js/blob/master/providers/json-rpc-provider.js#L124 is
a promise created inside a promise, but the outer promise is never aware of the inner promise. So the inner promise doesn't handle errors.

@alcuadrado
Copy link
Author

Getting back to that example, if you want the promise returned by JsonRpcSigner.prototype.sendTransaction to poll for the transaction until it's found or a an error happens, you should only change the 'check()' function like this:

function check() {
  provider.getTransaction(hash).then(function(transaction) {
      if (!transaction) {
          setTimeout(check, 1000);
          return;
      }
      transaction.wait = function() {
          return provider.waitForTransaction(hash);
      };
      resolve(transaction);
  })
  .catch(reject); // <------ This line is new
}

If you can clarify if this is the intended behavior, I'm happy to submit a PR fixing all the cases.

@ricmoo ricmoo added bug Verified to be an issue. on-deck This Enhancement or Bug is currently being worked on. labels Jun 3, 2018
@alcuadrado
Copy link
Author

Here's a reproduction script that works in node.

It uses toxy and cors to create a proxy that simulates an bad connection, making 25% of the HTTP request fail.

It sends a transaction every second. Some of them will fail gracefully, but eventually one will result in an unhandled promise rejection (see: https://github.com/ethers-io/ethers.js/blob/master/providers/json-rpc-provider.js#L124) and the script will exit.

const ethers = require("ethers");
const toxy = require("toxy");
const cors = require("cors");

const JSONRPC_PROVIDER_URL = "http://localhost:8545";
const PROXY_PORT = 3000;
const CONNECTION_FAILURE_PORBABILITY = 25;

function createFaultyProxy() {
  const proxy = toxy({
    forwardHost: true,
    timeout: 6e4,
    proxyTimeout: 6e4
  });

  proxy.use(cors());

  proxy.forward(JSONRPC_PROVIDER_URL);

  proxy
    .all("/*")
    .poison(toxy.poisons.abort())
    .rule(toxy.rules.probability(CONNECTION_FAILURE_PORBABILITY));

  proxy.listen(PROXY_PORT);
  console.log(
    `Proxy listening on port ${PROXY_PORT}, redirecting everything to ${JSONRPC_PROVIDER_URL} with ${CONNECTION_FAILURE_PORBABILITY}% of chances of failing.`
  );
}

function sendTransaction(provider) {
  provider
    .listAccounts()
    .then(addresses => provider.getSigner(addresses[0]))
    .then(signer => signer.sendTransaction({ to: signer.address, value: 123 }))
    .catch(() =>
      console.log("Error from outer promise, not from check(): ignored")
    );
}

createFaultyProxy();

const provider = new ethers.providers.JsonRpcProvider(
  `http://localhost:${PROXY_PORT}`
);

process.on("unhandledRejection", (error, promise) => {
  console.error("Unhandled Rejection ", error);
  process.exit(1);
});

setInterval(() => sendTransaction(provider), 1000);

@tomergev
Copy link

tomergev commented Jun 6, 2018

This is also happening to me in Node! Here is my code! It works perfectly for 3-4 minutes and then I get this error:
`
(node:7862) UnhandledPromiseRejectionWarning: Error: invalid json response
at exports.XMLHttpRequest.request.onreadystatechange (/home/appo/node_modules/ethers/providers/provider.js:606:33)
at exports.XMLHttpRequest.dispatchEvent (/home/appo/node_modules/xmlhttprequest/lib/XMLHttpRequest.js:591:25)
at setState (/home/appo/node_modules/xmlhttprequest/lib/XMLHttpRequest.js:610:14)
at exports.XMLHttpRequest.handleError (/home/appo/node_modules/xmlhttprequest/lib/XMLHttpRequest.js:532:5)
at ClientRequest.errorHandler (/home/appo/node_modules/xmlhttprequest/lib/XMLHttpRequest.js:459:14)
at ClientRequest.emit (events.js:182:13)
at Socket.socketErrorListener (_http_client.js:382:9)
at Socket.emit (events.js:182:13)
at emitErrorNT (internal/streams/destroy.js:82:8)
at emitErrorAndCloseNT (internal/streams/destroy.js:50:3)
at process._tickCallback (internal/process/next_tick.js:63:19)

`

`
try {
const ethers = require('ethers')

const provider = new ethers.providers.JsonRpcProvider(HTTP://127.0.0.1:8588)

const Web3 = require('web3')

const web3 = new Web3(new Web3.providers.HttpProvider(HTTP://127.0.0.1:8588))

provider.on(
block,
async (blockNumber) => {
console.log(Enter provider on block ${blockNumber})
/*
If the block number is less than 2 (0 or 1), then do not excute the code below
*/
if (blockNumber < 2) {
return
}

  /*
    Getting the block info on the block which was just created and the previous one
 */
  const [
    currentBlockInfo,
    previousBlockNumber
  ] = await Promise.all([
    web3.eth.getBlock(blockNumber),
    web3.eth.getBlock(blockNumber - 1)
  ])

  /*
    Date is given in seconds from epoch so changing seconds to milliseconds
  */
  const timeCurrentBlockCreated = new Date(currentBlockInfo.timestamp * 1000)
  const timePreviousBlockCreated = new Date(previousBlockNumber.timestamp * 1000)

  /*
    Getting the amount of seconds elapsed since the last block was created
  */
  const durationOfBlockInSeconds = (
    timeCurrentBlockCreated.getTime() - timePreviousBlockCreated.getTime() // returns the time elapsed in milliseconds, therefore dividing this result by 1,000
  ) / 1000

  /*
    currentBlockInfo.transactions is an array of all the transactionId's which was proccess in the block
  */
  const numberOfProccessedTransactions = currentBlockInfo.transactions.length

  /*
    Getting the average number of transactions occuring per second
  */
  const averageNumberOfTransactionsPerSecond = numberOfProccessedTransactions / durationOfBlockInSeconds

  const {
    totalDifficulty,
    difficulty,
    gasUsed,
    gasLimit
  } = currentBlockInfo

  console.log({
    averageNumberOfTransactionsPerSecond,
    difficultyCurrentBlock: difficulty,
    difficultyTotal: totalDifficulty, // integer of the total difficulty of the chain until this block
    numberOfProccessedTransactions,
    durationOfBlockInSeconds,
    blockNumber,
    gasLimit,
    gasUsed
  })
}

)

} catch (err) {
console.log({
success: false,
err
})
}
`

@ricmoo
Copy link
Member

ricmoo commented Jun 6, 2018

I will be getting to this today. :)

@ricmoo ricmoo self-assigned this Jun 6, 2018
@tomergev
Copy link

tomergev commented Jun 6, 2018

Thanks! I am using ethers.js for a project at work so having this up and running will be very helpful to me :)

@D-Nice
Copy link

D-Nice commented Jun 25, 2018

@ricmoo any updates on this, have some projects dependent on this library.

@ricmoo
Copy link
Member

ricmoo commented Jun 26, 2018

Does the library fail to work in these cases? Or is it just noisy?

I've been focussing all my time on getting the TypeScript library up to date and will have this fixed in that branch soon. But if this is actually causing problems (other than unwanted logs) I can back port the fix to this branch too.

I'm hoping to get the new version out this week, with lots of new bells and whistles, and better APIs for a few features. :)

@D-Nice
Copy link

D-Nice commented Jun 26, 2018

I believe it may be the root cause of memory leaks in my project, which is a long-running monitoring tool, the memory leaks appear to occur when these unhandled rejections are logged.

EDIT:

Speaking of which, here is a recent log of said application after running for a few days:

Basically has an endless amount of lines of these errors

(node:48105) UnhandledPromiseRejectionWarning: Error: invalid json response
    at exports.XMLHttpRequest.request.onreadystatechange (/home/oraclize/sentry/node_modules/ethers/providers/provider.js:606:33)
    at exports.XMLHttpRequest.dispatchEvent (/home/oraclize/sentry/node_modules/xmlhttprequest/lib/XMLHttpRequest.js:591:25)
    at setState (/home/oraclize/sentry/node_modules/xmlhttprequest/lib/XMLHttpRequest.js:610:14)
    at IncomingMessage.<anonymous> (/home/oraclize/sentry/node_modules/xmlhttprequest/lib/XMLHttpRequest.js:447:13)
    at IncomingMessage.emit (events.js:187:15)
    at endReadableNT (_stream_readable.js:1081:12)
    at process._tickCallback (internal/process/next_tick.js:63:19)
(node:48105) UnhandledPromiseRejectionWarning: Unhandled promise rejection. This error originated either by throwing inside of an async function without a catch block, or by rejecting a promi
se which was not handled with .catch(). (rejection id: 141)

<--- Last few GCs --->

[48105:0x25f61a0] 726205465 ms: Mark-sweep 1392.9 (1425.7) -> 1392.7 (1426.2) MB, 304529.5 / 49.7 ms  (average mu = 0.160, current mu = 0.147) allocation failure scavenge might not succeed
[48105:0x25f61a0] 726509396 ms: Mark-sweep 1393.3 (1426.2) -> 1393.0 (1426.7) MB, 302081.9 / 73.3 ms  (average mu = 0.084, current mu = 0.006) allocation failure scavenge might not succeed

and then finally

FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory

@ricmoo
Copy link
Member

ricmoo commented Jun 27, 2018

Oh, I see. I can definitely see how that could leak memory for a system tracking the promises.

Sorry for the delay, I will fix this in both the 3.0 and 4.0 branch tomorrow.

@ricmoo
Copy link
Member

ricmoo commented Jun 28, 2018

@alcuadrado Huge thanks! That scripted helped reproduce the error immediately. I've also added the eslint to help isolate the issues. In the future, it will be part of the standard build process, but some of the rules need to be tweaked.

I will add the changes to the v4 branch later, since I think some refactoring I plan will help reduce the number of places I need to worry about.

Once Travis CI is complete, I'll publish to npm.

@ricmoo
Copy link
Member

ricmoo commented Jun 28, 2018

I need to increase the timeout on some test cases. I think I’m being throttled more by Travis CI since I’ve added more target platforms to test. I’ll get to that shortly.

@ricmoo
Copy link
Member

ricmoo commented Jun 29, 2018

This has been published to npm as 3.0.25.

I'm going to leave the issue open until all the updates to the 4.0 branch have also been updated, but for the 3.0 users, it should be good to go. :)

@ricmoo ricmoo added the v4.0 label Jun 29, 2018
@alcuadrado
Copy link
Author

I'm glad that the script helped you @ricmoo ! Thanks for fixing it :)

ricmoo added a commit that referenced this issue Jul 3, 2018
@ricmoo
Copy link
Member

ricmoo commented Jul 3, 2018

This has been fixed in the v4 (TypeScript) branch too.

Please re-open this issue if there are still issues. Thanks! :)

@ricmoo ricmoo closed this as completed Jul 3, 2018
@ricmoo ricmoo removed the on-deck This Enhancement or Bug is currently being worked on. label Jul 3, 2018
@D-Nice
Copy link

D-Nice commented Jul 5, 2018

The occurrence is much lower, but still occasionally seeing some unhandled rejections I believe are originating from the library:

(node:129589) UnhandledPromiseRejectionWarning: Error: invalid json response
    at exports.XMLHttpRequest.request.onreadystatechange (/home/oraclize/sentry/node_modules/ethers/providers/provider.js:611:33)
    at exports.XMLHttpRequest.dispatchEvent (/home/oraclize/sentry/node_modules/xmlhttprequest/lib/XMLHttpRequest.js:591:25)
    at setState (/home/oraclize/sentry/node_modules/xmlhttprequest/lib/XMLHttpRequest.js:610:14)
    at IncomingMessage.<anonymous> (/home/oraclize/sentry/node_modules/xmlhttprequest/lib/XMLHttpRequest.js:447:13)
    at IncomingMessage.emit (events.js:187:15)
    at endReadableNT (_stream_readable.js:1081:12)
    at process._tickCallback (internal/process/next_tick.js:63:19)

@ricmoo
Copy link
Member

ricmoo commented Jul 5, 2018

Boo-urns... :p

Is this in the master (v3) or TypeScript (v4) branch. I’ll look more I to these shortly...

@ricmoo ricmoo reopened this Jul 5, 2018
@D-Nice
Copy link

D-Nice commented Jul 5, 2018

3.0.25 from npm

@D-Nice
Copy link

D-Nice commented Aug 1, 2018

Here's another I've seen in the logs

3|sentry   | (node:70836) UnhandledPromiseRejectionWarning: TypeError: name.toLowerCase is not a function
3|sentry   |     at Object.namehash (/home/oraclize/sentry/node_modules/ethers/utils/namehash.js:12:17)
3|sentry   |     at FallbackProvider.resolveName (/home/oraclize/sentry/node_modules/ethers/providers/provider.js:946:26)
3|sentry   |     at FallbackProvider.getBalance (/home/oraclize/sentry/node_modules/ethers/providers/provider.js:709:17)

@ricmoo ricmoo removed the v4.0 label Sep 30, 2018
@ricmoo ricmoo added the help-wanted Looking for others' assistance or input. label Nov 9, 2018
@ricmoo
Copy link
Member

ricmoo commented Nov 9, 2018

I'm curious as to whether this still happens. I'll be working with GitCoin to help reward anyone who would like to help out. Details to follow. :)

@ricmoo
Copy link
Member

ricmoo commented Mar 13, 2020

I'm going to close this now. In v5 I've tried to keep everything inside an async function that needs to be, so hopefully the resulting Promises will keep this from happening. Please re-open this issue though, or open a new one if you find any instances of an error getting swallowed.

Thanks! :)

@ricmoo ricmoo closed this as completed Mar 13, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Verified to be an issue. help-wanted Looking for others' assistance or input.
Projects
None yet
Development

No branches or pull requests

4 participants