vm.expectEmit is breaking in tests

[lyoungblood]

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 (08a629a 2023-06-03T00:14:26.563741000Z)

What command(s) is the bug in?

forge test -vvv

Operating System

Linux

Describe the bug

On the latest nightly build forge 0.2.0 (08a629a 2023-06-03T00:14:26.563741000Z) a test with vm.expectEmit(true, true, true, true, address(faucetToken)); throws an unexpected test failure:

Failing tests:
Encountered 1 failing test in tests-foundry/MErc20Delegate.t.sol:MErc20DelegateTest
[FAIL. Reason: Expected an emit, but no logs were emitted afterward. You might have mismatched events or not enough events were emitted.] testDelegatorMintWithPermit() (gas: 98067)

But on a previous build, forge 0.2.0 (200b3f4 2023-05-05T00:04:35.225055000Z) the same test succeeds:

Running 1 test for tests-foundry/MErc20Delegate.t.sol:MErc20DelegateTest
[PASS] testDelegatorMintWithPermit() (gas: 243217)
Test result: ok. 1 passed; 0 failed; finished in 20.64ms

The full trace of the failing test is:

Running 1 test for tests-foundry/MErc20Delegate.t.sol:MErc20DelegateTest
[FAIL. Reason: Expected an emit, but no logs were emitted afterward. You might have mismatched events or not enough events were emitted.] testDelegatorMintWithPermit() (gas: 98067)
Traces:
  [98067] MErc20DelegateTest::testDelegatorMintWithPermit() 
    ├─ [0] VM::addr(<pk>) [staticcall]
    │   └─ ← 0xe05fcC23807536bEe418f142D19fa0d21BB0cfF7
    ├─ [31394] FaucetTokenWithPermit::allocateTo(0xe05fcC23807536bEe418f142D19fa0d21BB0cfF7, 1000000000000000000 [1e18]) 
    │   ├─ emit Transfer(from: 0x0000000000000000000000000000000000000000, to: 0xe05fcC23807536bEe418f142D19fa0d21BB0cfF7, value: 1000000000000000000 [1e18])
    │   ├─ emit Transfer(from: FaucetTokenWithPermit: [0xF62849F9A0B5Bf2913b396098F7c7019b51A820a], to: 0xe05fcC23807536bEe418f142D19fa0d21BB0cfF7, value: 1000000000000000000 [1e18])
    │   └─ ← ()
    ├─ [585] FaucetTokenWithPermit::balanceOf(0xe05fcC23807536bEe418f142D19fa0d21BB0cfF7) [staticcall]
    │   └─ ← 1000000000000000000 [1e18]
    ├─ [11693] MErc20Delegator::balanceOf(0xe05fcC23807536bEe418f142D19fa0d21BB0cfF7) [staticcall]
    │   ├─ [9003] MErc20Delegator::delegateToImplementation(0x70a08231000000000000000000000000e05fcc23807536bee418f142d19fa0d21bb0cff7) [staticcall]
    │   │   ├─ [2664] MErc20Delegate::balanceOf(0xe05fcC23807536bEe418f142D19fa0d21BB0cfF7) [delegatecall]
    │   │   │   └─ ← 0
    │   │   └─ ← 0x0000000000000000000000000000000000000000000000000000000000000000
    │   └─ ← 0
    ├─ [3307] SigUtils::getTypedDataHash((0xe05fcC23807536bEe418f142D19fa0d21BB0cfF7, 0xa0Cb889707d426A7A386870A03bc70d1b0697598, 1000000000000000000 [1e18], 0, 60)) [staticcall]
    │   └─ ← 0x49345408dd9aeed9b3f6faaf9e69dda27c5ff2cb0a911bbb034696bb8ab0ec5f
    ├─ [0] VM::sign(<pk>, 0x49345408dd9aeed9b3f6faaf9e69dda27c5ff2cb0a911bbb034696bb8ab0ec5f) [staticcall]
    │   └─ ← 28, 0x2aacf1c69c85f4ea906db4e805768a09834d5fa5f8e1ffc903c58f01546b4c29, 0x2c4358cc06c878398786959411792542ed5969980d1fd765d3c88a0b95ca82ed
    ├─ [0] VM::expectEmit(true, true, true, true, FaucetTokenWithPermit: [0xF62849F9A0B5Bf2913b396098F7c7019b51A820a]) 
    │   └─ ← ()
    ├─ emit Approval(owner: 0xe05fcC23807536bEe418f142D19fa0d21BB0cfF7, spender: MErc20Delegator: [0xa0Cb889707d426A7A386870A03bc70d1b0697598], value: 1000000000000000000 [1e18])
    ├─ [0] VM::prank(0xe05fcC23807536bEe418f142D19fa0d21BB0cfF7) 
    │   └─ ← ()
    ├─ [26281] MErc20Delegator::approve(0x0000000000000000000000000000000000000000, 1) 
    │   ├─ [24571] MErc20Delegate::approve(0x0000000000000000000000000000000000000000, 1) [delegatecall]
    │   │   ├─ emit Approval(owner: 0xe05fcC23807536bEe418f142D19fa0d21BB0cfF7, spender: 0x0000000000000000000000000000000000000000, value: 1)
    │   │   └─ ← true
    │   └─ ← true
    └─ ← "Log != expected log"

Test result: FAILED. 0 passed; 1 failed; finished in 4.35ms

I don't want to include the complete test, but the section with breakage looks like this:

        // Ensure an Approval event was emitted as expected
        vm.expectEmit(true, true, true, true, address(faucetToken));
        emit Approval(user, address(mToken), 1e18);

        vm.prank(user);
        mErc20Delegator.approve(address(0), 1);

        // Ensure an Mint event was emitted as expected
        vm.expectEmit(true, true, true, true, address(mToken));
        emit Mint(user, 1e18, 1e18);

        // Ensure an Transfer event was emitted as expected
        vm.expectEmit(true, true, true, true, address(mToken));
        emit Transfer(address(mToken), user, 1e18);

        // Go mint as a user with permit
        vm.prank(user);
        mErc20Delegator.mintWithPermit(1e18, deadline, v, r, s);

Thanks for your help with this issue!

[Evalir]

Hey @lyoungblood thanks for this! I believe this change has to do with #4920 — from what I can see here, it's not super clear but it looks like you might have an ordering issue from what I see in the traces?

It's worth mentioning that the behavior now is that events are expected to be emitted in the next call. So if you're matching multiple events across multiple calls, you need to "declare" the events to be matched before the call were they're going to be emitted.

If you think this is actually a bug, could you maybe provide a more minimal repro? I'm 100% happy to look into this, just can' determine it from looking at these traces.

[Evalir]

Closing—stale and could not reproduce, plus further QA seems this is correct.

[PaulRBerg]

This might be a genuine bug - I'm in the same boat as @lyoungblood.

I'm as confident a person can be that there's no additional non-static call (methodList is static) between expectEmit and the call whereby the event is expected to be emitted. This can also be seen in the console logs:

emit InstallPlugin(owner: Alice: [0xBf0b5A4099F0bf6c8bC4252eBeC548Bae95602Ea], proxy: PRBProxy: [0xd462e9352b6793b5CB1aFeB8632880462C6bec3f], plugin: PluginDummy: [0x5615dEB798BB3E4dFa0139dFa1b3D433Cc23b72f])
    ├─ [52180] Registry::installPlugin(PluginDummy: [0x5615dEB798BB3E4dFa0139dFa1b3D433Cc23b72f])
    │   ├─ [871] PluginDummy::methodList()
    │   │   └─ ← [0xc2985578, 0xfebb0f7e]
    │   ├─ emit InstallPlugin(owner: Alice: [0xBf0b5A4099F0bf6c8bC4252eBeC548Bae95602Ea], proxy: PRBProxy: [0xd462e9352b6793b5CB1aFeB8632880462C6bec3f], plugin: PluginDummy: [0x5615dEB798BB3E4dFa0139dFa1b3D433Cc23b72f])
    │   └─ ← ()

As you can see, all event arguments match. You can see the full logs here.

I think I know what's going on. The bug started to occur only after adding two more indexed parameters in the event; with only one indexed parameter, the test was passing (even now, with the latest Foundry version). And, with two params, the bug still occurs.

@lyoungblood seems also to have had multiple indexed params.

[Evalir]

Hmmm interesting—I've tried to reproduce this but can't—do you think you can give a smol repro @PaulRBerg ? I think I might know what's going on here but need something I can test against.

[PaulRBerg]

@Evalir sure, here's a repo:

https://github.com/PaulRBerg/prb-proxy/blob/37dc8be6cb6eefce0b8199cdd8a942ee5f56350c/test/registry/install-plugin/installPlugin.t.sol#L72-L77

See the refactor/storage-redesign branch.

[Evalir]

Aight ser @PaulRBerg — I took a quick look at this, and it seems like events do differ.

The emitted event for the test is the following one:

    event InstallPlugin(address owner, IPRBProxy proxy, IPRBProxyPlugin indexed plugin);

While the emitted test on the registry is this one:

    event InstallPlugin(address indexed owner, IPRBProxy indexed proxy, IPRBProxyPlugin indexed plugin);

The event emitted in the test only has one indexed param, but the event emitted from the contract has 3. expectEmit will consider these 2 as different events, so I believe this is correct behavior. Do you think it should not be the case? Also @mds1 can chime on this

[mds1]

I agree that if indexed params differ they should be considered different, so a solution here is probably just to make this easier to catch and have a better failure message. Ref #592 (comment)

[PaulRBerg]

Oh my! I'm sorry for the false alarm, @Evalir. Thanks for tracking the cause down.

I agree with both of you that Foundry should consider these as different events (since the event topics would be different, I think).

And I also agree that the solution is to throw a more specific error message.

[Evalir]

No problem @PaulRBerg — glad this was just a false alarm haha. I definitely agree—we should give #592 a go and try to be more specific on what failed.

I'll close this, and let's keep the convo going on 592!