ethers.js
ethers.js copied to clipboard
ethers-io
WaitForTransaction() incorrectly times out (the transaction was immediately mined)
Describe the bug A transaction was submitted and quickly mined on the network; however, waitForTransaction did not return and in fact ended up failing as if the transaction was not mined/confirmed.
- Transaction submitted:
[2021-04-14 13:04:25.209 +0000] INFO (IndexerAgent/1 on indexer-agent-0): Transaction pending - It is mined at Apr-14-2021 01:04:35 PM +UTC (https://rinkeby.etherscan.io/tx/0xf15ee7523d3943bf1e0880c0e0ff388ed715fe7b0162fe80de9acda88b29581b)
- waitForTransaction timed out thinking that the tx did not get 3 confirmations
[2021-04-14 13:14:24.424 +0000] WARN (IndexerAgent/1 on indexer-agent-0): Failed to send transaction, retrying
Here is the place where waitForTransaction is used in our application: https://github.com/graphprotocol/indexer/blob/552061320c50635094af3b1fdc12d2d981a0e6a1/packages/indexer-agent/src/network.ts#L182-L185
Environment:
- The issue was noticed on a Node application running on a GCloud cluster VM (Ubuntu) talking to an Alchemy API Rinkeby endpoint.
- Ethers v5.1.0
- Using a
StaticJsonRpcProvider
Search Terms waitForTransaction(), transaction incorrectly timed out
Also odd: the timeout passed to waitForTransaction is 240000. This is also the time that waitForTransaction claims to have timed out with. But this happens after 10 minutes, not 4 minutes (see the log timestamps). I've confirmed that those 10 minutes are accurate.
I did some more experimentation today by setting the waitForTransaction timeout to 0.
The resulting behavior (waiting for 3 confirmations): transactions are always detected as being mined and having 3 confirmations eventually.
Sometimes waitForTransaction returns at the right time but every few transactions there's a (fairly precise) 10 minute delay between the block (and tx) being mined and await waitForTransaction(txHash, 3, 0) returning.
From our logs:
[2021-04-17 17:15:50.162 +0000] INFO (IndexerAgent/1 on indexer-agent-0): Sending transaction
attempt: 1
createdAtEpoch: 947
deployment: {
"ipfsHash": "QmVqMeQUwvQ3XjzCYiMhRvQjRiQLGpVt8C3oHgvDi3agJ2",
"bytes32": "0x6f5c5b9b2bb184bca1d2f578b1df5526507d42943a189afe35d797c7a7ad0abf"
}
indexer: "0x259748aC4941ACC2bFA372F5Fa240c3B8236d70a"
poi: "0x065a68d599316879e2b8277d75efb72a494e1eeba577e3a54a9c2023b13392f7"
tx: {
"v": 43,
"chainId": 4,
"value": {
"hex": "0x00",
"type": "BigNumber"
},
"from": "0xC2208Fe87805279b03c1a8a78d7eE4BfDb0E48eE",
"hash": "0x7bef973597ff61abe1a711e4c69aa77768c359ae15f8cde0b423a719e2f4e160",
"s": "0x335be1b84a6d539f6d123e3d27b5c717c8dbdc8c2dc53a5802b9779a801070b7",
"data": "0x44c32a61000000000000000000000000b5b7c038c86d9bccec91a781635766e254e506e9065a68d599316879e2b8277d75efb72a494e1eeba577e3a54a9c2023b13392f7",
"type": null,
"gasPrice": {
"hex": "0x3b9aca00",
"type": "BigNumber"
},
"to": "0x2d44C0e097F6cD0f514edAC633d82E01280B4A5c",
"r": "0xbfe474d1445d5098b42f67f89745ec0e5a4e236e8dd045433fe61e7c23152d37",
"nonce": 7592,
"gasLimit": {
"hex": "0x062ae4",
"type": "BigNumber"
}
}
component: "Network"
allocation: "0xb5B7c038C86D9BCCec91A781635766e254e506e9"
createdAtBlockHash: "0x664ce3afcfb294e6129122144fcfddc9705f8524abd43a70ab3ad3069428c5cf"
action: "close"
operator: "0xC2208Fe87805279b03c1a8a78d7eE4BfDb0E48eE"
[2021-04-17 17:15:50.162 +0000] INFO (IndexerAgent/1 on indexer-agent-0): Transaction pending
action: "close"
tx: {
"data": "0x44c32a61000000000000000000000000b5b7c038c86d9bccec91a781635766e254e506e9065a68d599316879e2b8277d75efb72a494e1eeba577e3a54a9c2023b13392f7",
"v": 43,
"gasLimit": {
"hex": "0x062ae4",
"type": "BigNumber"
},
"hash": "0x7bef973597ff61abe1a711e4c69aa77768c359ae15f8cde0b423a719e2f4e160",
"s": "0x335be1b84a6d539f6d123e3d27b5c717c8dbdc8c2dc53a5802b9779a801070b7",
"to": "0x2d44C0e097F6cD0f514edAC633d82E01280B4A5c",
"from": "0xC2208Fe87805279b03c1a8a78d7eE4BfDb0E48eE",
"value": {
"type": "BigNumber",
"hex": "0x00"
},
"chainId": 4,
"nonce": 7592,
"r": "0xbfe474d1445d5098b42f67f89745ec0e5a4e236e8dd045433fe61e7c23152d37",
"gasPrice": {
"hex": "0x3b9aca00",
"type": "BigNumber"
},
"type": null
}
createdAtEpoch: 947
component: "Network"
createdAtBlockHash: "0x664ce3afcfb294e6129122144fcfddc9705f8524abd43a70ab3ad3069428c5cf"
indexer: "0x259748aC4941ACC2bFA372F5Fa240c3B8236d70a"
poi: "0x065a68d599316879e2b8277d75efb72a494e1eeba577e3a54a9c2023b13392f7"
allocation: "0xb5B7c038C86D9BCCec91A781635766e254e506e9"
deployment: {
"bytes32": "0x6f5c5b9b2bb184bca1d2f578b1df5526507d42943a189afe35d797c7a7ad0abf",
"ipfsHash": "QmVqMeQUwvQ3XjzCYiMhRvQjRiQLGpVt8C3oHgvDi3agJ2"
}
operator: "0xC2208Fe87805279b03c1a8a78d7eE4BfDb0E48eE"
...
[2021-04-17 17:25:50.305 +0000] INFO (IndexerAgent/1 on indexer-agent-0): Transaction successfully included in block
indexer: "0x259748aC4941ACC2bFA372F5Fa240c3B8236d70a"
operator: "0xC2208Fe87805279b03c1a8a78d7eE4BfDb0E48eE"
allocation: "0xb5B7c038C86D9BCCec91A781635766e254e506e9"
receipt: {
"blockNumber": 8429717,
"logs": [
{
"topics": [
"0xddf252ad1be2c89b69c2b068fc378daa952ba7f163c4a11628f55a4df523b3ef",
"0x0000000000000000000000000000000000000000000000000000000000000000",
"0x0000000000000000000000002d44c0e097f6cd0f514edac633d82e01280b4a5c"
],
"logIndex": 28,
"data": "0x0000000000000000000000000000000000000000000000000000247c716d9cb5",
"blockNumber": 8429717,
"transactionHash": "0x7bef973597ff61abe1a711e4c69aa77768c359ae15f8cde0b423a719e2f4e160",
"address": "0x54Fe55d5d255b8460fB3Bc52D5D676F9AE5697CD",
"blockHash": "0xf641f8327772d56a41e0ed5e81c0957b814875ecc2ecbec9499baa40bb45f40a",
"transactionIndex": 16
},
{
"blockHash": "0xf641f8327772d56a41e0ed5e81c0957b814875ecc2ecbec9499baa40bb45f40a",
"address": "0x460cA3721131BC978e3CF3A49EfC545A2901A828",
"transactionIndex": 16,
"topics": [
"0x315d9cdbc182c9118c140c78a121ebb9f24bf73f841339a8a41cdc3586c34e18",
"0x000000000000000000000000259748ac4941acc2bfa372f5fa240c3b8236d70a",
"0x000000000000000000000000b5b7c038c86d9bccec91a781635766e254e506e9"
],
"transactionHash": "0x7bef973597ff61abe1a711e4c69aa77768c359ae15f8cde0b423a719e2f4e160",
"data": "0x00000000000000000000000000000000000000000000000000000000000003b40000000000000000000000000000000000000000000000000000247c716d9cb5",
"logIndex": 29,
"blockNumber": 8429717
},
{
"logIndex": 30,
"address": "0x2d44C0e097F6cD0f514edAC633d82E01280B4A5c",
"blockNumber": 8429717,
"topics": [
"0x0a7bb2e28cc4698aac06db79cf9163bfcc20719286cf59fa7d492ceda1b8edc2",
"0x000000000000000000000000259748ac4941acc2bfa372f5fa240c3b8236d70a"
],
"data": "0x0000000000000000000000000000000000000000000000000000247c716d9cb5",
"transactionHash": "0x7bef973597ff61abe1a711e4c69aa77768c359ae15f8cde0b423a719e2f4e160",
"transactionIndex": 16,
"blockHash": "0xf641f8327772d56a41e0ed5e81c0957b814875ecc2ecbec9499baa40bb45f40a"
},
{
"data": "0x00000000000000000000000000000000000000000000000000000000000003b4000000000000000000000000000000000000000000000000002386f26fc10000000000000000000000000000000000000000000000000000002386f26fc10000000000000000000000000000c2208fe87805279b03c1a8a78d7ee4bfdb0e48ee065a68d599316879e2b8277d75efb72a494e1eeba577e3a54a9c2023b13392f70000000000000000000000000000000000000000000000000000000000000000",
"blockNumber": 8429717,
"transactionIndex": 16,
"transactionHash": "0x7bef973597ff61abe1a711e4c69aa77768c359ae15f8cde0b423a719e2f4e160",
"address": "0x2d44C0e097F6cD0f514edAC633d82E01280B4A5c",
"blockHash": "0xf641f8327772d56a41e0ed5e81c0957b814875ecc2ecbec9499baa40bb45f40a",
"logIndex": 31,
"topics": [
"0x7203ffa6902c4c2a85ac2612321460fa20e29a972c272ecedfdf95f944616269",
"0x000000000000000000000000259748ac4941acc2bfa372f5fa240c3b8236d70a",
"0x6f5c5b9b2bb184bca1d2f578b1df5526507d42943a189afe35d797c7a7ad0abf",
"0x000000000000000000000000b5b7c038c86d9bccec91a781635766e254e506e9"
]
}
],
"blockHash": "0xf641f8327772d56a41e0ed5e81c0957b814875ecc2ecbec9499baa40bb45f40a",
"to": "0x2d44C0e097F6cD0f514edAC633d82E01280B4A5c",
"status": 1,
"transactionIndex": 16,
"transactionHash": "0x7bef973597ff61abe1a711e4c69aa77768c359ae15f8cde0b423a719e2f4e160",
"cumulativeGasUsed": {
"type": "BigNumber",
"hex": "0x1b4ea2"
},
"contractAddress": null,
"confirmations": 40,
"from": "0xC2208Fe87805279b03c1a8a78d7eE4BfDb0E48eE",
"gasUsed": {
"hex": "0x040e1b",
"type": "BigNumber"
},
"logsBloom": "0x02000000000000000000000080000000000000000000000000000000000000000000000000800000000000000000000000000000000010000000000000000140100000400000000000000008000000000000000000000020000020000000000000000000020001000001000000000800200000000000000800000010001000000000000000000040000000000000000000000008000000000000002000000000400000000000000000800000000000008000000000000000020000000000000000000002000001000000000100000000000000000000000000000000040020000000000020000808800000000000400000000000000000000000000000000000",
"byzantium": true
}
poi: "0x065a68d599316879e2b8277d75efb72a494e1eeba577e3a54a9c2023b13392f7"
deployment: {
"ipfsHash": "QmVqMeQUwvQ3XjzCYiMhRvQjRiQLGpVt8C3oHgvDi3agJ2",
"bytes32": "0x6f5c5b9b2bb184bca1d2f578b1df5526507d42943a189afe35d797c7a7ad0abf"
}
tx: "0x7bef973597ff61abe1a711e4c69aa77768c359ae15f8cde0b423a719e2f4e160"
createdAtBlockHash: "0x664ce3afcfb294e6129122144fcfddc9705f8524abd43a70ab3ad3069428c5cf"
component: "Network"
createdAtEpoch: 947
action: "close"
In this case, waitForTransaction(txHash, 3, 0) only returns at 17:25:50 UTC but the block in question was already mined at 17:15:59: https://rinkeby.etherscan.io/block/8429717.
What could cause this delay? Note that it happens reliably every few transactions.
I've been trying to reproduce this but cannot.
Do you possibly have a long running CPU intensive test that does not yield to the event loop? Are you using your own API key?
Can you try out this script, and see if you see the same problem? I'm wondering if it is a link/firewall issue:
const { ethers } = require("ethers");
let lastNow = null;
function getTime() {
const now = (new Date()).getTime();
if (lastNow == null) { lastNow = now; }
const result = parseInt(String(now - lastNow)) / 1000;
lastNow = now;
return result;
}
(async function() {
const provider = new ethers.providers.AlchemyProvider("ropsten");
while (1) {
// reset the timer
getTime();
// Get the current block
const blockNumber = await provider.getBlockNumber();
console.log(`Block Number (${ getTime() }):`, blockNumber);
// Get a transaction to test
const txs = (await provider.getBlockWithTransactions(blockNumber)).transactions;
if (txs.length === 0) { continue; }
const tx = txs[0];
console.log(`Transaction (${ getTime() }):`, tx.hash);
//console.log(`Receipt before wait (${ getTime() }):`, await provider.getTransactionReceipt(tx.hash));
// Wait for the receipt
try {
const receipt = await provider.waitForTransaction(tx.hash, 3, 0);
console.log(`Receipt after wait (${ getTime() }):`, receipt.confirmations);
} catch (error) {
console.log(`Receipt after wait error (${ getTime() }):`, error);
}
console.log("=========================");
}
})();
Also, it shouldn't matter, but can you also remove your node_modules/, package-lock.json (and yarn lock file if you use yarn) and do a new npm install to get the latest versions?
I've also tried setting the number of confirmations to a very large number and the timeout to smaller values, and the timeout seems to be honoured.
If you can tweak this script to reproduce the problem too, that might help me figure out the issue.
Thanks! :)
@ricmoo Thanks for the reply! I'm running the above script with the same provider URL that triggered the issue for me now. I'll let you know whether that triggers the issue. I'm testing with ethers 5.1.0 first.
It doesn't look like minedHandler is called after the first transaction is mined, so with any value of confirmations greater than 1, it never resolves?
https://github.com/ethers-io/ethers.js/blob/master/packages/providers/src.ts/base-provider.ts#L953
@peterbraden What do you mean? It registers a callback using .on, so it will be called on every block after the transaction is mined. It is not using .once.