Skip to content
This repository has been archived by the owner on Jan 21, 2022. It is now read-only.

Error: LevelUpArrayAdapter named 'blockLogs' index out of range #346

Closed
jtremback opened this issue Jul 11, 2017 · 43 comments
Closed

Error: LevelUpArrayAdapter named 'blockLogs' index out of range #346

jtremback opened this issue Jul 11, 2017 · 43 comments

Comments

@jtremback
Copy link

jtremback commented Jul 11, 2017

I get this error when running tests. It goes away for a little while after restarting testrpc.

I am on a MacBook with node 8.1.3, with testrpc 4.0.1

If you want to reproduce this, clone https://github.com/jtremback/guac and run npm run test a few times.

@cryptofuture
Copy link

Have the same issue.

LevelUpArrayAdapter named 'blockLogs' index out of range: index 11; length: 11

I happens after truffle test goes to the next test, on testrpc reverting to snapshot #1
I can run tests separately without any problem, but when I run all three one after etch other, all is bloody red.

@alex-miller-0
Copy link

Same issue here between tests. Individual tests are fine.

@jtremback
Copy link
Author

I thought it was because of the snapshotting at first, but I tried it without and it still seemed to be happening. But maybe I was mistaken. Has anyone experienced this without snapshotting?

@mikeshultz
Copy link

mikeshultz commented Jul 17, 2017

Version:

EthereumJS TestRPC v4.0.1 (ganache-core: 1.0.1)

Confirmed on 4.0.0 and 3.9.2. Tried to go back further, but... npm. Perhaps an upgraded dependency?

Snippet from debug logs:

SHA3
DUP2
SWAP1
SSTORE
JUMPDEST
JUMPDEST
POP
POP
JUMP
JUMPDEST
STOP

  Transaction: 0x7d677dca77f851068c6cb85fbfdcfb3a0c4f2274218c4e8f54332a1ceb1e98c3
  Gas usage: 43544
  Block Number: 15
  Block Time: Sun Jul 16 2017 22:29:28 GMT-0600 (MDT)

eth_getTransactionReceipt
Error: LevelUpArrayAdapter named 'blockLogs' index out of range: index 15; length: 15
    at /usr/local/lib/node_modules/ethereumjs-testrpc/build/cli.node.js:97358:23
    at /usr/local/lib/node_modules/ethereumjs-testrpc/build/cli.node.js:97332:5
    at /usr/local/lib/node_modules/ethereumjs-testrpc/build/cli.node.js:97778:12
    at /usr/local/lib/node_modules/ethereumjs-testrpc/build/cli.node.js:97543:19
    at /usr/local/lib/node_modules/ethereumjs-testrpc/build/cli.node.js:100234:7
    at _combinedTickCallback (internal/process/next_tick.js:95:7)
    at process._tickCallback (internal/process/next_tick.js:161:9)
eth_call
eth_getLogs
eth_blockNumber
eth_call
eth_call
eth_getLogs
eth_getFilterChanges
evm_revert
Reverting to snapshot #1
evm_snapshot
Saved snapshot #1
eth_blockNumber

@mikeshultz
Copy link

mikeshultz commented Jul 17, 2017

errr... scratch that. Once I removed /usr/local/lib/npm_modules and started from scratch, 3.9.2 did not show this error.

EDIT: Nope, got it again with 3.9.2... odd

@Ankarrr
Copy link

Ankarrr commented Jul 18, 2017

Im using TestRPC v4.0.1. I also see the error log when I run test.

But I restart TestRPC when I see the error log every time and then it will work fine...

@mikeshultz
Copy link

Restarting does not help with me. I am also seeing this error in the docker container, so it's not just my local system. It appears as though it's being thrown during an RPC InvalidResponse error.

Though the error does seem intermittent, since 1 out of every 50 seems to work in my case. The error seems to be thrown every time after a call to eth_getTransactionReceipt. I haven't seen any other calls cause it.

mikeshultz referenced this issue in trufflesuite/ganache Jul 20, 2017
once-synchronous data reads/writes asynchronous, and debugging issues
that came out of bad refactoring. One thing to note here is that the
data structure changed a bit: `data.blockHashes` points to the *block
index*, which is the array index of the block. This index doesn’t
necessarily match up with the block number.
@travs
Copy link

travs commented Jul 21, 2017

I'm also getting this on 4.0.1 and 3.9.2.

Reproduce:

@patrickgorrell
Copy link

patrickgorrell commented Jul 25, 2017

Started getting a weird issue today when I ran a clean install and not sure if it’s a known issue from the popup logs.

popup.js:80367 Error: LevelUpArrayAdapter named 'blocks' index out of range: index 4068832; length: 7
    at /Users/.nvm/versions/node/v8.1.3/lib/node_modules/ethereumjs-testrpc/build/cli.node.js:97358:23
    at /Users/.nvm/versions/node/v8.1.3/lib/node_modules/ethereumjs-testrpc/build/cli.node.js:97332:5
    at /Users/.nvm/versions/node/v8.1.3/lib/node_modules/ethereumjs-testrpc/build/cli.node.js:97778:12
    at /Users/.nvm/versions/node/v8.1.3/lib/node_modules/ethereumjs-testrpc/build/cli.node.js:97543:19
    at /Users/.nvm/versions/node/v8.1.3/lib/node_modules/ethereumjs-testrpc/build/cli.node.js:100234:7
    at _combinedTickCallback (internal/process/next_tick.js:95:7)
    at process._tickCallback (internal/process/next_tick.js:161:9)

truffle / testrpc on initial load on Node 8.1.3, Testrpc, Mac OSX Chrome Latest.

@jdkanani
Copy link

Same issue.

@patrickgorrell
Copy link

patrickgorrell commented Jul 25, 2017

I fixed it for now... Here is how I did it.

I was using Metamask w/ truffle. I was able to resolve the issue but first:

$ npm uninstall -g ethereumjs-testrpc
$ npm install -g ethereumjs-testrpc
$testrpc

Go to chrome -> Right click on metamask -> Manage Extension -> scroll to metamask -> click "Bakcground Image" blue link -> refresh the inspector that is opened (cmd+r on mac).

I was logged out of Metamask. I logged back in and the problem was resolved.

See: https://github.com/MetaMask/faq/blob/master/LOGS.md#background-logs-chrome

Background Logs in chrome -> Refresh the inspector

@ghanshaw
Copy link

I also get the same problem when I use testrpc and MetaMask. When I try to send transactions, the popup hangs and I see the error in the console. But sometimes, the popup hangs and I won't see any error in the console. Not sure how I should proceed--I can't even reliably get the same error message...

@mikeshultz
Copy link

mikeshultz commented Jul 30, 2017

Every time the error occurs, this is what I'm getting from some debug statements. For me, it always seems to happen during the RPC call eth_call, but not for every one of them. At some point when it occurs once, it happens with every subsequent call. Because of how intermittent this is, it feels very much like a race condition.

server.request.body: {"jsonrpc":"2.0","id":54,"method":"eth_getTransactionReceipt","params":["0x0eb8d1e056b1e84fb00b6edd0c70ccb6261f21bc9e440b82686326fed2a302ef"]}
LevelUpArrayAdapter.get(8)
LevelUpArrayAdapter.get(8)
LevelUpArrayAdapter.length == 9
LevelUpArrayAdapter.length == 9
{ id: 54,
  jsonrpc: '2.0',
  result: 
   { transactionHash: '0x0eb8d1e056b1e84fb00b6edd0c70ccb6261f21bc9e440b82686326fed2a302ef',
     transactionIndex: '0x00',
     blockHash: '0xcbffddd5f238c860133c3a15e219264bd1b4141f1446cb7d863f21e7a12e7c4d',
     blockNumber: '0x09',
     gasUsed: '0x030488',
     cumulativeGasUsed: '0x030488',
     contractAddress: null,
     logs: [] } }
server.request.body: {"jsonrpc":"2.0","id":55,"method":"eth_blockNumber","params":[]}
BlockchainDouble.getHeight(): 8
{ id: 55, jsonrpc: '2.0', result: '0x08' }
server.request.body: {"jsonrpc":"2.0","id":56,"method":"eth_call","params":[{"from":"0x54942de713d679efd97b8b3c5203e190b9b92f71","gas":"0x47e7c4","gasPrice":"0x174876e800","to":"0x64b9889865a89c40ff049fe5cec1f1568f46c5db","data":"0x32648e0900000000000000000000000049fb5e93463322cdde82f2ba1860a7df25d9f4b7"},"latest"]}
LevelUpArrayAdapter.get(9)
LevelUpArrayAdapter.get(9)
LevelUpArrayAdapter.length == 9
{ id: 56,
  jsonrpc: '2.0',
  result: undefined,
  error: 
   { message: 'Error: LevelUpArrayAdapter named \'blocks\' index out of range: index 9; length: 9\n    at /home/mike/dev/ganache-core/lib/database/leveluparrayadapter.js:52:23\n    at /home/mike/dev/ganache-core/lib/database/leveluparrayadapter.js:25:5\n    at /home/mike/dev/ganache-core/node_modules/level-sublevel/shell.js:102:12\n    at /home/mike/dev/ganache-core/node_modules/level-sublevel/nut.js:122:19\n    at /home/mike/dev/ganache-core/node_modules/cachedown/index.js:53:7\n    at _combinedTickCallback (internal/process/next_tick.js:131:7)\n    at process._tickDomainCallback (internal/process/next_tick.js:218:9)',
     code: -32000 } }

I'll continue to dig further but maybe someone more familiar with the codebase would recognize a bug faster than I.

EDIT: If I had to guess, this is probably a problem in web3-provider-engine.

@patrickgorrell
Copy link

@ghanshaw did you try my solution? I was having the exact same problem...

@yahortsaryk
Copy link

I had the same problem. @Pvader 's steps helped me to get Metamask working, thanks

@jtremback
Copy link
Author

Tried uninstalling and reinstalling, but it still happens.

@arpankotecha
Copy link

I'm having the same issue as well with TestRPC v4.0.1. It just started all of a sudden. Been running it without issues for a month. Not sure what might have triggered this. I've tried uninstall and reinstalling but that didn't help. I don't have metamask installed so that seems unrelated. Here's my trace.

 Error: Error: LevelUpArrayAdapter named 'blocks' index out of range: index 231; length: 231
at /usr/local/lib/node_modules/ethereumjs-testrpc/build/cli.node.js:97358:23
at /usr/local/lib/node_modules/ethereumjs-testrpc/build/cli.node.js:97332:5
at /usr/local/lib/node_modules/ethereumjs-testrpc/build/cli.node.js:97778:12
at /usr/local/lib/node_modules/ethereumjs-testrpc/build/cli.node.js:97543:19
at /usr/local/lib/node_modules/ethereumjs-testrpc/build/cli.node.js:100234:7
at _combinedTickCallback (internal/process/next_tick.js:95:7)
at process._tickCallback (internal/process/next_tick.js:161:9)

@patrickgorrell
Copy link

@arpankotecha did you try my solution above? I fixed that same issue as stated above.

@patrickgorrell
Copy link

@jttemback try my steps above. It should work.

@arpankotecha
Copy link

Hi @Pvader I tried the first half of the solution (kill testrpc, uninstall testrpc, install testrpc, start testrpc). The second part did not apply as I don't have metamask. Unfortunately the problem still persisted. I also upgraded both testrpc and truffle to the latest version. No luck.

@jtremback
Copy link
Author

@Pvader Also not using metamask, also reinstalled testrpc, still not working.

@arpankotecha
Copy link

arpankotecha commented Aug 8, 2017

Looks like a line in my truffle test is corrupting the db. I've gotten around it by supplying a path to the db on the command line:
mkdir logs; testrpc --db logs

When i encounter the error, I rm -r logs; mkdir logs and restart testrpc. Ofcourse this only works after I've commented out the offending line of code in my test:
assert.strictEqual(price, initiaPrice, "")

Not sure why that would corrupt the db. But my tests pass now and allows me to proceed with the project.

@mikeshultz
Copy link

mikeshultz commented Aug 8, 2017

@arpankotecha wow, nice find. For me, creating a new db directory allows my tests to go through just fine. Deleting and recreating that directory does not prevent all of my subsequent tests from failing with this error. So if I just create a new directory in /tmp every time I run my tests, they pass.

How odd.

EDIT: That appears to have only worked temporarily.

@dpilch
Copy link

dpilch commented Aug 8, 2017

I had this issue when I forgot to return promises in my test cases. Haven't run into the issue again after that.

@mikeshultz
Copy link

No matter how bad you screw up your tests, this is still throwing an internal testrpc error that appears to be caused during eth_call.

Right before the error on eth_call, this is what I'm seeing from internal calls:

eth_getBlockByNumber: latest(9)
eth_blockNumber: 8
eth_getBlockByNumber: latest(9)

The 9 is coming from block.header.number in GethApiDouble.eth_getBlockByNumber, not !blocks!length in the DB. It appears there's an evm_revert call before all this goes down, which does properly update !blocks!length but perhaps the next created block causes that length count and the actual block number to become out of sync?

Though in the DB on disk, it appears okay.

$ ls -lah /tmp/wat/\!blocks*
-rw-r--r-- 1 mike mike 1.3K Aug  8 13:22 /tmp/wat/!blocks!0
-rw-r--r-- 1 mike mike 2.4K Aug  8 13:22 /tmp/wat/!blocks!1
-rw-r--r-- 1 mike mike 1.6K Aug  8 13:22 /tmp/wat/!blocks!2
-rw-r--r-- 1 mike mike 7.8K Aug  8 13:22 /tmp/wat/!blocks!3
-rw-r--r-- 1 mike mike 7.8K Aug  8 13:22 /tmp/wat/!blocks!4
-rw-r--r-- 1 mike mike  13K Aug  8 13:22 /tmp/wat/!blocks!5
-rw-r--r-- 1 mike mike 1.6K Aug  8 13:22 /tmp/wat/!blocks!6
-rw-r--r-- 1 mike mike 1.6K Aug  8 13:22 /tmp/wat/!blocks!7
-rw-r--r-- 1 mike mike    1 Aug  8 13:22 /tmp/wat/!blocks!length
mike@patty:~/dev/ganache-core$ cat /tmp/wat/\!blocks\!length 
8
$ cat /tmp/wat/\!blocks\!7
{"header":{"parentHash":"0x14e0c45523711b8e50f5c1c02e65c6db572651609e3edc7202ca68486247ef29","uncleHash":"0x1dcc4de8dec75d7aab85b567b6ccd41ad312451b948a7413f0a142fd40d49347","coinbase":"0x0000000000000000000000000000000000000000","stateRoot":"0x9bd60b4e8d0c2a59ef9f76a518baae81463e0bf911c644d62fe740c7e427f455","transactionsTrie":"0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421","receiptTrie":"0x56e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421","bloom":"0x00000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000","difficulty":"0x","number":"0x07","gasLimit":"0x47e7c4","gasUsed":"0x425b","timestamp":"0x598a1319","extraData":"0x","mixHash":"0x0000000000000000000000000000000000000000000000000000000000000000","nonce":"0x"},"transactions":[{"nonce":"0x06","gasPrice":"0x174876e800","gasLimit":"0x47e7c4","to":"0x3abd0d49d2ed14b4b9141b15cdbdcdf03d9f3521","value":"0x","data":"0x16e85b2e","v":"0x1c","r":"0x","s":"0x","from":"0x04319405a70fbb5a3b30dd7917bb59796616f7ad","hash":"0x7d7002d7edbc3b1c5e5b51e624c25da912c8bcb8578b86b4e5bcae221630cc4b"}],"uncleHeaders":[]}

I tried updating BlockchainDouble.getHeight to use BlockchainDouble.latestBlock instead of just using the length stored in the DB, but no joy. Still not clear to me exactly where this error is coming from and the traceback is not really of any help.

I wonder if CacheDOWN is the one out of sync but I haven't yet dug into it. Or maybe I'm way off base, since node is not my strong point.

@prozacchiwawa
Copy link

I was getting this bug, but I think I figured out how to fix it. The printing of the transaction receipt after sendTransaction appeared to be happening after an evm_revert when a javascript contract test finished and another one started. My proposed fix is to add evm_revert, evm_snapshot and eth_getLogs (which is fired from printTransactionReceipt) to the set of sequenced operations on a blockchain instance. Anyone interested in testing this? https://github.com/prozacchiwawa/ganache-core/tree/20170812-truffle-test-sequence

@mikeshultz
Copy link

mikeshultz commented Aug 12, 2017

@prozacchiwawa Most of the "Forking" tests are failing with this:

 TypeError: this._findPath is not a function
  at ForkedStorageTrie.keyExists (lib/utils/forkedstoragetrie.js:30:8)
  at lib/utils/forkedblockchain.js:269:20
  at ForkedBlockchain.BlockchainDouble.getEffectiveBlockNumber (lib/blockchain_double.js:133:14)
  at ForkedBlockchain.getCode (lib/utils/forkedblockchain.js:266:8)
  at StateManager.getCode (lib/statemanager.js:208:19)
  at GethApiDouble.eth_getCode (lib/subproviders/geth_api_double.js:127:14)
  at GethApiDouble.handleRequest (lib/subproviders/geth_api_double.js:70:10)
  at GethDefaults.handleRequest (lib/subproviders/gethdefaults.js:17:12)
  at DelayedBlockFilter.handleRequest (lib/subproviders/delayedblockfilter.js:27:3)
  at ReactiveBlockTracker.handleRequest (lib/subproviders/reactiveblocktracker.js:25:12)
  at RequestFunnel.handleRequest (lib/subproviders/requestfunnel.js:35:12)

I was not able to run any of my contract tests against it, because it appears the test accounts were not created with funds(probably related to the above).

@prozacchiwawa
Copy link

I think the tests are broken in master in general (same failures from master clone, npm install && npm test). I'll rebranch from a release tag, to get a clearer picture. I hot patched this into my tree, and it seemed to solve my problem, but admittedly didn't need to generate accounts as I have a set of pregenerated ones I was using in my tests. Thanks for trying it out.

@mikeshultz
Copy link

@prozacchiwawa Yeah, sorry. It appears all of those errors are not related to your changes. I get those same errors from a clean master branch of ganache-core from a week or two ago. Let me see if I can get a working branch and then I'll test your changes.

@prozacchiwawa
Copy link

Remade my branch against release: https://github.com/prozacchiwawa/ganache-core/tree/20170812-truffle-test-sequence-release . All tests seem to be passing in this branch.

@mikeshultz
Copy link

That find path is easy enough to fix but I'm still not getting account balances when I start it. How are you building that, anyway?

I'll try your branch in a minute.

@prozacchiwawa
Copy link

prozacchiwawa commented Aug 12, 2017 via email

@mikeshultz
Copy link

This has got to be the most frustrating codebase I've stuck my nose into but I'm getting nowhere. I can't get this to build because of some failing dependency, and I'm still having an account balance issue. In the state manager, accounts show a balance:

> server.provider.manager.state.accounts['0xabc...'].account.balance
<Buffer 00 00 00 00 00 00 00 05 6b c7 5e 2d 63 10 00 00>

But not through getBalance:

> server.provider.manager.state.blockchain.getBalance("0xabc...", 'latest',  function(err, bal) { console.log(bal); })
<Buffer >

It's a fresh source tree, so maybe this is a separate bug in master, or my system is a mess. I wasn't seeing this the other day when I was testing. I'll try again tomorrow with a fresh node install.

@edwmamedov
Copy link

This bug is real stopper, @tcoulter could you please fix it ASAP.
Thanks.

@tcoulter
Copy link
Contributor

We're taking a look at this. Will add more info when we've locked it down.

@tcoulter
Copy link
Contributor

This has been fixed in ganache-core (the code that powers the testrpc). Will go out with the next TestRPC release, which should be in the next couple days.

Thanks all for the reports!

@Meekohi
Copy link

Meekohi commented Oct 7, 2017

I am still seeing this on EthereumJS TestRPC v4.1.3 (ganache-core: 1.1.3)

@jackcasey
Copy link

I just got the error on the new version too :

$ testrpc --version
EthereumJS TestRPC v4.1.3 (ganache-core: 1.1.3)

@tomericco
Copy link

Make sure that you wait for your promises.
If you are using async/await syntax, make sure every call to the contract is prefixed by await

@benjamincburns
Copy link
Contributor

@Meekohi & @jackcasey if you are still seeing this issue after employing @tomericco's advice, please post here with repro steps and we may reopen the issue.

@mgraczyk
Copy link

@benjamincburns Easy repro:

Run this

$ ./node_modules/.bin/ganache-cli
Ganache CLI v6.1.0 (ganache-core: 2.1.0)

Then in another shell, run

curl localhost:8545 -X POST -d '{"method": "eth_getBalance", "params": ["", 1]}'

@mgraczyk
Copy link

mgraczyk commented May 11, 2018

If you'd like a repo to compare with geth, try:

Geth:

$ curl https://mainnet.infura.io:8545 -X POST -d '{"method": "eth_getBalance", "params": ["0x0000000000000000000000000000000000000000", "0x1111111111111111"], "id": 0}'
{"jsonrpc":"2.0","id":0,"result":"\u003cnil\u003e"}

ganache-cli

$ curl localhost:8545 -X POST -d '{"method": "eth_getBalance", "params": ["0x0000000000000000000000000000000000000000", "0x1111111111111111"], "id": 0}'
{"id":0,"error":{"message":"LevelUpArrayAdapter named 'blocks' index out of range: index 1; length: 1","code":-32000,"data":{"stack":"Error: LevelUpArrayAdapter named 'blocks' index out of range: index 1; length: 1\n    at <>/node_modules/ganache-cli/build/cli.node.js:2:778143\n    at <>/node_modules/ganache-cli/build/cli.node.js:2:777808\n
at <>/node_modules/ganache-cli/build/cli.node.js:2:774000\n    at <>/node_modules/ganache-cli/build/cli.node.js:2:776505\n    at <>/node_modules/ganache-cli/build/cli.node.js:2:748516\n    at process._tickCallback (internal/process/next_tick.js:112:11)","name":"Error"}}}

@tudor-pop
Copy link

had the issue because I was calling the right method on the wrong contract...realised after 2 hours of not knowing what's going on

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests