vm.warp changes block.timestamp in test contract but not in contracts-under-test

[webthethird]

Component

Forge

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

• Foundry
• Foundryup

What version of Foundry are you on?

forge 0.0.2 (532ef5e 2024-04-22T00:21:35.201114596Z)

What command(s) is the bug in?

forge test

Operating System

Linux

Describe the bug

I was getting some weird behavior while testing a limit order book contract, which stores orders with an expiry timestamp, when testing for expired orders. So I set up a minimal reproducible example, and found a discrepancy between block.timestamp when read in the test contract (Expiry.t.sol) vs. when it is read in the contract-under-test (Expiry.sol). The contracts are as follows:

contract Expiry {
    uint256 public expiry;

    constructor() {
        expiry = block.timestamp;
    }

    function setExpiry(uint256 _expiry) public {
        console.log("Expiry.setExpiry: block.timestamp = %s", block.timestamp);
        console.log("Expiry.setExpiry: expiry (before) = %s", expiry);
        expiry = _expiry;
        console.log("Expiry.setExpiry: expiry (after) = %s", expiry);
    }

    function isExpired() public view returns (bool) {
        console.log("Expiry.isExpired: block.timestamp = %s", block.timestamp);
        console.log("Expiry.isExpired: expiry = %s", expiry);

        return block.timestamp >= expiry;
    }
}

contract ExpiryTest is Test {
    Expiry public e;

    function setUp() public {
        e = new Expiry();
    }

    function test_Expiry() public {
        console.log("ExpiryTest: block.timestamp = %s", block.timestamp);
        e.setExpiry(block.timestamp + 1 days);
        console.log("ExpiryTest: block.timestamp = %s", block.timestamp);
        assertFalse(e.isExpired());
        console.log("ExpiryTest: block.timestamp = %s", block.timestamp);
        skip(1 days);
        console.log("ExpiryTest: block.timestamp = %s", block.timestamp);
        assertTrue(e.isExpired());
    }
}

The resulting logs and traces are:

Ran 1 test for test/Expiry.t.sol:ExpiryTest
[FAIL. Reason: assertion failed] test_Expiry() (gas: 15528)
Logs:
  ExpiryTest: block.timestamp = 1
  Expiry.setExpiry: block.timestamp = 2
  Expiry.setExpiry: expiry (before) = 1
  Expiry.setExpiry: expiry (after) = 86401
  ExpiryTest: block.timestamp = 1
  Expiry.isExpired: block.timestamp = 3
  Expiry.isExpired: expiry = 86401
  ExpiryTest: block.timestamp = 1
  ExpiryTest: block.timestamp = 86401
  Expiry.isExpired: block.timestamp = 4
  Expiry.isExpired: expiry = 86401

Traces:
  [15528] ExpiryTest::test_Expiry()
    ├─ [0] console::log("ExpiryTest: block.timestamp = %s", 1) [staticcall]
    │   └─ ← ()
    ├─ [0] 0xB5c1DF089600415B21FB76bf89900Adb575947c8::setExpiry(86401 [8.64e4])
    │   └─ ← ()
    ├─ [0] console::log("ExpiryTest: block.timestamp = %s", 1) [staticcall]
    │   └─ ← ()
    ├─ [0] 0xB5c1DF089600415B21FB76bf89900Adb575947c8::isExpired() [staticcall]
    │   └─ ← false
    ├─ [0] VM::assertFalse(false) [staticcall]
    │   └─ ← ()
    ├─ [0] console::log("ExpiryTest: block.timestamp = %s", 1) [staticcall]
    │   └─ ← ()
    ├─ [0] VM::warp(86401 [8.64e4])
    │   └─ ← ()
    ├─ [0] console::log("ExpiryTest: block.timestamp = %s", 86401 [8.64e4]) [staticcall]
    │   └─ ← ()
    ├─ [0] 0xB5c1DF089600415B21FB76bf89900Adb575947c8::isExpired() [staticcall]
    │   └─ ← false
    ├─ [0] VM::assertTrue(false) [staticcall]
    │   └─ ← assertion failed
    └─ ← assertion failed

Suite result: FAILED. 0 passed; 1 failed; 0 skipped; finished in 25.62ms (14.68ms CPU time)

Two things about the logs strike me as odd:

• In the context of Expiry, block.timestamp is incrementing by 1 after every call from the test contract, though it does not increment in the context of ExpiryTest.
• After calling skip(1 days) in the test contract (which calls vm.warp under the hood), block.timestamp is updated correctly in the context of ExpiryTest but is unaffected in the context of Expiry.

The expected behavior would result in the following logs instead:

Logs:
  ExpiryTest: block.timestamp = 1
  Expiry.setExpiry: block.timestamp = 1
  Expiry.setExpiry: expiry (before) = 1
  Expiry.setExpiry: expiry (after) = 86401
  ExpiryTest: block.timestamp = 1
  Expiry.isExpired: block.timestamp = 1
  Expiry.isExpired: expiry = 86401
  ExpiryTest: block.timestamp = 1
  ExpiryTest: block.timestamp = 86401
  Expiry.isExpired: block.timestamp = 86401
  Expiry.isExpired: expiry = 86401

Minimal reproducible example repo
Note: I am not using via-ir in this minimal example, though I do need to use it in the limit order repo I'm working on, because certain dependencies from matterlabs/era-contracts throw stack-too-deep compilation errors otherwise. I am aware of the potential issues from using vm.warp and block.timestamp with via-ir, which is (or at least was) a general issue with foundry, but this seems to be something different.

[webthethird]

@dutterbutter Any updates on this issue? This discrepancy between timestamps is preventing me from testing a significant chunk of my limit order contract.