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 occasionally crashes with "Key not found" db error #359

Closed cgewecke closed 6 years ago

cgewecke commented 7 years ago

Testrpc occasionally crashes with the error below.

From aragon-core Travis build #273

1) Contract: Token sales "before all" hook: prepare suite:
     Uncaught NotFoundError: Key not found in database
      at node_modules/ethereumjs-testrpc/build/lib.node.js:85786:18
      at node_modules/ethereumjs-testrpc/build/lib.node.js:85551:19
      at node_modules/ethereumjs-testrpc/build/lib.node.js:88248:21
      at ReadFileContext.callback (node_modules/ethereumjs-testrpc/build/lib.node.js:87717:14)
      at FSReqWrap.readFileAfterOpen [as oncomplete] (fs.js:366:13)

That's just an example - have also seen it on Open-Zeppelin which installs with yarn . . .

Steps to Reproduce (for bugs)

There is no discernible pattern. It does not prefer one test over another, the beginning of the suite over the end, the beforeEach over the unit. Nothing.

[Edit - Oct 9, 2017] Seems to occur on the seam between contract suites and may be linked to Truffle's roll back of the chain state there. See jimkberry and others' notes below. Frequency of occurrence ~ 10%.

Your Environment

edwmamedov commented 7 years ago

Have the same issue in truffle tests, same version

` 1) Contract: Test withdraw() method "before all" hook: prepare suite: Uncaught NotFoundError: Key not found in database at /Users/eduard/ws/ethereum/solidity-auction-contract/node_modules/ethereumjs-testrpc/build/cli.node.js:97777:18 at /Users/eduard/ws/ethereum/solidity-auction-contract/node_modules/ethereumjs-testrpc/build/cli.node.js:97542:19 at /Users/eduard/ws/ethereum/solidity-auction-contract/node_modules/ethereumjs-testrpc/build/cli.node.js:100239:21 at ReadFileContext.callback (/Users/eduard/ws/ethereum/solidity-auction-contract/node_modules/ethereumjs-testrpc/build/cli.node.js:99708:14) at FSReqWrap.readFileAfterOpen [as oncomplete] (fs.js:366:13) Error: NotFoundError: Key not found in database

`

habdelra commented 7 years ago

I'm seeing this as well. I'm using the latest version of testrpc 4.1.1

k06a commented 6 years ago

Version: EthereumJS TestRPC v4.1.3 (ganache-core: 1.1.3)

net_version
eth_sendTransaction

  Transaction: 0x4bc2cba89d3eb10e77023b4e8957e089a7a0cda7a797bf1d76e2608735f37905
  Gas usage: 6000000
  Block Number: 221
  Block Time: Mon Sep 18 2017 23:16:10 GMT+0300 (MSK)
  Runtime Error: invalid opcode

evm_revert
Reverting to snapshot #23
NotFoundError: Key not found in database
    at /usr/local/lib/node_modules/ethereumjs-testrpc/build/cli.node.js:78911:18
    at /usr/local/lib/node_modules/ethereumjs-testrpc/build/cli.node.js:78676:19
    at /usr/local/lib/node_modules/ethereumjs-testrpc/build/cli.node.js:80821:21
    at ReadFileContext.callback (/usr/local/lib/node_modules/ethereumjs-testrpc/build/cli.node.js:80718:14)
    at FSReqWrap.readFileAfterOpen [as oncomplete] (fs.js:421:13)
jimkberry commented 6 years ago

Version EthereumJS TestRPC v4.1.1 (ganache-core: 1.1.2) (I need to upgrade)

I also am running into this. I have a couple of questions for the folks who have already reported it:

It is my understanding that it might be possible for this to be the result of something like a call to testrpc that references a particular block not getting waited-for, and an evm_revert happening (that makes that block no longer there) before the call is handled.

Meekohi commented 6 years ago

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

dwalintukan commented 6 years ago

I'm receiving this as well about 5% of the time. 4.1.3

sohkai commented 6 years ago

I'm seeing this as well, on EthereumJS TestRPC v6.0.1 (ganache-core: 2.0.0).

@jimkberry @cgewecke An interesting workaround I found while running into this issue was to reorganize some of my tests. Initially I had left all the tests for asserting failures to the end, with something like this:

Reverter.sol:

contract Reverter {
    function revert() external {
        require(false);
    }
}

---------------

reverter.js:

async function assetRevert(block) {
    try {
        await block();
    } catch (e) {
        return assert.isAbove(e.message.search("revert"), -1);
    }
}

it("should revert") {
    const reverter = await Reverter.new();
    assertRevert(async() => { await reverter.revert(); });
}

Doing this either gives me the NotFoundKey error or this:

<project>/node_modules/ethereumjs-testrpc/build/cli.node.js:68497
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"&&!ENVIRON
MENT_IS_WEB&&!ENVIRONMEN

TypeError: Cannot read property 'toJSON' of null
    at <project>/node_modules/ethereumjs-testrpc/build/cli.node.js:85028:24
    at <project>/node_modules/ethereumjs-testrpc/build/cli.node.js:21795:5
    at <project>/node_modules/ethereumjs-testrpc/build/cli.node.js:82948:7
    at <project>/node_modules/ethereumjs-testrpc/build/cli.node.js:7542:16
    at <project>/node_modules/ethereumjs-testrpc/build/cli.node.js:7759:32
    at <project>/node_modules/ethereumjs-testrpc/build/cli.node.js:7534:16
    at <project>/node_modules/ethereumjs-testrpc/build/cli.node.js:82943:9
    at Object.decode (<project>/node_modules/ethereumjs-testrpc/build/cli.node.js:43920:5)
    at <project>/node_modules/ethereumjs-testrpc/build/cli.node.js:82940:20
    at <project>/node_modules/ethereumjs-testrpc/build/cli.node.js:7671:20

On any test files run after (100% of the time).

However, when I move those failure assertion tests to the start of the test, the other test files run fine and everything works (afaik 100% of the time).

I should note that I'm also running evm_increaseTime and evm_mine on the beforeEach() hook of each test. Not sure if this affects anything though.

I tried to make a simple example repo that experiences this issue and can be solved via the workaround, but I've yet to make a really simple example fail in this way.

sohkai commented 6 years ago

Actually @jimkberry, @cgewecke, I realized my tests were messed up in the above scenario and it was due to "un-waited-for" promises.

I forgot to wait for the returned promises from the assertRevert() call above, probably deferring their actual execution to until the other tests started running with new EVM contexts.

Making sure that I wait for them makes the tests run without a problem in their original ordering.

benjamincburns commented 6 years ago

@sohkai Even still, TestRPC shouldn't crash because of that. Are you able to submit a minimal example so that I can debug it more thoroughly? I have a feeling this is a manifestation of #234.

benjamincburns commented 6 years ago

Doh, sorry @sohkai - too many context switches - I scrolled up and saw your example! Thanks for doing that!

karianne commented 6 years ago

I also experience this problem.

mickys commented 6 years ago

I'm been having the same issues while running my 300+ test suite ( split into about 30 separate js test case files ) on a debian 9.2 linux machine that has node 8.9.2.

Package versions: EthereumJS TestRPC v4.1.3 (ganache-core: 1.1.3) Truffle v3.4.11.

My tests work fine on

Seems there is a breaking change after 8.7.0 that relates to the way testrpc handles "restoring snapshots" when the last test asserts a throw ( race condition maybe ).

In any case, if you run into these kinds of issues, just make sure your last test does not throw and you should be all good, or use node 8.7.0, as that specific version seems to be working just fine.

later edit, seems i just removed the whole "revert" functionality in truffle a while back since i'm already doing it myself when i actually need to.. and that's why the issue did not manifest on my workstation. I removed it mostly because of the fact that testrpc will not revert to previous time when using evm_increaseTime

elenadimitrova commented 6 years ago

At Colony we also see this with roughly the 10% frequency that @cgewecke reports. Environment: testrpc 6.0.3 node 9.1.0

Copy of the last error from Circle CI

testRpc stderr:

/home/ubuntu/colonyNetwork/node_modules/ethereumjs-testrpc-sc/build/cli.node.js:68557
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;
NotFoundError: Key not found in database
    at /home/ubuntu/colonyNetwork/node_modules/ethereumjs-testrpc-sc/build/cli.node.js:80265:18
    at /home/ubuntu/colonyNetwork/node_modules/ethereumjs-testrpc-sc/build/cli.node.js:80030:19
    at /home/ubuntu/colonyNetwork/node_modules/ethereumjs-testrpc-sc/build/cli.node.js:82175:21
    at ReadFileContext.callback (/home/ubuntu/colonyNetwork/node_modules/ethereumjs-testrpc-sc/build/cli.node.js:82072:14)
    at FSReqWrap.readFileAfterOpen [as oncomplete] (fs.js:437:13)
habdelra commented 6 years ago

I've tried all the suggestions made in this thread and still have not seen anything to conclusively workaround this problem. The one thing I'm observing that seems pretty consistent is that the more tests that we have the more often we encounter this problem. To work around this issue, I wrote a shell script that stops and starts testrpc in between test files, so that we are generally not running more than 20-30 tests in an single testrpc instance. This results in slower tests, but at least they have been really consistent in terms of not sporadically failing. In case anyone else finds this useful, here's the test runner that I'm using to stop and start testrpc between test files.:

./bin/test-runner.sh:

#!/bin/bash

# Due to issue https://github.com/trufflesuite/ganache-cli/issues/359
# running all the tests usually causes testrpc to crash. Instead,
# run all the tests with separate testrpc instances. It's slower, but
# more consistent.

CURRENT_DIR=`pwd`
cd `dirname $0`
DIR=`pwd`

TEST_DIR="$DIR/../test"
TRUFFLE="$DIR/../node_modules/.bin/truffle"
TESTRPC="$DIR/../node_modules/.bin/ganache-cli"
TESTRPC_PID=""
SUITE_EXIT=0

function finish {
  kill -9 $TESTRPC_PID
}

for filename in $TEST_DIR/*-test.js; do
  $TESTRPC --gasLimit 6100000 > /dev/null &
  TESTRPC_PID=$!
  $TRUFFLE test "$filename"
  TEST_EXIT=$?
  kill -9 $TESTRPC_PID
  if [ $TEST_EXIT -ne 0 ]; then
    SUITE_EXIT=$TEST_EXIT
  fi
done

trap finish EXIT

if [ $SUITE_EXIT -ne 0 ]; then
  >&2 echo "Exiting with failing tests"
else
  echo "Tests passed"
fi
exit $SUITE_EXIT
mickys commented 6 years ago

@habdelra since you're already running them in a separate instance, why not go the extra mile and run them in separate threads.

It's not like running the tests is that resource intensive. Each test could log their output into their own log file, and after all of them finish you combine them and display the result in the order you want.

This should work just fine as long as you're not doing coverage tests which would require some changes to sol-cover.

benjamincburns commented 6 years ago

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

elenadimitrova commented 6 years ago

https://github.com/trufflesuite/ganache-cli/issues/426 is most likely related

edgraaff commented 6 years ago

In our project I made two .js files to test two contracts, the order they run in seems to be the pattern for failure. If test1.js runs before test2.js, all is fine, but if test2.js runs before test1.js it always fails.

Either way, a workaround was to add a one-second delay at the end of the contract test.

contract('MyFancyContract', accounts => {
  // do your tests here

  // add this as last test
  it('should wait a second', () => {
    return new Promise((resolve, reject) => {
      setTimeout(resolve, 1000);
    })
  });
});
edgraaff commented 6 years ago

Sorry, that wasn't entirely correct. It turned out that test2.js had a test that did not return the promise. In other words; the contract test was ended before all tests actually completed. Explains why the second delay fixed it.

contract('MyFancyContract', accounts => {
  it('should do a trick', () => {
    // forgot 'return' here
    return MyFancyContract.deployed()
      .then(c => c.doTrick())
      .then(res => {
        // validate res
      });
  });
});
elenadimitrova commented 6 years ago

Since Friday the frequency this shows it's ugly head has gone from 10% to solid 100%

benjamincburns commented 6 years ago

@elenadimitrova can you please diff your tests and check for changes which might cause transactions/calls to be run after truffle/mocha think the test is meant to be completed? Based on what @edgraaff is saying, I think this is often a problem caused by evm_revert happening while some other task (call/transaction/getBalance) is running.

benjamincburns commented 6 years ago

@elenadimitrova also if you can roll your changes back to whatever things looked like on Friday and the problem goes back to a 10% nuisance, there may be some valuable insight gained which can help us to fix this.

elenadimitrova commented 6 years ago

@area successfully patched this for us using https://github.com/ethereumjs/merkle-patricia-tree/pull/30 plus disabling the use of evm_revert

nadavhollander commented 6 years ago

@elenadimitrova Likewise clawing my eyes out right now on this issue. How did you disable use of evm_revert?

benjamincburns commented 6 years ago

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

Closing this case for now, but please reopen if I've got it wrong and this problem shows its ugly face again.

barakman commented 6 years ago

@benjamincburns: The problem persists with ganache-cli@7.0.0-beta.0.

My setup is:

A while ago, I have posted a simple test case which reproduces the problem pretty consistently (though at a random point) here. I am posting a simplified version of it below...

On-Chain:

pragma solidity ^0.4.18;

contract MyContract {
    uint256 public constant ONE = 1000000000;
    uint256 public constant GAMMA = 179437500000000000000000000000000000000000;
    uint256 public constant DELTA = 29437500;
    uint256 public constant AMOUNT = 1000000;

    function buy(uint256 x, uint256 alpha, uint256 beta) external pure returns (uint256) {
        uint256 temp = alpha - beta * x;
        return AMOUNT * (temp * ONE) / (temp * (ONE - DELTA) + GAMMA);
    }

    function sell(uint256 x, uint256 alpha, uint256 beta) external pure returns (uint256) {
        uint256 temp = alpha - beta * x;
        return AMOUNT * (temp * (ONE + DELTA) - GAMMA) / (temp * ONE);
    }
}

Off-Chain:

contract("MyContractTest", function() {
    let hMyContract;
    let ONE;
    let GAMMA;
    let DELTA;
    let AMOUNT;

    let NUM_OF_TESTS = 10;

    let minN = web3.toBigNumber("0");
    let maxN = web3.toBigNumber("20000000000000000000000000");
    let alpha = web3.toBigNumber("10000000000000000000000000000000000");
    let beta = web3.toBigNumber("0");
    let incN = maxN.minus(minN).dividedBy(NUM_OF_TESTS - 1);

    describe("accuracy assertion:", function() {
        before(async function() {
            hMyContract = await artifacts.require("MyContract.sol").new();
            ONE = await hMyContract.ONE();
            GAMMA = await hMyContract.GAMMA();
            DELTA = await hMyContract.DELTA();
            AMOUNT = await hMyContract.AMOUNT();
        });
        for (let func of [buy, sell]) {
            for (let n = 0; n < 1000; n++) {
                for (let i = 0; i < NUM_OF_TESTS; i++) {
                    it(`${func.name} test ${n} ${i}`, async function() {
                        let x = minN.plus(incN.times(i)).truncated();
                        let [fixedPoint, floatPoint] = await func(x, alpha, beta);
                        let ratio = fixedPoint.dividedBy(floatPoint);
                        assert(ratio.greaterThanOrEqualTo("0.99999"), `ratio = ${ratio.toFixed()}`);
                        assert(ratio.lessThanOrEqualTo("1"), `ratio = ${ratio.toFixed()}`);
                    });
                }
            }
        }
    });

    function buyFunc(x, alpha, beta) {
        let temp = alpha.minus(beta.times(x));
        return AMOUNT.times(temp.times(ONE)).dividedBy(temp.times(ONE.minus(DELTA)).plus(GAMMA));
    }

    function sellFunc(x, alpha, beta) {
        let temp = alpha.minus(beta.times(x));
        return AMOUNT.times(temp.times(ONE.plus(DELTA)).minus(GAMMA)).dividedBy(temp.times(ONE));
    }

    async function buy(x, alpha, beta) {
        let fixedPoint = await hMyContract.buy(x, alpha, beta);
        let floatPoint = buyFunc(x, alpha, beta);
        return [fixedPoint, floatPoint];
    }

    async function sell(x, alpha, beta) {
        let fixedPoint = await hMyContract.sell(x, alpha, beta);
        let floatPoint = sellFunc(x, alpha, beta);
        return [fixedPoint, floatPoint];
    }
});

The error message by truffle test is:

  1) Contract: MyContractTest "before each" hook: before test for "buy test 1":
     Error: Could not connect to your Ethereum client. Please check that your Ethereum client:
    - is running
    - is accepting RPC connections (i.e., "--rpc" option is used in geth)
    - is accessible over the network
    - is properly configured in your Truffle configuration file (truffle.js)

      at ProviderError.ExtendableError (C:\Users\...\webpack:\~\truffle-error\index.js:10:1)
      at new ProviderError (C:\Users\...\webpack:\~\truffle-provider\error.js:17:1)
      at C:\Users\...\webpack:\~\truffle-provider\wrapper.js:71:1
      at C:\Users\...\webpack:\~\truffle-provider\wrapper.js:129:1
      at XMLHttpRequest.request.onreadystatechange (C:\Users\...\webpack:\~\web3\lib\web3\httpprovider.js:128:1)
      at XMLHttpRequestEventTarget.dispatchEvent (C:\Users\...\webpack:\~\xhr2\lib\xhr2.js:64:1)
      at XMLHttpRequest._setReadyState (C:\Users\...\webpack:\~\xhr2\lib\xhr2.js:354:1)
      at XMLHttpRequest._onHttpRequestError (C:\Users\...\webpack:\~\xhr2\lib\xhr2.js:544:1)
      at ClientRequest.<anonymous> (C:\Users\...\webpack:\~\xhr2\lib\xhr2.js:414:1)
      at Socket.socketErrorListener (_http_client.js:387:9)
      at emitErrorNT (internal/streams/destroy.js:64:8)
      at _combinedTickCallback (internal/process/next_tick.js:138:11)
      at process._tickCallback (internal/process/next_tick.js:180:9)

In addition to all of the above, with the --noVMErrorsOnRPCResponse flag in use, it seems that an "Invalid JSON RPC response..." error is quite often emitted as a result of 'revert' (require failure) or 'invalid opcode' (assert failure) occurring on the contract side. I trigger those on purpose (as part of the contract verification process), but I expect to catch them with a "revert" message or an "invalid opcode" message (not an "Invalid JSON RPC response" message).

Thanks

barakman commented 6 years ago

Added more information at truffle 729.