Intermittent failure when running truffle tests about ganache-cli-archive HOT 19 CLOSED

Cause found, video here: https://youtu.be/tzjr_hTE_lg

This cache insertion is the culprit. What do we do? https://github.com/ethereumjs/ethereumjs-vm/blob/master/lib/cache.js#L80

Edit: That questions more rhetorical while I get people queued for discussion.

from ganache-cli-archive.

@area Awesome - thanks for this. Confirming that I reproduced it. Looking into it now.

from ganache-cli-archive.

Not sure if it's good or bad news, but I assume it'll help: I've just seen the same failure on a test written using the pattern of the 'never fails' test.

from ganache-cli-archive.

I still haven't been able to pin this one down. Really tough issue; still looking.

from ganache-cli-archive.

@area I can't get this to reproduce anymore. I was able to reproduce it earlier today, however, it no longer seems to be an issue.

Things I did between then and now that could possibly affect it:

• Restarted my computer (gross, but possible)
• Removed my node_modules directory within the testrpc checkout and reinstalled.

I've narrowed it down to those two things (at least, that's all I can think of at the moment). There has also been some changes to master which I'm running now and, although they likely shouldn't have affected this bug, they could have.

Can you give it a try and see if you can reproduce? If so, try the above two things and let me know if the issue goes away (if it does, this isn't necessarily a good thing). I used to be able to reproduce it nearly 100% of the time after a few runs. Now the test seems to be looping forever.

from ganache-cli-archive.

Oh, one last thing: I'm on the latest version of Truffle. Although I hope that's unrelated, still cannot be sure. https://github.com/ConsenSys/truffle/releases

from ganache-cli-archive.

I can still reproduce on latest truffle, latest testrpc (after blowing away node_modules) and running the test immediately after restarting.

from ganache-cli-archive.

Not sure what changed but I'm reproducing it steadily now.

from ganache-cli-archive.

To follow up, I added a few log events to the root contract, and an address is getting created, as evidenced by the outputs below. This suggests it's not an ethereumjs-vm issue, at least not during contract creation. It might still be an issue during the call, but it's likely like an issue with the provider engine moreso ethereumjs-vm itself.

    Events emitted during test:
    ---------------------------

    LogInteger(integer: 0)
    LogAddress(addr: 0x939a3b993dac23f66ff801de9955a58fda516bdb)
    LogInteger(integer: 1)

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

createSubcontract() now looks like this:

   event LogInteger(uint256 integer);
   event LogAddress(address addr);

   function createSubcontract()
   {
     LogInteger(subcontractNum);
     address addr = address(new Subcontract());
     LogAddress(addr);

     subcontracts[subcontractNum] = addr;
     subcontractNum++;
     LogInteger(subcontractNum);
   }

from ganache-cli-archive.

@area Can you give me access to your repository so I can commit changes to it? I've cut down the test case a bit to make things simpler, and I want to send this on to other people.

Here's what (I think) I've verified in the case where the test fails:

1. The root contract is created.
2. The root contract has code at its address, and its code matches that when the test passes.
3. The sub contract is created (address is output via logs, and checked via further requests done manually).
4. The sub contract has code at its address, and its code matches that when the test passes.
5. When the test passes, the root contract's subcontractNum is 1, as expected.
6. When the test fails, the root contract's subcontractNum is 0 when it should be 1.
7. When the test passes, the root contract's subcontracts mapping has a value at index 0.
8. When the test fails, the root contract's subcontracts mapping does not have a value at index 0.
9. The test is sending the createSubcontract() transaction to the correct contract address (the root contract).
10. The test is sending the subcontractNum() call to the correct address (the root contract; the same address the above transaction was sent to).
11. The TestRPC is requesting address storage from the same position whether or not the test passes or fails (i.e., the eth_call request results in a eth_getStorageAt request by the provider engine, and the parameters of that request are the same no matter if the test passes or fails).

I've also added some code to the test that displays some of this information, which I'll commit once given access. Here's a comparison between when the test passes and fails:

Using environment test.
Compiling contracts...


  Contract: RootContract

  RootContract address:                   0x5a6c643d09ec67eafe95adc2536582528472e259
  Creating SubContract...
    Sent to (via getTransactionByHash):   0x5a6c643d09ec67eafe95adc2536582528472e259
  SubContract address (via logs):         0x72cd343446b821c07e42397fbc5a368ff0cc1563
  SubContract address (via RootContract): 0x72cd343446b821c07e42397fbc5a368ff0cc1563
  SubContract count   (via RootContract): 1
  SubContract code:                       0x606060405200

    ✓ this test will eventually fail (659ms)


  1 passing (1s)

Using environment test.
Compiling contracts...


  Contract: RootContract

  RootContract address:                   0xeb848628bb5d70f83801e9a1d244989758170dd3
  Creating SubContract...
    Sent to (via getTransactionByHash):   0xeb848628bb5d70f83801e9a1d244989758170dd3
  SubContract address (via logs):         0xe166dc445d31108fe8358ac6c765e08107725afe
  SubContract address (via RootContract): 0x0000000000000000000000000000000000000000
  SubContract count   (via RootContract): 0
  SubContract code:                       0x606060405200

    1) this test will eventually fail

    Events emitted during test:
    ---------------------------

    LogAddress(addr: 0xe166dc445d31108fe8358ac6c765e08107725afe)
    LogInteger(integer: 1)

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


  0 passing (1s)
  1 failing

I'm still not able to account for the discrepancy and my hypotheses are minimal. Will continue.

from ganache-cli-archive.

Update (here for posterity): Using the changes on my machine, which I hope to upload to the test repo, you can reproduce the error deterministically by starting the TestRPC with the following parameters:

$ ./bin/testrpc -m "fat family plate raw violin boring spread income swim ethics tenant liberty"

(and then in a different terminal)
$ while ../truffle/cli.js test; do :; done

For me, it fails on the first test run, and always fails.

As well, using a different mnemonic, you can have the first run pass but the second one fail, if you want to compare a passing then failing test:

$ ./bin/testrpc -m "rule time service awful dog bicycle rescue repair robot goose patrol target"

(and then in a different terminal)
$ while ../truffle/cli.js test; do :; done

It turns out the deterministic addresses created produce the erroneous behavior 100% of the time.

from ganache-cli-archive.

Scratch giving me access. I've forked the repo here: https://github.com/tcoulter/testrpc_bug_reproduce

When running the above tests, use that repo.

from ganache-cli-archive.

More findings:

When the tests pass, ethereumjs-vm makes one less put into the stateTrie, whereas when the test fails it makes one extra. As well, that one extra appears to be the same put call twice. Here's a comparison:

Passing test (5 calls to put):

eth_sendTransaction
State Trie: putting 0000000000000000000000000000000000000000 : f84c80888afdb320d8d89b41a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a0c5d2460186f7233c927e7db2dcc703c0e500b653ca82273b7bfad8045d85a470
State Trie: putting 12be8eadcb66ff841671dc5b65e90798d686cc2c : f85403900fffffffffffffefffc96fe3b10f64c0a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a0c5d2460186f7233c927e7db2dcc703c0e500b653ca82273b7bfad8045d85a470
State Trie: putting 5b8934f78826298b504354c870525c057e5bcb58 : f8440180a0b06eea2c173149591433a32f617d3b723e77ba4c89208a73799a964dc38314e1a0d931bda081742df3cfb479e9320a8c0900a1f4954500f186d267c38c5f88113a
State Trie: putting fe9984dccaa78479cc60ab29179ebd9a99c2ede4 : f8448080a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a02f392ea1bb95460c866659701c2089d106e3876771a938437fadb93ad10f9db2
State Trie: putting 0000000000000000000000000000000000000000 : f84c8088d06144a31dcc9b41a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a0c5d2460186f7233c927e7db2dcc703c0e500b653ca82273b7bfad8045d85a470

  Gas usage: 97108
  Block Number: 0x03

Failing test (6 put calls; notice the 4th and 5th are exactly the same - EDIT: They're not exactly the same, but very similar.):

eth_sendTransaction
State Trie: putting 0000000000000000000000000000000000000000 : f84c80888afdb320d8d89b41a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a0c5d2460186f7233c927e7db2dcc703c0e500b653ca82273b7bfad8045d85a470
State Trie: putting 9cab3196974be07581aa3b8f2f271717d7c45ce9 : f85403900fffffffffffffefffc96fe3b10f64c0a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a0c5d2460186f7233c927e7db2dcc703c0e500b653ca82273b7bfad8045d85a470
State Trie: putting e896fa9d0c96832a69f3ac769756a283f7cc2632 : f8448080a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a02f392ea1bb95460c866659701c2089d106e3876771a938437fadb93ad10f9db2
State Trie: putting fb08f969e3f3afb43fcd3b785caed5fa972d120b : f8448080a0b5e842349ccfe67678e039b67b31faff7ddbf183d6ad225c72609034e132813fa0d931bda081742df3cfb479e9320a8c0900a1f4954500f186d267c38c5f88113a
State Trie: putting fb08f969e3f3afb43fcd3b785caed5fa972d120b : f8440180a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a0d931bda081742df3cfb479e9320a8c0900a1f4954500f186d267c38c5f88113a
State Trie: putting 0000000000000000000000000000000000000000 : f84c8088d06144a31dcc9b41a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a0c5d2460186f7233c927e7db2dcc703c0e500b653ca82273b7bfad8045d85a470

  Gas usage: 97108
  Block Number: 0x03

@wanderer Do you have any idea why this might be happening?

from ganache-cli-archive.

Passing TestRPC output: https://gist.github.com/tcoulter/55384811f76a6e515363f55dbdfd1158
Failing TestRPC output: https://gist.github.com/tcoulter/f5395f1338924522e7904cdc43e74cb5

from ganache-cli-archive.

Oh ***, the second put appears to be updating the root contract's state a second time.

First:

> util.rlp.decode("0xf8448080a0b5e842349ccfe67678e039b67b31faff7ddbf183d6ad225c72609034e132813fa0d931bda081742df3cfb479e9320a8c0900a1f4954500f186d267c38c5f88113a")
[ <Buffer >,
  <Buffer >,
  <Buffer b5 e8 42 34 9c cf e6 76 78 e0 39 b6 7b 31 fa ff 7d db f1 83 d6 ad 22 5c 72 60 90 34 e1 32 81 3f>,
  <Buffer d9 31 bd a0 81 74 2d f3 cf b4 79 e9 32 0a 8c 09 00 a1 f4 95 45 00 f1 86 d2 67 c3 8c 5f 88 11 3a> ]

Second

> util.rlp.decode("0xf8440180a056e81f171bcc55a6ff8345e692c0f86e5b48e01b996cadc001622fb5e363b421a0d931bda081742df3cfb479e9320a8c0900a1f4954500f186d267c38c5f88113a")
[ <Buffer 01>,
  <Buffer >,
  <Buffer 56 e8 1f 17 1b cc 55 a6 ff 83 45 e6 92 c0 f8 6e 5b 48 e0 1b 99 6c ad c0 01 62 2f b5 e3 63 b4 21>,
  <Buffer d9 31 bd a0 81 74 2d f3 cf b4 79 e9 32 0a 8c 09 00 a1 f4 95 45 00 f1 86 d2 67 c3 8c 5f 88 11 3a> ]

I've verified through some hacks that if I filter out the last put, the test passes successfully.

@wanderer This is definitely an error for you.

from ganache-cli-archive.

damn @tcoulter fantastic sleuth work! the ethereumjs-vm has some funky behaviour with its caches that i tried to fix during my refactors over the summer, but required large changes that caused hundreds of breaking tests (there ares thousands or tens of thousands of tests). so that never got merged. Maybe we can try for a more minimal change that resolves this issue.

from ganache-cli-archive.

Sorry didn't give you access to my repo last night, but I'm super glad to see progress. I'm now much more comfortable with the fact that I wasn't able to figure out what was happening myself after seeing how deep into the rabbit hole you had to go!

Hope a fix appears soon.

from ganache-cli-archive.

Update: This PR fixes the issue: ethereumjs/ethereumjs-monorepo#54. Let's hope the thousands of ethereumjs-vm tests pass ::cross your fingers::

from ganache-cli-archive.

This has been fixed on master!

from ganache-cli-archive.