feat(forge): enable console logging in invariant handlers

[PaulRBerg]

Component

Forge

Describe the feature you would like

It would be useful to be able to use console2.log in invariant handlers, e.g.

function MyInvariantTest is StdInvariant {
    Handler internal handler = new Handler();
    function setUp() public virtual {
        targetContract(address(handler));
    }
}

contract Handler {
    function doSomething() external {
        console2.log("Hello World");
    }
}

This code does not console log "Hello World" at the moment.

Additional context

No response

[lucas-manuel]

Agreed would like to see this as well.

[0xfarhaan]

+1 would like to see this

[PaulRBerg]

As brainstormed in person with @gakonst and @lucas-manuel, what we actually want here might be a new cheat vm.exit which exits the invariant campaign and console logs the user-provided message.

[Evalir]

Would love to flesh this out a tad more @PaulRBerg 👀

[mds1]

As brainstormed in person with @gakonst and @lucas-manuel

big fomo inducing sentence 😭

---

Also curious to hear more though, I don't think I understand the use case or suggestion—why is exiting the campaign early preferable over a standard console log?

[lucas-manuel]

From what I remember in the earlier discussions about adding logs to invariant tests was that it had a big effect on performance, we were trying to think of ways around this.

Is there any way to isolate just console.log output rather than the whole stack trace?

[mds1]

@Evalir @gakonst Would replacing the console.log solidity library with native vm.print cheats help with performance? The assumption being that intercepting cheat calls is cheaper than tracing the console calls

[Evalir]

i've been fiddling with this issue today and I've observed this—doing this the "obvious" way (just preserving logs and decoding them later) introduces a huge performance hit. I'm not super sure how a native cheatcode would look, as in the end we've got to recover the logs from the last call and decode them. I might need to think about this a tad more, but I feel that "rerouting" log output might require redesigning how we retrieve logs/traces a bit cc @mattsse

[PaulRBerg]

Would love to flesh this out a tad more @PaulRBerg 👀

The problem with the standard calls in invariant campaigns is two-fold:

1. They produce a bunch of logs, whereas the Foundry user might be interested to debug only the first run that reverts. The lack of corpus saving and replay (ref feat: fuzz corpus saving and replay in standard format #2552) is a related issue.
2. Performance issues (as @lucas-manuel said). In Sablier, we tried to use something like Lucas' invariant_call_summary, but the performance hit in CI was so significant that we removed quickly afterward.

However, implementing vm.exit is not mutually exclusive with supporting standard logs in invariants. It's just another way of debugging invariants.

[mds1]

whereas the Foundry user might be interested to debug only the first run that reverts.

Hm isn't this how console logs currently work for fuzz tests though? They only show up for a single run—the last run if all runs pass, or the failed run if a run failed

Performance issues make sense, though I'm still not understanding the UX/naming of vm.exit. Can you provide an example of what usage would look like? Is it calling vm.exit(string), logging the string, and then exiting "something"? Is that "something" the single run and continue to the next run, the individual test so it has no more runs, or the entire test suite?

If that's correct, presumably you'd also want #2985 support?

[PaulRBerg]

isn't this how console logs currently work for fuzz tests though? They only show up for a single run — the last run if all runs pass, or the failed run if a run failed

You are right. The actual scenario I had in my head was this:

You bumped into a failing invariant that you no longer observe, and you want to console log some state in a particular handler function, or at a particular depth.

Is it calling vm.exit(string), logging the string, and then exiting "something"?

Yes

Is that "something" the single run and continue to the next run

No, the invariants campaign will not move to the next run. As I've said above, you would add this vm.exit in a particular handler function, and potentially within an if block.

you'd also want #2985 support?

Absolutely

[lucas-manuel]

Hm isn't this how console logs currently work for fuzz tests though?

Forgive my lack of low-level understanding here haha but want to understand where the performance hit is coming from because yeah I think this is true^

Aren't invariants always run without logs and then in the case that they do fail they are re-run on the run that caused the failure? I understand with a large depth it would generate a large sequence of logs and maybe that's what it is. In this case, would setting verbosity to 2 help in any way with performance? Just so concole.log gets output?

Also @mds1 @Evalir is there an issue yet for outputting a seed that causes a run failure? It would be extremely useful to be able to debug with runs = 1 with that specific failing seed getting passed in.

[mds1]

Thanks @PaulRBerg, I think I understand now. So vm.exit + vm.depth would basically be an alternative way of logging, and the way you'd use it is to place the vm.exit call right before assertions that might cause failures, that way you can log data right before the failire? It seems that a performant console.log would remove the need for vm.exit? (but vm.depth is still useful).

If I'm still misunderstanding, would you mind provide a snippet of how vm.exit would look compared to a flow without vm.exit?

---

Aren't invariants always run without logs and then in the case that they do fail they are re-run on the run that caused the failure? I understand with a large depth it would generate a large sequence of logs and maybe that's what it is. In this case, would setting verbosity to 2 help in any way with performance? Just so concole.log gets output?

This is my understanding also

Also @mds1 @Evalir is there an issue yet for outputting a seed that causes a run failure? It would be extremely useful to be able to debug with runs = 1 with that specific failing seed getting passed in.

We have #2551 and #2552 for failure persistence, which should cover this use case. It's been a while since I've looked at those so feel free to leave any comments/suggestions there

[Evalir]

Hey all! Ton of discussion on this issue—heads up that we're implementing the requested feature (console log support) on #5488 ; happy to not close the issue if we wanna keep tracking the other requests here

[PaulRBerg]

So vm.exit + vm.depth would basically be an alternative way of logging, and the way you'd use it is to place the vm.exit call right before assertions that might cause failures, that way you can log data right before the failire

Yes, but not just before failures - it would be helpful for debugging purposes in general.

For example, in Sablier, we are creating up to 100 streams in every given invariant campaign. We might be interested in logging something when this threshold is hit for the first time.

It seems that a performant console.log would remove the need for vm.exit? (but vm.depth is still useful).

I would say that a performant console.log plus vm.depth would remove the need for vm.exit.