search

trufflesuite / ganache-cli-archive

Fast Ethereum RPC client for testing and development. See https://github.com/trufflesuite/ganache for current development.
https://www.trufflesuite.com/ganache
MIT License
3.36k stars 695 forks source link

testrpc crashes after a while with "Cannot read property 'pop' of undefined" in "CheckpointTrie.Trie._updateNode" #417

Closed roderik closed 6 years ago

roderik commented 6 years ago

Not doing anything special, had a bunch of filters running on events, but I was not using the app. 

testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_getLogs
testrpc_1        | eth_getLogs
testrpc_1        | eth_getLogs
testrpc_1        | eth_getLogs
testrpc_1        | eth_getLogs
testrpc_1        | eth_getLogs
testrpc_1        | eth_getLogs
testrpc_1        | eth_getLogs
testrpc_1        | eth_getLogs
testrpc_1        | eth_getLogs
testrpc_1        | eth_getLogs
testrpc_1        | eth_getLogs
testrpc_1        | eth_getLogs
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_call
testrpc_1        | eth_getCode
testrpc_1        | /src/build/cli.node.js:68541
testrpc_1        | var Module;if(!Module)Module=(typeof Module!=="undefined"?Module:null)||{};var moduleOverrides={};for(var key in Module){if(Module.hasOwnProperty(key)){moduleOverrides[key]=Module[key]}}var ENVIRONMENT_IS_WEB=false;var ENVIRONMENT_IS_WORKER=false;var ENVIRONMENT_IS_NODE=false;var ENVIRONMENT_IS_SHELL=false;if(Module["ENVIRONMENT"]){if(Module["ENVIRONMENT"]==="WEB"){ENVIRONMENT_IS_WEB=true}else if(Module["ENVIRONMENT"]==="WORKER"){ENVIRONMENT_IS_WORKER=true}else if(Module["ENVIRONMENT"]==="NODE"){ENVIRONMENT_IS_NODE=true}else if(Module["ENVIRONMENT"]==="SHELL"){ENVIRONMENT_IS_SHELL=true}else{throw new Error("The provided Module['ENVIRONMENT'] value is not valid. It must be one of: WEB|WORKER|NODE|SHELL.")}}else{ENVIRONMENT_IS_WEB=typeof window==="object";ENVIRONMENT_IS_WORKER=typeof importScripts==="function";ENVIRONMENT_IS_NODE=typeof process==="object"&&"function"==="function"&&!ENVIRONMENT_IS_WEB&&!ENVIRONMENT_IS_WORKER;ENVIRONMENT_IS_SHELL=!ENVIRONMENT_IS_WEB&&!ENVIRONMENT_IS
testrpc_1        | 
testrpc_1        | TypeError: Cannot read property 'pop' of undefined
testrpc_1        |     at CheckpointTrie.Trie._updateNode (/src/build/cli.node.js:62182:24)
testrpc_1        |     at /src/build/cli.node.js:61929:16
testrpc_1        |     at /src/build/cli.node.js:62265:14
testrpc_1        |     at processNode (/src/build/cli.node.js:62270:23)
testrpc_1        |     at /src/build/cli.node.js:62261:5
testrpc_1        |     at /src/build/cli.node.js:62002:7
testrpc_1        |     at /src/build/cli.node.js:17600:7
testrpc_1        |     at /src/build/cli.node.js:23000:16
testrpc_1        |     at /src/build/cli.node.js:23217:32
testrpc_1        |     at /src/build/cli.node.js:22992:16

Second time today:

testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | net_version
testrpc_1        | eth_getCode
testrpc_1        | /src/build/cli.node.js:68541
testrpc_1        | var Module;if(!Module)Module=(typeof Module!=="undefined"?Module:null)||{};var moduleOverrides={};for(var key in Module){if(Module.hasOwnProperty(key)){moduleOverrides[key]=Module[key]}}var ENVIRONMENT_IS_WEB=false;var ENVIRONMENT_IS_WORKER=false;var ENVIRONMENT_IS_NODE=false;var ENVIRONMENT_IS_SHELL=false;if(Module["ENVIRONMENT"]){if(Module["ENVIRONMENT"]==="WEB"){ENVIRONMENT_IS_WEB=true}else if(Module["ENVIRONMENT"]==="WORKER"){ENVIRONMENT_IS_WORKER=true}else if(Module["ENVIRONMENT"]==="NODE"){ENVIRONMENT_IS_NODE=true}else if(Module["ENVIRONMENT"]==="SHELL"){ENVIRONMENT_IS_SHELL=true}else{throw new Error("The provided Module['ENVIRONMENT'] value is not valid. It must be one of: WEB|WORKER|NODE|SHELL.")}}else{ENVIRONMENT_IS_WEB=typeof window==="object";ENVIRONMENT_IS_WORKER=typeof importScripts==="function";ENVIRONMENT_IS_NODE=typeof process==="object"&&"function"==="function"&&!ENVIRONMENT_IS_WEB&&!ENVIRONMENT_IS_WORKER;ENVIRONMENT_IS_SHELL=!ENVIRONMENT_IS_WEB&&!ENVIRONMENT_IS
testrpc_1        | 
testrpc_1        | TypeError: Cannot read property 'get' of undefined
testrpc_1        |     at dbGet (/src/build/cli.node.js:61974:8)
testrpc_1        |     at /src/build/cli.node.js:17591:5
testrpc_1        |     at /src/build/cli.node.js:23129:20
testrpc_1        |     at iterate (/src/build/cli.node.js:23210:13)
testrpc_1        |     at /src/build/cli.node.js:23222:29
testrpc_1        |     at /src/build/cli.node.js:22992:16
testrpc_1        |     at /src/build/cli.node.js:17596:7
testrpc_1        |     at /src/build/cli.node.js:61979:9
testrpc_1        |     at dispatchError (/src/build/cli.node.js:33147:36)
testrpc_1        |     at /src/build/cli.node.js:22782:14

Always just after "eth_getCode"

benjamincburns commented 6 years ago

@roderik I pinged you on gitter, but will chat here, too. I've seen this before myself, but never on a clean branch (aka, always when I'm in the middle of making some changes). It's very intermittent for me and has been difficult for me to track down. Does it reproduce regularly for you? If so, perhaps you could share a little more detail about your environment? Or better yet, some code which makes it reproduce regularly?

roderik commented 6 years ago

Sorry chat app overload :) My Gitter is not sending notifications.

I was typing up a lot of other stuff, but maybe you are right, and maybe it is related to the Migration behaviour.

It is always after the getCode call: https://github.com/ethereum/wiki/wiki/JSON-RPC#eth_getcode

So for some reason that crashes. It might indeed be because change the contract -> which means it would change the address & change the truffle json file -> but I do not deploy and just run my filter watches with the old addresses. Meaning it tries to call getCode for something that does not exist?

421 and #422 seem to be the same error

benjamincburns commented 6 years ago

Oh sorry, I don't think this is related to migration behaviour. Your comment on 414 just caught my eye, is all.

You say "after" the getCode call - by this you mean the getCode returns successfully, and then on the next attempted RPC call it crashes? If so, which call is that one?

Is this happening at a certain point during your migration? Like, the first migration always goes off successfully, but then it usually fails after the nth or the mth?

Calling getCode for something which doesn't exist seems to work fine - you get back 0x0 as expected.

benjamincburns commented 6 years ago

From some of the other issues I've referenced (especially #340) it seems that this doesn't always occur on eth_getCode calls, and that interval mining is an aggravating factor.

@roderik are you using interval mining, by any chance?

roderik commented 6 years ago

No, no interval mining for me.

This is my docker image and startup command

  testrpc:
    image: settlemint/testrpc
    ports:
      - "8545:8545"
    command: ["node", "./build/cli.node.js", "-l", "0xfffffffffff", "-h", "0.0.0.0", "-i", "1337", "-m", '"robot robot robot robot robot robot robot robot robot robot robot robot"']
roderik commented 6 years ago

I updated the docker image to the latest version, and included #425 I will start using it this way and report back if I have more information

roderik commented 6 years ago

No joi 😢 

testrpc_1        | EthereumJS TestRPC v6.0.2 (ganache-core: 2.0.1)
testrpc_1        | 
testrpc_1        | Available Accounts
testrpc_1        | ==================
testrpc_1        | (0) 0x55e0adaa8fb6969e855d00d7ad8e2ce25de1a778
testrpc_1        | (1) 0x5d870db6dd46f8a192052b32df8755df41a397cf
testrpc_1        | (2) 0x4612a9c4faac6ec79b1edf006c7024499f0ceab9
testrpc_1        | (3) 0x45298d239a1048d5e061809d65a63da4487b2b98
testrpc_1        | (4) 0x3e6fdd560aacfda84ca5b14b0b660f717fd03ed9
testrpc_1        | (5) 0x64951d3f93f415986553c912fbede5a55faa1504
testrpc_1        | (6) 0xf1dbfcabd19d537dc9fbde6af52860018e47cd2f
testrpc_1        | (7) 0x123f0760c0cc848447b1d62670c17588d0ed6cb9
testrpc_1        | (8) 0xc8d3f52369c67689c3ea9758a11d69a0c5301c4d
testrpc_1        | (9) 0xe96df52a842b624016c8ae61f05968dd6f4c56b6
testrpc_1        | 
testrpc_1        | Private Keys
testrpc_1        | ==================
testrpc_1        | (0) 8eafa8cbf4df7d0a16472b6ff3b2222a930d03ee6e71138437407087fbffe008
testrpc_1        | (1) 720b36b9a9fc449eacd9d6f9327234e1d59d931217c913057b32f8d7485df7c1
testrpc_1        | (2) 11b9fa8c37a6fa9940aa3a282076b5932fdeb013d006e0036aa37a66b3148c41
testrpc_1        | (3) bec4b3a93fb59faa03c4bc52db211da9fe7b27ced688916873302adbf8c0622b
testrpc_1        | (4) dff6d5b583b7cf5c3d09a13e6a9ae9e7192610fc177c39dd507e31f11b4610a9
testrpc_1        | (5) 0c6a27787d01c88ce0ae6b2d6830be3cf01b9e5c51a12e966dd368018cda51b3
testrpc_1        | (6) 50e829f351c0b641b7479db2a60dd4a07d5d5e99bc7e4e8a054e97db95dbc9c2
testrpc_1        | (7) a0c29a7531957b77cba488f470e99149f38c993e23664da98caf2f61301c3eca
testrpc_1        | (8) 88f8c1b1f33264953864258b656875929c793c4c3d87ef115f0ff11732e8767f
testrpc_1        | (9) d603bfb4eba977eb9f193a95ecf8197132fd85da2f43da859b7b8228c20205e6
testrpc_1        | 
testrpc_1        | HD Wallet
testrpc_1        | ==================
testrpc_1        | Mnemonic:      "robot robot robot robot robot robot robot robot robot robot robot robot"
testrpc_1        | Base HD Path:  m/44'/60'/0'/0/{account_index}
testrpc_1        | 
testrpc_1        | Gas Limit
testrpc_1        | ==================
testrpc_1        | 17592186044415
testrpc_1        | 
testrpc_1        | Listening on 0.0.0.0:8545
testrpc_1        | eth_getBlockByNumber
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | eth_getBlockByNumber
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_accounts
testrpc_1        | eth_accounts
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x4c124e95415d97afcfa3779b39880dda1011b5a67b85108a765ab981ca832152
testrpc_1        |   Contract created: 0xe7dcac570083aea17107ea71fdb2199a49c374a3
testrpc_1        |   Gas usage: 272165
testrpc_1        |   Block Number: 1
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:16 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_newBlockFilter
testrpc_1        | eth_getFilterChanges
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_getCode
testrpc_1        | eth_uninstallFilter
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x8f65ae6ac59d23ae5770c90112ad34099fff337446d9476cece4d9de9cc69e1e
testrpc_1        |   Gas usage: 41984
testrpc_1        |   Block Number: 2
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:16 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_accounts
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x329992ef5acf773f93751d4d7e489a6c040acce0a0dfc76a4ec9226ab53bfb0b
testrpc_1        |   Contract created: 0xa0c6e87a943000ba47eb2f1a8d33367fa2eafe56
testrpc_1        |   Gas usage: 268361
testrpc_1        |   Block Number: 3
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:17 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_newBlockFilter
testrpc_1        | eth_getFilterChanges
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_getCode
testrpc_1        | eth_uninstallFilter
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0xb0a96b92105ddbcdede5559a10a6c9bcacd379e08203626cfedeefbb36793ab4
testrpc_1        |   Contract created: 0xd50d4d24cbb715b314ca6b6f77546a95fe110b0a
testrpc_1        |   Gas usage: 567374
testrpc_1        |   Block Number: 4
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:17 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_newBlockFilter
testrpc_1        | eth_getFilterChanges
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_getCode
testrpc_1        | eth_uninstallFilter
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0xf873e425dd65adbd68cde87a3895a7bd14c37ed31712a46016920d47693c7467
testrpc_1        |   Contract created: 0xcb45c5d6055284b7a047bab92c52df1a3670182d
testrpc_1        |   Gas usage: 3037502
testrpc_1        |   Block Number: 5
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:17 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_newBlockFilter
testrpc_1        | eth_getFilterChanges
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_getCode
testrpc_1        | eth_uninstallFilter
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x864a14c37a3e958081abaf4fb31a9748a7572f6f11d607f54d5c0b2ea431040e
testrpc_1        |   Gas usage: 30372
testrpc_1        |   Block Number: 6
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:17 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x87792466075272cade27967562d7f9a7ab0a218c6ad41b7b1fa4eac5a5625915
testrpc_1        |   Contract created: 0x25d11a58b8adc1cb0843b881a96b3e706c6a6800
testrpc_1        |   Gas usage: 567374
testrpc_1        |   Block Number: 7
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:17 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_newBlockFilter
testrpc_1        | eth_getFilterChanges
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_getCode
testrpc_1        | eth_uninstallFilter
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x7772ffa8f322b4f4611c798e9ded07479cb0a55ffe812c7803984e662300c720
testrpc_1        |   Contract created: 0x293e70bc5467715e64c6d40dd0b57fe964c4a8ad
testrpc_1        |   Gas usage: 3178224
testrpc_1        |   Block Number: 8
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:17 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_newBlockFilter
testrpc_1        | eth_getFilterChanges
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_getCode
testrpc_1        | eth_uninstallFilter
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0xe5c1ed14714c5e638141b4b98024e4679456d689e631811bf31f191ee8a836f3
testrpc_1        |   Gas usage: 30372
testrpc_1        |   Block Number: 9
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:17 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x5e11d0e7c0382c98db92f324c6c4c7ad443a9b2557fc50e99d8d5358e851a235
testrpc_1        |   Contract created: 0x3579ab2b18eacaef823c8db89784d97a10ba0760
testrpc_1        |   Gas usage: 942869
testrpc_1        |   Block Number: 10
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:17 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_newBlockFilter
testrpc_1        | eth_getFilterChanges
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_getCode
testrpc_1        | eth_uninstallFilter
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x32787b9f2c9381e55613626ddae5f8ba888ea5acd209e642bb569d472036844a
testrpc_1        |   Gas usage: 91904
testrpc_1        |   Block Number: 11
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:17 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x1d131ff61b64375a835eb97bfea0b974accd46242137944a32951bdb7fd3eb66
testrpc_1        |   Contract created: 0x775e11a2c8166fa50908682c0e3bf0be72da7879
testrpc_1        |   Gas usage: 817858
testrpc_1        |   Block Number: 12
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:17 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_newBlockFilter
testrpc_1        | eth_getFilterChanges
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_getCode
testrpc_1        | eth_uninstallFilter
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0xe47423ee008785be3508e4ef2686d02bfa245b28ce7e24ea2ea2085bdb7311ef
testrpc_1        |   Contract created: 0x528a10550c99c1c23c3b11107bbd6b2244949fb1
testrpc_1        |   Gas usage: 817858
testrpc_1        |   Block Number: 13
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:17 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_newBlockFilter
testrpc_1        | eth_getFilterChanges
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_getCode
testrpc_1        | eth_uninstallFilter
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x464d7c4cb3b6876d31686e4544568dddd006aa03fd339752d177fa6f3aa8a6a3
testrpc_1        |   Contract created: 0x953055ee5cdd626adc61ff7a362c6139c56fb127
testrpc_1        |   Gas usage: 817858
testrpc_1        |   Block Number: 14
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:17 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_newBlockFilter
testrpc_1        | eth_getFilterChanges
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_getCode
testrpc_1        | eth_uninstallFilter
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0xa05029dcc422ee165c9ff0a71995c56d39bd37c82a2388ab98ec5f0f42d61053
testrpc_1        |   Gas usage: 26984
testrpc_1        |   Block Number: 15
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:17 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_accounts
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0xa1245f64aaa91bb9e51e951b4c71e19976cd8c8288de563acc5bb934aef59f32
testrpc_1        |   Gas usage: 106840
testrpc_1        |   Block Number: 16
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:17 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0xe2ffe6c14f8627ae6a70cf08dac3fd3446287707fc1c8df5a65fcee627fb6bdc
testrpc_1        |   Gas usage: 106840
testrpc_1        |   Block Number: 17
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:17 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x0f65f0576911d0616331ef89205f981992b3cc49aa54dbb71e35951b1116c976
testrpc_1        |   Gas usage: 106840
testrpc_1        |   Block Number: 18
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:17 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0xfc8bbcc2f55d933badf0a84a841b1e19552f02f7ce32e048d25c519540c74d47
testrpc_1        |   Gas usage: 91904
testrpc_1        |   Block Number: 19
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:18 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x5982e43c18b3417bef52ff640ea8c5b31d500f840e8f6c1f99061c15207b3cc7
testrpc_1        |   Gas usage: 91904
testrpc_1        |   Block Number: 20
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:18 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0xd952e931c8b14e5345366098f51c8ca506cec898abac041a7ccbac5d0ab86acd
testrpc_1        |   Gas usage: 91904
testrpc_1        |   Block Number: 21
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:18 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0xc6f98e595cb4586daefa75cff8ffe4fa0527c78d395572dec0dee7be9d551ac8
testrpc_1        |   Gas usage: 91840
testrpc_1        |   Block Number: 22
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:18 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x107cdb66a605bf260079dfdcd0b1d5817c84e89691671dbad8331b5fd340706b
testrpc_1        |   Gas usage: 91840
testrpc_1        |   Block Number: 23
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:18 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0xf14affda66544584f3d8c4e948a20c2385a6616420924df242909a770ac0322f
testrpc_1        |   Gas usage: 91840
testrpc_1        |   Block Number: 24
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:18 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0xe5a6aa6d6e5de831df53e0b69ccb9d10208131c05da6fc8e4f17d6ccd51ed665
testrpc_1        |   Gas usage: 91904
testrpc_1        |   Block Number: 25
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:18 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x3d4621bf4fc86aefe8080adb56c78c916a98b82a72e8812e515e4dbee6bfcf64
testrpc_1        |   Gas usage: 91904
testrpc_1        |   Block Number: 26
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:18 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x7e3991cd2501d16c17968cba235067af22f72f569eda1ca5603fe5590c0797fc
testrpc_1        |   Gas usage: 91904
testrpc_1        |   Block Number: 27
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:18 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x8a3e6869d94047c85f43158a0ffd6e5b603c3cd3ff315b0f8c9e72d117871cd7
testrpc_1        |   Gas usage: 91904
testrpc_1        |   Block Number: 28
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:18 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x6ca2ff79aae88f9427d99e1350de845fb3c9dc6d28641dc016d0d4f52262f22e
testrpc_1        |   Gas usage: 91904
testrpc_1        |   Block Number: 29
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:18 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0xa26c0272b01ce7c9260d3744e82c2d2746c1803dc9a9c642fc0bbb62499b2f42
testrpc_1        |   Gas usage: 91904
testrpc_1        |   Block Number: 30
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:18 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x6e821732ee3e130c6964f259847980a8419c01686548bf3b38350fe80d773637
testrpc_1        |   Gas usage: 26984
testrpc_1        |   Block Number: 31
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:18 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_accounts
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0xed05582ad82da2da25ecb5c3b7e24ff6aa0f91abca41181567fdf48e06bfc83b
testrpc_1        |   Gas usage: 1762351
testrpc_1        |   Block Number: 32
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:18 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0xc0a620bbba0c8c25ccfb5e687342c7339e41d683c186bc20ca5a18a70a378eb2
testrpc_1        |   Gas usage: 498552
testrpc_1        |   Block Number: 33
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:18 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x39983b9bcc92c6a26bba07e9f5299db7100941bd0150cd5fe63460df2bfc967f
testrpc_1        |   Gas usage: 163112
testrpc_1        |   Block Number: 34
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:18 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x664b3901cfc72878702183d718eceae946f2c02e01346684deee522d53992256
testrpc_1        |   Gas usage: 1867797
testrpc_1        |   Block Number: 35
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:18 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0xc189735ee81c7bf0ee98fc2b2a98989dfb39295a22058d8d0b7b8a2e2a60b937
testrpc_1        |   Gas usage: 498662
testrpc_1        |   Block Number: 36
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:18 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0x6b92642d81a2480d4efee4f400c03683dd27c92a78056aa1bf19a0d264f19f1c
testrpc_1        |   Gas usage: 163222
testrpc_1        |   Block Number: 37
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:19 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_sendTransaction
testrpc_1        | 
testrpc_1        |   Transaction: 0xb05092823731c1191ecb568725cf51c1e0adc745f62a11dfa6bdf9bc594a5423
testrpc_1        |   Gas usage: 26984
testrpc_1        |   Block Number: 38
testrpc_1        |   Block Time: Wed Nov 15 2017 09:33:19 GMT+0000 (UTC)
testrpc_1        | 
testrpc_1        | eth_getTransactionReceipt
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_getBlockByNumber
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | eth_getBlockByNumber
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | net_version
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_getCode
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | net_version
testrpc_1        | eth_getCode
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | eth_call
testrpc_1        | /src/build/cli.node.js:72295
testrpc_1        | var Module;if(!Module)Module=(typeof Module!=="undefined"?Module:null)||{};var moduleOverrides={};for(var key in Module){if(Module.hasOwnProperty(key)){moduleOverrides[key]=Module[key]}}var ENVIRONMENT_IS_WEB=false;var ENVIRONMENT_IS_WORKER=false;var ENVIRONMENT_IS_NODE=false;var ENVIRONMENT_IS_SHELL=false;if(Module["ENVIRONMENT"]){if(Module["ENVIRONMENT"]==="WEB"){ENVIRONMENT_IS_WEB=true}else if(Module["ENVIRONMENT"]==="WORKER"){ENVIRONMENT_IS_WORKER=true}else if(Module["ENVIRONMENT"]==="NODE"){ENVIRONMENT_IS_NODE=true}else if(Module["ENVIRONMENT"]==="SHELL"){ENVIRONMENT_IS_SHELL=true}else{throw new Error("The provided Module['ENVIRONMENT'] value is not valid. It must be one of: WEB|WORKER|NODE|SHELL.")}}else{ENVIRONMENT_IS_WEB=typeof window==="object";ENVIRONMENT_IS_WORKER=typeof importScripts==="function";ENVIRONMENT_IS_NODE=typeof process==="object"&&"function"==="function"&&!ENVIRONMENT_IS_WEB&&!ENVIRONMENT_IS_WORKER;ENVIRONMENT_IS_SHELL=!ENVIRONMENT_IS_WEB&&!ENVIRONMENT_IS
testrpc_1        | 
testrpc_1        | TypeError: Cannot read property 'pop' of undefined
testrpc_1        |     at CheckpointTrie.Trie._updateNode (/src/build/cli.node.js:65936:24)
testrpc_1        |     at /src/build/webpack:/node_modules/merkle-patricia-tree/baseTrie.js:107:10
testrpc_1        |     at /src/build/webpack:/node_modules/merkle-patricia-tree/baseTrie.js:443:6
testrpc_1        |     at processNode (/src/build/webpack:/node_modules/merkle-patricia-tree/baseTrie.js:448:1)
testrpc_1        |     at /src/build/webpack:/node_modules/merkle-patricia-tree/baseTrie.js:439:1
testrpc_1        |     at /src/build/webpack:/node_modules/merkle-patricia-tree/baseTrie.js:180:6
testrpc_1        |     at /src/build/webpack:/node_modules/merkle-patricia-tree/util.js:76:1
testrpc_1        |     at /src/build/webpack:/node_modules/merkle-patricia-tree/node_modules/async/lib/async.js:53:1
testrpc_1        |     at /src/build/webpack:/node_modules/merkle-patricia-tree/node_modules/async/lib/async.js:270:22
testrpc_1        |     at /src/build/webpack:/node_modules/merkle-patricia-tree/node_modules/async/lib/async.js:45:1
mintdapi_testrpc_1 exited with code 7

Same code on v5 and a recent Parity node work fine btw

LiorRabin commented 6 years ago

any way to workaround this?

benjamincburns commented 6 years ago

Sorry guys, this one is definitely on my list. Will take me a little while to circle 'round to it, however.

benjamincburns commented 6 years ago

@roderik one more question for you - can you please post your command line args? For instance, are you using the forking feature?

roderik commented 6 years ago 
  testrpc:
    image: settlemint/testrpc:latest
    ports:
      - "8545:8545"
    command: ["node", "./build/cli.node.js", "-l", "0xfffffffffff", "-h", "0.0.0.0", "-i", "1337", "-m", 'robot robot robot robot robot robot robot robot robot robot robot robot']
benjamincburns commented 6 years ago

Nice mnemonic ;-)

q3k commented 6 years ago

Disclaimer: I am not a JS programmer, treat everything below with a grain of salt and with your red herring detector turned up to 11.

I've taken a quick look at this (also been bitten by the "get on undefined" bug), and it seems like this is a race condition between modifying Trie._getDBs (via checkpoint/commit) and accessing it in Trie._getRaw. Not sure if it's a bug in the merkle-patricie-tree module or how it's being called by ganache-core/cli. My first guess is that checkpoint being synchronous and not taking .sem when modifying ._getDBs is a possible culprit.

Investigating this is hopelessly painful, not only because it's a heisenbugish race (that becomes more difficult to trigger with debug log statements added) but it's also smack middle of a callback hell.

benjamincburns commented 6 years ago

@q3k sorry I didn't respond sooner. I totally agree w/ the sentiment on the "heisenbugish race" you mention. :-(

Your thoughts on the cause echo my own, though I have a feeling that they're more developed w.r.t. the actual root cause. However I think it's telling that the issue manifests in a couple of different ways (see the traces in @roderik's initial report).

benjamincburns commented 6 years ago

I think this and #359 are related, but I can't be certain so I won't call this a dupe just yet.

benjamincburns commented 6 years ago

@q3k, @roderik, and others trying to debug this: just a heads up that we're in the process of publishing a bounty for a reliable automated repro of this over on #450. It's not live yet, but I suspect it will be later today. Wanted to notify here first given the work the people in this thread have already done to troubleshoot this!

Edit: it looks like this bounty will go live sometime tomorrow, US time.

benjamincburns commented 6 years ago

Thanks to @0xNPE, we now have a reproduction of this issue merged to the develop branch (per PR trufflesuite/ganache-core#41). As you can see above, @owocki and I are opening a second bounty for the actual fix over in #453. Submissions welcome :-D

benjamincburns commented 6 years ago

So there's a simple fix to this issue which I've been avoiding making because it feels a little like sweeping it under the rug. That fix is to process each request serially. I've made this change in trufflesuite/ganache-core#53, and this seems to eliminate this problem, and various others, entirely.

I've just published ganache-cli@7.0.0-beta.0 which has this change, as well as support for websockets, and numerous other fixes. You can get it by doing npm install -g ganache-cli@beta.

Closing this case for now, however I'll still keep the bounty in #453 open, as I'd much rather have an appropriate lower-level fix which doesn't require this sort of serial request processing.

roderik commented 6 years ago

Awesome!

holgerd77 commented 6 years ago

Hi, for information: just released ethereumjs/merkle-patricia-tree v2.3.1 with the fix from @federicobond https://github.com/ethereumjs/merkle-patricia-tree/pull/28 on npm.

Lost a bit track how much of this bug is fixed by this and what workarounds you already implemented. Feel free to get in contact or open new PRs if there are further or still ongoing questions or issues.