Intermittent reverts when rerunning tests

Hi. I have a weird thing here where my code sometimes reverts in truffle test, sometimes not.

When it reverts, 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.

When I run these 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.

Could it be a Gas issue? The repository 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 have already found out, that when I encapsulate the tests within a nested

describe("Initiating token sale", function() {
    // lets move tests here
}

then less reverts will happen, but still do.

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 = {
// See http://truffleframework.com/docs/advanced/configuration
// to customize your Truffle configuration!
networks: {
development: {
host: “127.0.0.1”,
port: 8545,
gas: 6000000,
gasPrice: 5e9,

  network_id: "*",
},

For the sake of completeness the code of token contract:

contract XXXToken is ERC20Detailed, ERC20Mintable, ERC20Pausable {

    function initialize(
        address minter,
        address[] memory pausers
    ) public initializer {

        require(pausers[0] != address(0));

        ERC20Detailed.initialize("XXXToken", "XXX", uint8(18));
        ERC20Mintable.initialize(minter);

        ERC20Pausable.initialize(pausers[0]);

        // add the other pausers as well if existing
        for (uint256 i = 1; i < pausers.length; ++i) {
            _addPauser(pausers[i]);
        }
    }

    function () external payable {
        revert();
    }

    /**
     * @dev Minting tokens
     * @param account The account of beneficiary who will get the minted token
     * @param value The amount of minted token
     */
    function _mint(address account, uint256 value) internal whenNotPaused onlyMinter {
        super._mint(account, value);
    }

}

And the CrowdSale contract:

contract XXXTokenSale is Initializable, Ownable {
    using SafeMath for uint256;

    XXXToken private _token;
    uint256 private _openingTime;
    uint256 private _closingTime;

    uint256 private _mintedTokens;

    TokenTimelock private _timeLock;

    /**
     * @dev Reverts if not in crowdsale time range.
     */
    modifier onlyWhileOpen {
        require(isOpen());
        _;
    }

    TeamVesting private _teamVesting;

    event TeamVestingAssigned(address teamVesting);

    function initialize(uint256 openingTime, uint256 closingTime, XXXToken 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;

    }

    function addTimelock(uint256 releaseTime) public {
        _timeLock = new TokenTimelock();
        _timeLock.initialize(_token, address(_teamVesting), releaseTime );
    }

    /**
     * @return the token being sold.
     */
    function token() public view returns (XXXToken) {
        return _token;
    }

    function mintedTokens() public view returns (uint256) {
        return _mintedTokens;
    }

    /**
     * @return true if the crowdsale is open, false otherwise.
     */
    function isOpen() public view returns (bool) {
        // solhint-disable-next-line not-rely-on-time
        return block.timestamp >= _openingTime && block.timestamp <= _closingTime;
    }

    /**
     * @dev Checks whether the period in which the crowdsale is open has already elapsed.
     * @return Whether crowdsale period has elapsed
     */
    function hasClosed() public view returns (bool) {
        // solhint-disable-next-line not-rely-on-time
        return block.timestamp > _closingTime;
    }

    function assignTeamVesting(TeamVesting teamVesting) public onlyOwner {
        require(address(teamVesting) != address(0));

        _teamVesting = teamVesting;
        emit TeamVestingAssigned(address(teamVesting));
    }


    function () external payable {
        revert();
    }

    /**
     * @dev Overrides delivery by minting tokens upon purchase.
     * @param beneficiary Token purchaser
     * @param tokenAmount Number of tokens to be minted
     */
    function mintTokens(address beneficiary, uint256 tokenAmount) public onlyWhileOpen {

        _mintedTokens = _mintedTokens.add(tokenAmount);

        require(XXXToken(address(token())).mint(beneficiary, tokenAmount));
    }

}

Has anybody faced this issue and can tell a workaround?

1 Like

I’ve upgraded truffle and ganache to latest versions, but the issues are still happening.

I’ve filed an issue: https://github.com/trufflesuite/truffle/issues/2092 and also published the repository earlier than planned. Maybe this helps.

2 Likes

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 revert s 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;
    }
1 Like

Okay, I found the root cause together with https://github.com/CruzMolina.

The reason is, that block.timestamp is a second behind sometines in Ganache network. Thus all tests for TimeCrowdSale (and all those that are borrowed from it) will fail in such a situation.

I submitted a PullRequest and described verything: https://github.com/OpenZeppelin/openzeppelin-eth/pull/52

1 Like

Hi @itinance

In the TimedCrowdsale.test.js time is advanced before the tests are run using the openzeppelin-test-helpers which I assume deals with the issue you were experiencing.

  before(async function () {
    // Advance to the next block to correctly read time in the solidity "now" function interpreted by ganache
    await time.advanceBlock();
  });

My thoughts would be to change the tests rather than the smart contract code.

I’m pretty sure the reason is that you’re missing an await before tokenSale.initialize. This is what would be causing the non deterministic behavior.

2 Likes

@frangio thx. I already added all missing ‘await’ (Link) but still faced this issue as long as not reducing the blocktime in the contract for a second.

I have also tried out the suggestion from @abcoathup and added the await time.advanceBlock() statement into before. It will still break my tests without the adjustment of a second.

Isn’t it weird?

1 Like

Hi @itinance I wasn’t able to reproduce using your repo.

Do you have some minimum code that consistently produces the issue? It would be great to track down to then see how to resolve.

1 Like

Hi @abcoathup, nice to have you here :slight_smile: I submitted a little change reverting

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

to

require(openingTime >= block.timestamp);

in a separate remote branch.

When I run then tests with “truffle test”, from 5 times at least 2 will break. The first test run might go through successfully, but the second or third one would break. Arbitrary.

How was it going on your machine?

1 Like

Hi @itinance

I had modified your contract and wasn’t getting the error, but do now using your branch.

I suggest you add revert reasons to your requires (and also your tests), e.g.:

        require(openingTime >= block.timestamp, "NCDTokenSale: opening time is before current time"); // in order to make this testable with Ganache, we have to reduce a second
        require(closingTime > openingTime, "NCDTokenSale: opening time is not before closing time");

The OpenZeppelin tests set the openingTime to the future, to test the contract prior to the sale being open.

I want to see if I can cut it down to minimum code that consistently produces the issue.

2 Likes

This helped a lot. With this time in future the 1-second-sometimes-issue does not happen.

And many thanks for the advice using reason-argument in require. This makes reverting more clear as it will print the particular reason while reverting. Hadn’t this in my mind ^^

1 Like

I am reproducing the issue with the following intermittently.

Sample contract

pragma solidity ^0.5.7;

contract Sample {
    uint256 private _timeX;

    function doStuff(uint256 timeX) public {
        // solhint-disable-next-line not-rely-on-time
        require(timeX >= block.timestamp, "Sample: timeX is before current time");

        _timeX = timeX;
    }
}

Sample tests

const { time } = require('openzeppelin-test-helpers');

const Sample = artifacts.require('Sample');

contract('Sample', function ([_, other]) {

  before(async function () {
    // Advance to the next block to correctly read time in the solidity "now" function interpreted by ganache
    await time.advanceBlock();
  });

  beforeEach(async function () {
    this.timeX = await time.latest();
    this.sample = await Sample.new();
  });

  describe('do stuff', function () {
    it('does stuff 1', async function () {
      await this.sample.doStuff(this.timeX);
    });

    it('does stuff 2', async function () {
      await this.sample.doStuff(this.timeX);
    });

    it('does stuff 3', async function () {
      await this.sample.doStuff(this.timeX);
    });
  });
});
1 Like

Not sure I see what the issue is: you’re mining a block, getting its timestamp, and then checking that it is equal to a new block’s timestamp. That’ll only happen if the second block is mined with the same timestamp as the first one, which is of course a non-deterministic event.

2 Likes

Awesome. :smile: Thanks for the explanation @nventuro

@itinance I hope that explains to you what we were seeing.

Housekeeping: renamed topic.