Test non-deterministically fails in test suite with vm.revertTo

[anna-carroll]

Component

Forge

Have you ensured that all of these are up to date?

• Foundry
• Foundryup

What version of Foundry are you on?

forge 0.2.0 (c948388 2023-11-18T00:19:51.373226000Z)

What command(s) is the bug in?

forge test

Operating System

macOS (Apple Silicon)

Describe the bug

I wrote a test contract with 3 tests - 1 should always pass, 2 should always fail. In practice, the test that should always pass actually fails sometimes and passes other times, with no code changes (e.g. behaves non-deterministically).

Of the 2 always-failing tests, one of them calls vm.revertTo(snapshot) - could this be causing the strange behavior? To test this hypothesis, I commented out the vm.revertTo(snapshot) call, and the test suite behaved as expected deterministically (1 always passing, 2 always failing).

Test file is included below. Tests are

• test_shouldPass (should be always-passing, but in practice passes/fails non-deterministically)
• test_shouldFail (always-failing)
• test_shouldFailWithRevertTo (always-failing, calls vm.revertTo)

Here is the entire test file:

// SPDX-License-Identifier: UNLICENSED
pragma solidity ^0.8.13;

import {Test} from "forge-std/Test.sol";

contract Target {
    function num() public pure returns (uint256) {
        return 2;
    }
}

contract RevertTest is Test {
    uint256 snapshot;
    Target targ;

    function setUp() public {
        snapshot = vm.snapshot();
        targ = new Target();
    }

    // this non-deterministically fails sometimes and passes sometimes
    function test_shouldPass() public {
        assertEq(2, targ.num());
    }

    // always fails
    function test_shouldFaillWithRevertTo() public {
        assertEq(3, targ.num());
        vm.revertTo(snapshot);
    }

    // always fails
    function test_shouldFail() public {
        assertEq(3, targ.num());
    }
}

here is a trace of a run where all three fail:

[FAIL. Reason: assertion failed] test_shouldFail() (gas: 19933)
Logs:
  Error: a == b not satisfied [uint]
        Left: 3
       Right: 2

Traces:
  [83407] RevertTest::setUp()
    ├─ [0] VM::snapshot()
    │   └─ ← 0
    ├─ [23875] → new Target@0x5615dEB798BB3E4dFa0139dFa1b3D433Cc23b72f
    │   └─ ← 119 bytes of code
    └─ ← ()

  [19933] RevertTest::test_shouldFail()
    ├─ [146] Target::num() [staticcall]
    │   └─ ← 2
    ├─ emit log(: "Error: a == b not satisfied [uint]")
    ├─ emit log_named_uint(key: "      Left", val: 3)
    ├─ emit log_named_uint(key: "     Right", val: 2)
    ├─ [0] VM::store(VM: [0x7109709ECfa91a80626fF3989D68f67F5b1DD12D], 0x6661696c65640000000000000000000000000000000000000000000000000000, 0x0000000000000000000000000000000000000000000000000000000000000001)
    │   └─ ← ()
    └─ ← ()

[FAIL. Reason: assertion failed] test_shouldFaillWithRevert() (gas: 22400)
Logs:
  Error: a == b not satisfied [uint]
        Left: 3
       Right: 2

Traces:
  [83407] RevertTest::setUp()
    ├─ [0] VM::snapshot()
    │   └─ ← 0
    ├─ [23875] → new Target@0x5615dEB798BB3E4dFa0139dFa1b3D433Cc23b72f
    │   └─ ← 119 bytes of code
    └─ ← ()

  [22400] RevertTest::test_shouldFaillWithRevert()
    ├─ [146] Target::num() [staticcall]
    │   └─ ← 2
    ├─ emit log(: "Error: a == b not satisfied [uint]")
    ├─ emit log_named_uint(key: "      Left", val: 3)
    ├─ emit log_named_uint(key: "     Right", val: 2)
    ├─ [0] VM::store(VM: [0x7109709ECfa91a80626fF3989D68f67F5b1DD12D], 0x6661696c65640000000000000000000000000000000000000000000000000000, 0x0000000000000000000000000000000000000000000000000000000000000001)
    │   └─ ← ()
    ├─ [0] VM::revertTo(0)
    │   └─ ← true
    └─ ← ()

[FAIL. Reason: assertion failed] test_shouldPass() (gas: 5431)
Traces:
  [83407] RevertTest::setUp()
    ├─ [0] VM::snapshot()
    │   └─ ← 0
    ├─ [23875] → new Target@0x5615dEB798BB3E4dFa0139dFa1b3D433Cc23b72f
    │   └─ ← 119 bytes of code
    └─ ← ()

  [5431] RevertTest::test_shouldPass()
    ├─ [146] Target::num() [staticcall]
    │   └─ ← 2
    └─ ← ()

Test result: FAILED. 0 passed; 3 failed; 0 skipped; finished in 495.54µs

Ran 1 test suites: 0 tests passed, 3 failed, 0 skipped (3 total tests)

Failing tests:
Encountered 3 failing tests in test/Counter.t.sol:RevertTest
[FAIL. Reason: assertion failed] test_shouldFail() (gas: 19933)
[FAIL. Reason: assertion failed] test_shouldFaillWithRevert() (gas: 22400)
[FAIL. Reason: assertion failed] test_shouldPass() (gas: 5431)

Encountered a total of 3 failing tests, 0 tests succeeded

and here is a trace of a run where it passed:

➜  auth-template git:(main) ✗ forge test -vvvvv
[⠒] Compiling...
No files changed, compilation skipped

Running 3 tests for test/Counter.t.sol:RevertTest
[FAIL. Reason: assertion failed] test_shouldFail() (gas: 19933)
Logs:
  Error: a == b not satisfied [uint]
        Left: 3
       Right: 2

Traces:
  [83407] RevertTest::setUp()
    ├─ [0] VM::snapshot()
    │   └─ ← 0
    ├─ [23875] → new Target@0x5615dEB798BB3E4dFa0139dFa1b3D433Cc23b72f
    │   └─ ← 119 bytes of code
    └─ ← ()

  [19933] RevertTest::test_shouldFail()
    ├─ [146] Target::num() [staticcall]
    │   └─ ← 2
    ├─ emit log(: "Error: a == b not satisfied [uint]")
    ├─ emit log_named_uint(key: "      Left", val: 3)
    ├─ emit log_named_uint(key: "     Right", val: 2)
    ├─ [0] VM::store(VM: [0x7109709ECfa91a80626fF3989D68f67F5b1DD12D], 0x6661696c65640000000000000000000000000000000000000000000000000000, 0x0000000000000000000000000000000000000000000000000000000000000001)
    │   └─ ← ()
    └─ ← ()

[FAIL. Reason: assertion failed] test_shouldFaillWithRevert() (gas: 22400)
Logs:
  Error: a == b not satisfied [uint]
        Left: 3
       Right: 2

Traces:
  [83407] RevertTest::setUp()
    ├─ [0] VM::snapshot()
    │   └─ ← 0
    ├─ [23875] → new Target@0x5615dEB798BB3E4dFa0139dFa1b3D433Cc23b72f
    │   └─ ← 119 bytes of code
    └─ ← ()

  [22400] RevertTest::test_shouldFaillWithRevert()
    ├─ [146] Target::num() [staticcall]
    │   └─ ← 2
    ├─ emit log(: "Error: a == b not satisfied [uint]")
    ├─ emit log_named_uint(key: "      Left", val: 3)
    ├─ emit log_named_uint(key: "     Right", val: 2)
    ├─ [0] VM::store(VM: [0x7109709ECfa91a80626fF3989D68f67F5b1DD12D], 0x6661696c65640000000000000000000000000000000000000000000000000000, 0x0000000000000000000000000000000000000000000000000000000000000001)
    │   └─ ← ()
    ├─ [0] VM::revertTo(0)
    │   └─ ← true
    └─ ← ()

[PASS] test_shouldPass() (gas: 5431)
Traces:
  [83407] RevertTest::setUp()
    ├─ [0] VM::snapshot()
    │   └─ ← 0
    ├─ [23875] → new Target@0x5615dEB798BB3E4dFa0139dFa1b3D433Cc23b72f
    │   └─ ← 119 bytes of code
    └─ ← ()

  [5431] RevertTest::test_shouldPass()
    ├─ [146] Target::num() [staticcall]
    │   └─ ← 2
    └─ ← ()

Test result: FAILED. 1 passed; 2 failed; 0 skipped; finished in 604.75µs

Ran 1 test suites: 1 tests passed, 2 failed, 0 skipped (3 total tests)

Failing tests:
Encountered 2 failing tests in test/Counter.t.sol:RevertTest
[FAIL. Reason: assertion failed] test_shouldFail() (gas: 19933)
[FAIL. Reason: assertion failed] test_shouldFaillWithRevert() (gas: 22400)

Encountered a total of 2 failing tests, 1 tests succeeded

[Evalir]

hey @anna-carroll we've added some fixes regarding this—is this still happening?

[Evalir]

Closing—tested a few times and can't reproduce anymore. Feel free to reopen if you see this behavior again!