calling evm_mine with a timestamp does not persist time offset

[msuscens]

Discussed in #3264

I'm opening as an issue as suggested by @davidmurdoch

^{Originally posted by msuscens June 21, 2022}
Hello,

I have Truffle tests that successfully pass with Ganache v6 but fail with Ganache v7.3.1. The truffle tests in question use the ganache-time-traveler utility to advance time. Specifically, the issue is with functions that need a certain amount of time to pass before they will execute (without reverting). I, therefore, use ganache-time-traveler to advance the time before executing the function. Unfortunately, with ganache 7.3.1 these functions revert even though time has been advanced by the required amount. Here is an example:

describe("After Incubation: Hatch single egg", () => {

        let snapshotId
        beforeEach("Advance Time to End of Incubation", async() => {
            let snapshot = await timeMachine.takeSnapshot()
            snapshotId = snapshot['result']

            // Incubate for required time
            await truffleAssert.passes(
                timeMachine.advanceTimeAndBlock(INCUBATION_DURATION),
                "Failed to advance time and block"
            )
        })

        afterEach("Revert To Start of Incubation Time", async() => {
            await timeMachine.revertToSnapshot(snapshotId)
        })

        it("should allow egg owner to hatch it, emitting an Hatched event ", async () => {
            let txResult
            await truffleAssert.passes(
                txResult = await eggToken.hatch(
                    [0], //eggids
                    {from: accounts[2]}
                )
            )
            truffleAssert.eventEmitted(txResult, 'Hatched', (ev) => {
                return equals(toNumbers(ev.hatchlingIds), [0]) &&
                    equals(toNumbers(ev.eggIds),[0]) &&
                    ev.owner == accounts[2]
            }, "Event Hatched has incorrect parameter values!")
        })

etc ...

This test passes with Ganche v6 but eggToken.hatch reverts under v7.3.1 with the following message:

After Incubation: Hatch single egg
         should allow egg owner to hatch it, emitting an Hatched event :
     Transaction: 0x20883a2a3329b9925a86499b4fe1e9727a029f197d00f084ed920e94eb1954d6 exited with an error (status 0). Reason given: hatch: Egg not incubated!.
     Please check that the transaction:
     - satisfies all conditions set by Solidity `require` statements.
     - does not trigger a Solidity `revert` statement.
 
  StatusError: Transaction: 0x20883a2a3329b9925a86499b4fe1e9727a029f197d00f084ed920e94eb1954d6 exited with an error (status 0). Reason given: hatch: Egg not incubated!.
      at Context.<anonymous> (test/2.eggToken/6.eggToken_hatch_gen0_test.js:217:43)
      at runMicrotasks (<anonymous>)
      at processTicksAndRejections (internal/process/task_queues.js:93:5)

I'd appreciate any help/advice on how to resolve this issue.

I'm on a 2022 MacBook Pro (M1 Pro processor): MacOS 12.4
Truffle v5.5.3 (core: 5.5.3)
Ganache v7.0.1
Solidity - 0.8.13 (solc-js)
Node v14.15.5
Web3.js v1.5.3

Note: Even though it says "Ganache v7.0.1" above (from 'truffle version'), I've installed v7.3.1 and when I start ganache (via CL) it says "ganache v7.3.1 (@ganache/cli: 0.4.1, @ganache/core: 0.4.1)"

[MicaiahReid]

Hi @msuscens, thanks for opening this issue!

I took a look at the ganache-time-traveler library and the advanceTimeAndBlock function. I've tested the general functionality of advancing time via and evm_mine call like the advanceTimeAndBlock function does and it seems to be working fine. Are you able to share a repo for me to do a little more digging to see what the issue could be?

Thank you!

[msuscens]

Hello @MicaiahReid , thank you for looking into this issue.

I've created a public repository with a cut-down version of my full project. I've also added a README file that shows what I'm experiencing under Ganache 6.12.2 vs Ganache 7.3.1. Simply execute 'truffle test' under each version of Ganache.

https://github.com/msuscens/Egg.git

Please let me know if you need anything else in order to investigate.

[MicaiahReid]

Hi @msuscens. I've done some digging, and you can use the --miner.timestampIncrement 1 flag when starting Ganache v7.3.1 or greater to fix this issue. This will have the miner set a block's timestamp to previousBlock.timestamp + 1 rather than using your computer's time.

It looks like the evm_mine function does correctly set the mined block to the specified timestamp. However, if the miner is using your CPU time, the next block that is mined (which is the block that your transaction will go onto) will have a timestamp equal to your CPU time regardless of if the previous block was manually set. In other words, Ganache doesn't enforce a block's timestamp being greater than a previous block's timestamp.

In your case, the following was happening:

block n timestamp: 1
 => use evm_mine to mine a block with timestamp of 61
block n+1 timestamp: 61
 => your test sends a transaction to make a contract call
block n+2 timestamp: 2

From my understanding of ganache-cli, this should have been the case back then, too. Ganache, as far as I'm aware, has never enforced a block having a timestamp greater than the previous block. So, I think it was a bug within ganache-cli that allowed the ganache-time-traveler package to work in the way that it did.

Let me know if adding --miner.timestampIncrement 1 fixes this for you. In the meantime @davidmurdoch do you think there is a bug in Ganache with the situation I've described above? I'm currently leaning towards a no, especially because we have the new timestampIncrement flag to cover all desired use cases.

[davidmurdoch]

I did some digging and I think this may be a regression in ganache v7. Previously, evm_mine would cause the internal clock offset to be updated to the given timestamp value. See:

evm_mine is here:

ganache/lib/subproviders/geth_api_double.js

Line 557 in efa9c47

this.state.processBlock(timestamp, function(err) {

which leads to here:

ganache/lib/statemanager.js

Line 576 in efa9c47

StateManager.prototype.processBlock = function(timestamp, callback) {

which leads to:

ganache/lib/blockchain_double.js

Line 733 in efa9c47

BlockchainDouble.prototype.processNextBlock = function(timestamp, callback) {

and finally to:

ganache/lib/blockchain_double.js

Line 792 in efa9c47

self.setTime(new Date(timestamp * 1000));

[MicaiahReid]

Great find, @davidmurdoch!

@msuscens, hopefully using the --miner.timestampIncrement 1 flag will suffice as a workaround until we get a fix released.

[msuscens]

Thank you @MicaiahReid / @davidmurdoch,

Yes, I can confirm that using --miner.timestampIncrement 1 flag on my full project resolves the issue! Thank you both very much!! I can now finally use Ganache v7 🚀

I do have another issue with Truffle tests running with Ganache but I'll investigate further first and then post in the Q&A section.

Thanks again,
Mark

[jeffsmale90]

After attempting to resolve some of the short comings of this approach, I have decided to close the PR, and address this with a simpler fix. #3506

Initially I thought it made sense to decouple BlockTime from the Blockchain, as they are separate concerns. I have subsequently learned that with timestampIncrement !== "clock", the interface between Blockchain and BlockTime becomes quite messy. The decisions made - for instance when to increment, when to apply / reset the adjustments should be made by the blockchain, but don't fit on a generalised BlockTime interface.

[MicaiahReid]

@jeffsmale90 this is an issue and not a PR, so I don't think we should close it until the fix is merged 😄

[jeffsmale90]

I haven't looked into the code to confirm this yet, but it appears that when a timestamp increment is specified, the offset is persisted when evm_mine is called with a timestamp parameter, but not when using clock.

I'll pick this up today and try to get a hotfix together to resolve.