Chain falls over when a consistent load of transactions is thrown at it #363

dan-turner · 2017-12-11T04:30:53Z

Repro Steps

Create a Kubernetes cluster on GKE (version 1.8)
Deploy: https://github.com/CBAInnovationLab/k8s-ethermint
Forward node-0 8545 to localhost using script provided
Forward netstats 3000 to localhost using script provided
Clone: https://github.com/CBAInnovationLab/web3-sandbox
Run yarn install to install packages
Open browser and go to http://localhost:3000 to view netstats as the test runs
Run yarn start to throw 1000 transactions at node-0

Expected Behaviour

See yarn stream transaction hashes to console
See transactions being included in blocks in netstats
The delta section of final output should read:

Deltas
------
Coinbase: -1000
Another: 1000
Sum: 0

Actual Behaviour

Yarn streams transaction hashes to console
For a time, transactions can be seen being included in blocks in netstats
Part way through netstats shows zero txs being included in blocks despite transactions still streaming to node-0
The delta section of final output reads something like (we saw the number range from 117 to 1000):

Deltas
------
Coinbase: -423
Another: 423
Sum: 0

Trying to run the tests again results in something like the following:

Nonce: 3311
Error: known transaction: 176c44de0cb7134b0f0f966e2acfa8d883efa928171cf703b758f73866528035
    at Object.InvalidResponse (/Users/dan/code/web3-sandbox/node_modules/web3/lib/web3/errors.js:38:16)
    at /Users/dan/code/web3-sandbox/node_modules/web3/lib/web3/requestmanager.js:86:36
    at XMLHttpRequest.request.onreadystatechange (/Users/dan/code/web3-sandbox/node_modules/web3/lib/web3/httpprovider.js:122:7)
    at XMLHttpRequestEventTarget.dispatchEvent (/Users/dan/code/web3-sandbox/node_modules/xhr2/lib/xhr2.js:64:18)
    at XMLHttpRequest._setReadyState (/Users/dan/code/web3-sandbox/node_modules/xhr2/lib/xhr2.js:354:12)
    at XMLHttpRequest._onHttpResponseEnd (/Users/dan/code/web3-sandbox/node_modules/xhr2/lib/xhr2.js:509:12)
    at IncomingMessage.<anonymous> (/Users/dan/code/web3-sandbox/node_modules/xhr2/lib/xhr2.js:469:24)
    at emitNone (events.js:111:20)
    at IncomingMessage.emit (events.js:208:7)
    at endReadableNT (_stream_readable.js:1056:12)

The only way to recover the node is to delete the pod and wait for it to be recreated and resync.

There's also nothing suspicious in the logs.

Tendermint Logs

I[12-11|03:01:49.151] Executed block                               module=state height=8446 validTxs=23 invalidTxs=0
I[12-11|03:01:49.162] Committed state                              module=state height=8446 txs=23 hash=1779420665D96AEF06AB5A38D111FDFCD41DC0914D4082ABF4C3729921F32172
I[12-11|03:01:50.464] Executed block                               module=state height=8447 validTxs=29 invalidTxs=0
I[12-11|03:01:50.483] Committed state                              module=state height=8447 txs=29 hash=41B28EE9822505E71641F68A1B59F8F443938A30952E90B69182E5F13C64489E
I[12-11|03:01:51.743] Executed block                               module=state height=8448 validTxs=23 invalidTxs=0
I[12-11|03:01:51.757] Committed state                              module=state height=8448 txs=23 hash=2931791675D0A2FB5361126384E64AE1FD8648CD91E1FB3E57589FEAFA012B3C
I[12-11|03:01:53.049] Executed block                               module=state height=8449 validTxs=24 invalidTxs=0
I[12-11|03:01:53.067] Committed state                              module=state height=8449 txs=24 hash=66D1017DE365F48E6200679C81CABDA2E823F7A96770737EE900F95E806D2E67
I[12-11|03:01:54.365] Executed block                               module=state height=8450 validTxs=15 invalidTxs=0
I[12-11|03:01:54.374] Committed state                              module=state height=8450 txs=15 hash=AF8B200E030B0F25454C0E45E6B36F73538D0917C1785B5971424CF052BBD921
I[12-11|03:01:55.699] Executed block                               module=state height=8451 validTxs=0 invalidTxs=0
I[12-11|03:01:55.703] Committed state                              module=state height=8451 txs=0 hash=5FE2908669385CA7B7CB591D29541E271E8E77900D4FDAB6286343ED15EE1D9C
I[12-11|03:01:57.014] Executed block                               module=state height=8452 validTxs=0 invalidTxs=0
I[12-11|03:01:57.020] Committed state                              module=state height=8452 txs=0 hash=691B9D3B09A5A0559616292BB472D68AB1071B7C18CEA1E8C583D5EC2574BFDA
I[12-11|03:01:58.368] Executed block                               module=state height=8453 validTxs=0 invalidTxs=0
I[12-11|03:01:58.374] Committed state                              module=state height=8453 txs=0 hash=7F85A4E730EB1286A83A18CD69520E23CAD91A043AA8D01CCB3EC8D1873B7D7D
I[12-11|03:01:59.686] Executed block                               module=state height=8454 validTxs=0 invalidTxs=0
I[12-11|03:01:59.692] Committed state                              module=state height=8454 txs=0 hash=5079A2D1FEBC81A98ED0A0E1CCECE7D731AF81E760D445D854F9C5C166A4BC8E
I[12-11|03:02:01.025] Executed block                               module=state height=8455 validTxs=0 invalidTxs=0
I[12-11|03:02:01.028] Committed state                              module=state height=8455 txs=0 hash=A18E4517C8B8B4DD8BB79F0530728DC145AFA5D9FDF151F10992457EC41C7545
I[12-11|03:02:02.358] Executed block                               module=state height=8456 validTxs=0 invalidTxs=0
I[12-11|03:02:02.363] Committed state                              module=state height=8456 txs=0 hash=5F205610EA8794530E8E4BDD5F55243D6BCFBEFE002CF9D067FA42CA164CCCAB
I[12-11|03:02:03.696] Executed block                               module=state height=8457 validTxs=0 invalidTxs=0
I[12-11|03:02:03.700] Committed state                              module=state height=8457 txs=0 hash=AD79A2547C33CE40B126D737BBD8FA138BA8C557A9EC0189B6AFF3C1A1941735

Ethermint Logs

INFO [12-11|03:03:06] Imported new chain segment               blocks=1 txs=0  mgas=0.000 elapsed=2.034ms   mgasps=0.000    number=8504 hash=af5888…e06b89
INFO [12-11|03:03:06] Submitted transaction                    fullhash=0xce67e6c5e2ca5c3da837258005ea3ebc04885d53120d18728f8a1b9ec58daaf8 recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:06] Submitted transaction                    fullhash=0x8bd833bc4aa77f444151cffaf17bb82ad27eb3e282cbaeb3dae0b29351630b77 recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:06] Submitted transaction                    fullhash=0xbe85ab3ba6dcfbeb743c44479535a23f1ddeb4e7e776da9b183168afd0d87917 recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:06] Submitted transaction                    fullhash=0x11a0c5f4d2eadce3f80fea8be62fbc98e35498a56b0803db18138aa2a9c9cfcf recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0xbd6b0bba5c5d13ff99f4c7f6eea0e369e9711b386ddd9c2421f5915a923f5cfd recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0x50b4dbb5080414b24b6ff7f4ab0da34b856ca5e5bfd2aaeaf86591c5cc05803e recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0xf964ad9fc37b6759987aec4ccab25af376a9a5120b4e4b2f054580445ccc86ef recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0xca98b56f207c91c3f83900761f8735def14ae3ad740c128e2320a8c2d9e347ff recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0x3e2560d50a6d2ec69154d4adf9310eea190c9d87ae6320c48d16fd72d17183dc recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0xc0e3825343528dfb33c878f2e9f13079d7a8bcbb262eb8bc2728e3f3f1978c2c recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0xad00842cf9e7788593ec6808af2082f14b535758373231cbb5b8fdab8947b4e7 recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0x22f582a4b65a69121547e84601bdb985a0eb30ddfcfe88bb5fd571e1ffdb5131 recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0x47045dae4f43a97c6b2a030078b368c434759b85ca458fa89271d1248a1f06d2 recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0x496d85c4c3cb3d1a97e26dedd05bc0c4531d8d324c84d9ab0372e47872cc56a2 recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0xfe2fc3cfb894af102b7dad002d4e15aa8a3749f0a2edf2063c1df90c442f6f7b recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0xbfa5b49edc7390636d3f8563e7a5685b0e6d9f8fc31abe2b3226da3a7e53d7a6 recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0x94e21b259fec8c347c5dfe1aac17bfca2a6190d26f3dffd86e031ac8418d58bb recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0x65b7181667e641506f0e1632cf4935fe84587fb21cf1da5ea53319c165a450d4 recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0x365a3f85031c0130c81251d48cc57048286e062300e881085b50351ccf9d9e9c recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0x8d10553681ba9ece59a840406efd8fed7762bd563f697f8f54561c32cc1f176e recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0x5f47488f40bd335aaacc9bc3c0e45d03f8b8bf61bdfd4fb50118dcd936384372 recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0xc211a16e5f091ba3b62743ed5ba5274b07419f4376e079c6def3b9cf602d5eac recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0x1fd4430d687b2717e1fb43aeb9a90d141ebea75e229448a73b2ff9f7b3cd9d26 recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:07] Submitted transaction                    fullhash=0x475ead817ef919c9aa5b087f02c0b9af66afd79f28d073f4b0ab5fe9f7ce7dc9 recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:08] Submitted transaction                    fullhash=0x58c7ad91609bd2ff92ea63576c35cd31891a6c1be0177ac97b89a264543311ae recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:08] Submitted transaction                    fullhash=0x86e3eb9d34774f76c3d99c0edf73598c6f25ce6a3672e2180dc87a721d38652f recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:08] Submitted transaction                    fullhash=0x76b1a1b2b3b1f9c03991d88c14720e8f23b7334c6f2d0ef5e733345051161e01 recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:08] Imported new chain segment               blocks=1 txs=0  mgas=0.000 elapsed=591.996µs mgasps=0.000    number=8505 hash=46d02b…b1678f
INFO [12-11|03:03:08] Submitted transaction                    fullhash=0xe3bd87c1fde5303fa0a5baf0df04a8e23aaccd3f2894827f60719cd2f7c638d8 recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:08] Submitted transaction                    fullhash=0x2e109945628a5b615f7452123e92999dc3ac83d703fb8b6f964d41a28cdb0c57 recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:08] Submitted transaction                    fullhash=0x994cdc3349e66b10d6ea6c5bbaef1977c518d06a41b90bf898b2f82d876c96e7 recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:08] Submitted transaction                    fullhash=0xdecb338295f9aea67c75104d07103a3240686d9bec65a0446f2db47b0ce9367a recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:08] Submitted transaction                    fullhash=0x266440b473e84b579082681f2ada8239e22f0f63944f242716ef1f93768e14a2 recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c
INFO [12-11|03:03:08] Submitted transaction                    fullhash=0xc931b342236798df976e6dde753581e06950205bac4d5787900c6dd60cfe005f recipient=0xd4645b2d3d46746ebba9f5788e32250ae345a10c

The text was updated successfully, but these errors were encountered:

dan-turner · 2017-12-11T08:05:22Z

Interestingly, I went to try Quorum, and noticed that it's behaving quite similarly. It seems there is an issue for it over there too:

Consensys/quorum#189

Quorum logs:

node-7_1  | INFO [12-11|07:54:26] TX failed, will be removed               hash=089619…6ac0e9 err="nonce too high"
node-7_1  | INFO [12-11|07:54:26] Not minting a new block since there are no pending transactions
node-1_1  | INFO [12-11|07:54:26] Submitted transaction                    fullhash=0x3ad6c86a17beeb3ffb73e11f70c5dd2f4693eca2cd2878cbb182182af38a047f recipient=0xd4645B2D3d46746EBBa9f5788e32250AE345A10C
node-7_1  | INFO [12-11|07:54:26] TX failed, will be removed               hash=089619…6ac0e9 err="nonce too high"
node-7_1  | INFO [12-11|07:54:26] Not minting a new block since there are no pending transactions
node-1_1  | INFO [12-11|07:54:26] QUORUM-CHECKPOINT                        name=TX-CREATED      tx=0x3ad6c86a17beeb3ffb73e11f70c5dd2f4693eca2cd2878cbb182182af38a047f to=0xd4645B2D3d46746EBBa9f5788e32250AE345A10C
node-1_1  | INFO [12-11|07:54:26] Submitted transaction                    fullhash=0x63e52a7af865002bcf9e168dea8cff34d9a431097796f47d6b62246c4352631b recipient=0xd4645B2D3d46746EBBa9f5788e32250AE345A10C
node-1_1  | INFO [12-11|07:54:26] QUORUM-CHECKPOINT                        name=TX-CREATED      tx=0x63e52a7af865002bcf9e168dea8cff34d9a431097796f47d6b62246c4352631b to=0xd4645B2D3d46746EBBa9f5788e32250AE345A10C
node-7_1  | INFO [12-11|07:54:26] TX failed, will be removed               hash=089619…6ac0e9 err="nonce too high"
node-7_1  | INFO [12-11|07:54:26] Not minting a new block since there are no pending transactions
node-1_1  | INFO [12-11|07:54:26] Submitted transaction                    fullhash=0x50d6ad449d70cd9c7a7f69021b0fc14040a74b2b8059abbd6f72a927aaa66592 recipient=0xd4645B2D3d46746EBBa9f5788e32250AE345A10C
node-1_1  | INFO [12-11|07:54:26] QUORUM-CHECKPOINT                        name=TX-CREATED      tx=0x50d6ad449d70cd9c7a7f69021b0fc14040a74b2b8059abbd6f72a927aaa66592 to=0xd4645B2D3d46746EBBa9f5788e32250AE345A10C
node-7_1  | INFO [12-11|07:54:26] TX failed, will be removed               hash=089619…6ac0e9 err="nonce too high"
node-7_1  | INFO [12-11|07:54:26] Not minting a new block since there are no pending transactions

The following Parity in PoA playground on the other hand works perfectly with my test harness:
https://github.com/dstarcev/parity-poa-playground

dan-turner · 2017-12-11T13:01:00Z

Hmmm, I wonder if it's related to this:

ethereum/go-ethereum#14405
ethereum/go-ethereum#14523

Doesn't look like the txpool settings (e.g. --txpool.accountqueue) are exposed via ethermint. How can we test this?

dan-turner · 2017-12-11T23:55:52Z

If I inspect the txpool of node-0 (the node I sent the txs to) I see this:

> txpool
{
  content: {
    pending: {
      0xbfdacdfe79ccf1e61649220df47701df16606405: {
        3628: {...},
        3629: {...},
        3630: {...},
        3631: {...},
        3632: {...},
        
        // Lots more transactions

        4304: {...},
        4305: {...},
        4306: {...},
        4307: {...},
        4308: {...},
        4309: {...},
        4310: {...}
      }
    },
    queued: {}
  },
  inspect: {
    pending: {
      0xbfdacdfe79ccf1e61649220df47701df16606405: {
        3628: "0xd4645b2d3d46746ebba9f5788e32250ae345a10c: 1 wei + 4000001 × 0 gas",
        3629: "0xd4645b2d3d46746ebba9f5788e32250ae345a10c: 1 wei + 4000001 × 0 gas",
        3630: "0xd4645b2d3d46746ebba9f5788e32250ae345a10c: 1 wei + 4000001 × 0 gas",
        3631: "0xd4645b2d3d46746ebba9f5788e32250ae345a10c: 1 wei + 4000001 × 0 gas",
        3632: "0xd4645b2d3d46746ebba9f5788e32250ae345a10c: 1 wei + 4000001 × 0 gas",
        
        // Lots more transactions

        4304: "0xd4645b2d3d46746ebba9f5788e32250ae345a10c: 1 wei + 4000001 × 0 gas",
        4305: "0xd4645b2d3d46746ebba9f5788e32250ae345a10c: 1 wei + 4000001 × 0 gas",
        4306: "0xd4645b2d3d46746ebba9f5788e32250ae345a10c: 1 wei + 4000001 × 0 gas",
        4307: "0xd4645b2d3d46746ebba9f5788e32250ae345a10c: 1 wei + 4000001 × 0 gas",
        4308: "0xd4645b2d3d46746ebba9f5788e32250ae345a10c: 1 wei + 4000001 × 0 gas",
        4309: "0xd4645b2d3d46746ebba9f5788e32250ae345a10c: 1 wei + 4000001 × 0 gas",
        4310: "0xd4645b2d3d46746ebba9f5788e32250ae345a10c: 1 wei + 4000001 × 0 gas"
      }
    },
    queued: {}
  },
  status: {
    pending: 0,
    queued: 0
  },
  getContent: function(callback),
  getInspect: function(callback),
  getStatus: function(callback)
}

If I check the other nodes, their txpool is empty:

> txpool
{
  content: {
    pending: {},
    queued: {}
  },
  inspect: {
    pending: {},
    queued: {}
  },
  status: {
    pending: 0,
    queued: 0
  },
  getContent: function(callback),
  getInspect: function(callback),
  getStatus: function(callback)
}

Doesn't "pending" mean they should be processable?

Also, Tendermint on node-0 doesn't seem to see any unconfirmed txs:

> curl http://node-0.ethermint:46657/unconfirmed_txs
{
  "jsonrpc": "2.0",
  "id": "",
  "result": {
    "n_txs": 0,
    "txs": []
  }
}

illya13 · 2017-12-28T14:30:00Z

ethermint version ?

ratranqu · 2018-02-23T23:14:22Z

It's very likely this has been fixed by: tendermint/tendermint#1091

We are testing (so far conclusively) the fix back ported to a 0.10.x branch here:
https://gitlab.com/katalysis/tendermint/commits/tendermint-0.10.x

zramsay · 2018-07-11T18:44:46Z

see https://github.com/cosmos/ethermint for latest work on ethermint

zramsay added this to the 0.6.0 milestone Feb 8, 2018

zramsay closed this as completed Jul 11, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Chain falls over when a consistent load of transactions is thrown at it #363

Chain falls over when a consistent load of transactions is thrown at it #363

dan-turner commented Dec 11, 2017 •

edited

Loading

dan-turner commented Dec 11, 2017 •

edited

Loading

dan-turner commented Dec 11, 2017 •

edited

Loading

dan-turner commented Dec 11, 2017 •

edited

Loading

illya13 commented Dec 28, 2017

ratranqu commented Feb 23, 2018

zramsay commented Jul 11, 2018

Chain falls over when a consistent load of transactions is thrown at it #363

Chain falls over when a consistent load of transactions is thrown at it #363

Comments

dan-turner commented Dec 11, 2017 • edited Loading

Repro Steps

Expected Behaviour

Actual Behaviour

dan-turner commented Dec 11, 2017 • edited Loading

dan-turner commented Dec 11, 2017 • edited Loading

dan-turner commented Dec 11, 2017 • edited Loading

illya13 commented Dec 28, 2017

ratranqu commented Feb 23, 2018

zramsay commented Jul 11, 2018

dan-turner commented Dec 11, 2017 •

edited

Loading

dan-turner commented Dec 11, 2017 •

edited

Loading

dan-turner commented Dec 11, 2017 •

edited

Loading

dan-turner commented Dec 11, 2017 •

edited

Loading