Weird behaviour: arbitrary and random REVERT while running test with same code without any changes

[itinance]

• I've asked for help in the Truffle Gitter before filing this issue.

---

Issue

I get random and unpredictable reverts while running tests on the very same code basis. Sometimes they run through, sometimes a revert is happening running on local network powered by ganache.

When it reverts, in my case it always revert at the line where “addMinter” is executed on the CrowdSale-Contract out of “beforeEach” in the test (which can be seen with the output of console.log(5). After “5” was printed to stdout, it reverts. When I would debug this with “truffle debug $transactionID”, everything would go through successfully.

When I run my tests 5 times, then there is a big chance that at least for one time it reverts with the very first test, sometimes at the second or third test, sometimes everything is going through without any revert.

When I run these tests 10 times, in some cases everything works fine, and mostly it breaks within a particular test like described above.

Sometimes 5 times running tests in a row works sucessfully, sometimes it breaks constantely.

Steps to Reproduce

My tests looks as follows (and can be found here: https://github.com/itinance/ncd-token):

contract("CrowdSale tests", async ([_, owner, pauser1, pauser2,  ...otherAccounts]) => {
    let token, tokenSale,
        openingTime, closingTime, afterClosingTime;

    const buyer = otherAccounts[1];
  
    beforeEach(async function () {
        token = await XXXToken.new({from: owner});
        token.initialize( owner, [pauser1, pauser2]);

        openingTime = await time.latest();
        closingTime = openingTime.add(time.duration.years(1));
        afterClosingTime = closingTime.add(time.duration.seconds(1));

        console.log(4, token.address);

        tokenSale = await XXXTokenSale.new({from: owner});
        tokenSale.initialize(openingTime, closingTime, token.address);

        console.log(5)

        await token.addMinter(tokenSale.address, {from: owner});
        console.log(6)
        await token.renounceMinter({ from: owner });

        console.log(7)

    });

        it('crowdsale should be minter', async function () {
          (await token.isMinter(tokenSale.address)).should.equal(true);
        });

        it('owner should not be minter anymore', async function () {
          (await token.isMinter(owner)).should.equal(false);
        });

        it('Timelock can be added', async function() {
          await tokenSale.addTimelock(afterClosingTime);
        })

});

I run on MacbookPro with MacOS Mojave and the following toolset:

$ truffle version
Truffle v5.0.21 (core: 5.0.21)
Solidity v0.5.0 (solc-js)
Node v10.16.0
Web3.js v1.0.0-beta.37
Ganache CLI v6.4.3 (ganache-core: 2.5.5)

Ganache was launched this way:

ganache-cli --mnemonic “your twelve word mnemonic here”

truffle-config.js:

module.exports = {
  networks: {
    development: {
      host: "127.0.0.1",
      port: 8545,
      gas: 6000000,
      gasPrice: 5e9,
      network_id: "*",
    },

Expected Behavior

Constant predictable behaviour across running tests on the very same code base.

Actual Results

Some times tests are running through, sometimes not

Environment

I run on MacbookPro with MacOS Mojave and the following toolset:

    $ truffle version
    Truffle v5.0.20 (core: 5.0.20)
    Solidity v0.5.0 (solc-js)
    Node v10.16.0
    Web3.js v1.0.0-beta.37
    Ganache CLI v6.3.0 (ganache-core: 2.4.0)

Ganache was launched this way:

ganache-cli --mnemonic “your twelve word mnemonic here”

truffle-config.js:

module.exports = {
  networks: {
    development: {
      host: "127.0.0.1",
      port: 8545,
      gas: 6000000,
      gasPrice: 5e9,

      network_id: "*",
    },

[CruzMolina]

Hey @itinance, based on your repo's activity, looks like you're already on it, but I would def make sure that for all contract instance method calls you make sure to await them appropriately.

[itinance]

Thx for reaching out @CruzMolina. I've already found missing await-statements and added them to every instance method call. Nevertheless, it keeps breaking, I wrote a script where I can run truffle test multiple times and grep for "Error:":

alias tt="truffle test"

5 times "truffle test" in a row, grepped for "Error:", 4 failed:

$ run 5 tt|grep Error\:
     Error: Returned error: VM Exception while processing transaction: revert
     Error: Returned error: VM Exception while processing transaction: revert
     Error: Returned error: VM Exception while processing transaction: revert
     Error: Returned error: VM Exception while processing transaction: revert

15 tests in a row, 5 failed:

$ time run 15 tt|grep Error\:
     Error: Returned error: VM Exception while processing transaction: revert
     Error: Returned error: VM Exception while processing transaction: revert
     Error: Returned error: VM Exception while processing transaction: revert
     Error: Returned error: VM Exception while processing transaction: revert
     Error: Returned error: VM Exception while processing transaction: revert

5 fails in 15 runs. But the count is arbitrary and may differ in subsequent tests.

It is remarkable that only the CrowdSale-Test with minting token makes this trouble. Indeed, when I don't call initialize on the CrowdSale contract (and therefor comment out the tests regarding this particular contract), no reverts will occur. Any ideas what is wrong with that?

Nothing special happens there:

    function initialize(uint256 openingTime, uint256 closingTime, NCDToken token) public initializer {
        require(address(token) != address(0));

        _token = token;

        // solhint-disable-next-line not-rely-on-time
        require(openingTime >= block.timestamp);
        require(closingTime > openingTime);

        _openingTime = openingTime;
        _closingTime = closingTime;
    }

[CruzMolina]

Are your tests still failing on the beforeEach?

[itinance]

@CruzMolina yes

I switched completely into MintableCrowdsale of OpenZeppelin-eth from my own implementation and the same issues occur from time to time

[CruzMolina]

Ah, so sometimes the time.latest() is a second behind the block.timestamp mined in the initialize transaction in the beforeEach.

Perhaps it wouldn't hurt to subtract one second from openingTime?

[itinance]

Hey @CruzMolina , you are right! It is the time function.

When I change [this line](https://github.com/itinance/ncd-token/blob/master/contracts/NCDTokenSale.sol#L39) from

require(openingTime >= block.timestamp);

to

require(openingTime >= block.timestamp - 1);

everything works as expected!

I have borrowed this line from OpenZeppelin and will open a PullRequest.

THANK YOU VERY MUCH!!!!!!!