feat(forge): add cheatcodes vm.recordLogs() and vm.getRecordedLogs() #2161

bentobox19 · 2022-06-29T17:20:51Z

Overview

The methods vm.recordLogs() and vm.getRecordedLogs() provide the tester the ability to leverage information from the events emitted during the execution of a transaction.

Ref: #543

Motivation

While porting solutions from the CTF Ethernaut to Foundry, got bumped by the fact that when you create a challenge, you are calling the Ethernaut.sol contract with the address of the factory of the challenge you want to solve. Ethernaut.sol will invoke the factory, deploy a new challenge for you, and return the address of this new contract within an event LevelInstanceCreatedLog(address indexed player, address instance).

In practical terms, one can just modify the Ethernaut contract to return you the address instead of emitting such event, but, this is a motivation to just build the feature into Foundry!

Solution

Implement vm.captureLogs(): Function mirroring vm.record().
Implement vm.getRecordedLogs(): Function mirroring vm.accesses().

onbjerg

Small comments, thanks for taking this on 😄

testdata/cheats/CaptureLogs.t.sol

onbjerg · 2022-07-01T12:13:57Z

testdata/cheats/Cheats.sol

+    // Captures all the transaction logs
+    function captureLogs() external;
+    // Gets (and consumes) the next captured transaction log
+    function nextCapturedLog() external returns (bytes32[] memory topics,bytes memory data);


What's the primary reasoning for this cheatcode vs. something like vm.getLogs() and popping/indexing off of the returned array?

Hey @onbjerg I really appreciate your early review of this draft!

I'll do my best to be succint.

Disclaimer I'll do once: I have less than a week of experience in the marriage of Rust+Solidity 😅 !!! There are many features or patterns I ignore, and I'm most likely to propose stuff you already discussed and discarded. But well, there's only one way to start any jouney.

Background

Initially I wanted something very simple™ and give the tester all the parsing work. After all, what I wanted as a feature is the ability to capture logs, leaving the UX problem as a future issue.

Analysis

What do we give to the tester if we invoke vm.getLogs?

Should it be a bytes32[][]. Maybe... But wait! data is not necessarily constained to 32 bytes!

So you have somehow an array of (bytes32[], bytes). Can we do that? 🤔

If we can't do above, can we just take the content of a RawLog, do a (bytes32[], bytes) tuple, abi.encode it into a bytes field and then return a bytes[] ? Seems cumbersome... Why don't we just go low-level and get the first log of the list in the simplest format we can afford?

So in the end, I ended up thinking in UX!

Proposal

Having as cheatcodes vm.captureLogs() and vm.nextCapturedLog() within forge.

Then you just, in a FIFO fashion, take the first log from the list, leaving the next one in queue.

vm.nextCapturedLog() gives you back a (bytes32[], bytes). The tester needs to do some quick decoding such as abi.decode(data, (string)).

Still working on how to work the Topic 0. For now its processing is to be at the tester discretion.

Create later some wrapper at forge-std to getLogs(). This or these function(s) would be iterating over nextCapturedLog, taking care of indexing and decoding aspects.

Wrapping up

My final goal is to be able to port the Ethernaut challenge into forge. I need the feature of capturing (and then reading those captured) logs. Let's take advantage we currently have some capacity on implementing this, and let's look towards the best solution 🙂

Thanks for this info! I had the same thought as @onbjerg when looking at this. IMO I think the best UX would be something like this:

interface Vm { // Records all transaction logs so they can be retrieved later. function recordLogs() external; // Returns an array of the recorded logs. `accessLog` is consistent with `accesses`, even // though semantics are a bit different. In general I don't feel strongly about all // the cheatcode names function accessLogs() external returns ((bytes32[] memory topics, bytes memory data)[]); // Similar alternative. struct Log { bytes32[] topics; bytes data; } function logs() external returns (Log[] memory); }

I don't personally see a big need for a cheatcode to access the next log, as opposed to just returning the full array and having the user loop through it or access a particular index. Providing the whole array instead is also nice because you if you know the index of an expected event it's cleaner to access it.

Thanks for the write-up @bentobox19! Don't worry about being new to Rust + Solidity, we'll help you if you need 😄 Looks good so far.

I agree with @mds1's 2nd proposal here: it would be entirely feasible (and imo preferable) to return Log structs. The nice thing about having it return all logs it captured between recordLogs and logs (or accessLogs, not sure what the best name is) is that helper "cheatcodes" like nextLog can be built on top in Forge Std or other libraries 😄

So I would definitely propose that you:

Remove the nextCapturedLog cheatcode

Replace it with a logs or accessLogs (still not sure about naming) that returns Log[]

A note on behavior of the logs cheatcode: I think it should return all logs between the call to recordLogs and the call to logs. After this the internal buffer should be cleared - in other words, the combination of these two cheatcodes define the range in which the logs were emitted, if that makes sense?

Thank you @mds1 and @onbjerg onbjerg for your prompt feedback: I am renaming to

// Record all the transaction logs function recordLogs() external; // Gets all the recorded logs function getRecordedLogs() external returns ((bytes32[] memory topics, bytes memory data)[]);

Let's pass on getLogs(), to avoid any potential confusion of the testers with the RPC method eth_getLogs 🤷‍♂️

bentobox19 · 2022-07-01T18:02:28Z

Hey @onbjerg I went a bit verbose here: #2161 (comment)

Really open to discuss it until we converge into a solution. So far, it's been a very instructive experience where you have to reason in Rust, and low level Solidity all in a single package.

evm/src/executor/abi.rs

bentobox19 · 2022-07-03T03:36:50Z

In the end I went with

    struct Log {bytes32[] topics; bytes data;}
    function recordLogs() external;
    function getRecordedLogs() external returns (Log[] memory);

The compilers weren't very friendly with

    function getRecordedLogs() external returns ((bytes32[] memory topics, bytes memory data)[]);

So, the common flow is, for example

        cheats.recordLogs();
        emitter.emitEvent(1, 2, 3, "some data");
        Cheats.Log[] memory entries = cheats.getRecordedLogs();

        assertEq(entries.length, 1);
        assertEq(entries[0].topics.length, 4);
        assertEq(entries[0].topics[0], keccak256("LogTopic123(uint256,uint256,uint256,bytes)"));
        assertEq(entries[0].topics[1], bytes32(uint256(1)));
        assertEq(entries[0].topics[2], bytes32(uint256(2)));
        assertEq(entries[0].topics[3], bytes32(uint256(3)));
        assertEq(abi.decode(entries[0].data, (string)), string("some data"));

On the last assertion, even if the data is not a string, but a bytes variable, assertEq wants to work with the former.

The PR!

Alright. I'm setting this PR on:

I'm satisfied with the working of both cheatcodes, I was driven by the tests at RecordLogs.t.sol.
One of the tests uncovered a bug on anonymous events. I'd like this to be filled as a separate issue.

Thank you.

gakonst · 2022-07-04T20:36:32Z

@bentobox19 this looks good - can you explain why we panic on anonymous events?

Defer to @mds1 on the interface being exposed, I like it

bentobox19 · 2022-07-05T01:34:45Z

Hey @gakonst

can you explain why we panic on anonymous events?

This is my output when runing the test

[ bentobox: testdata ]$ ../target/debug/forge test -c cheats/RecordLogs.t.sol --match-test testRecordOnAnonymousEvent -vvvv
[⠑] Compiling...
No files changed, compilation skipped

Running 1 test for cheats/RecordLogs.t.sol:RecordLogsTest
[PASS] testRecordOnAnonymousEvent() (gas: 46536)
The application panicked (crashed).
Message:  index out of bounds: the len is 0 but the index is 0
Location: /Users/bentobox/foundry/evm/src/trace/decoder.rs:299

This is a bug. Consider reporting it at https://github.com/foundry-rs/foundry

Backtrace omitted. Run with RUST_BACKTRACE=1 environment variable to display it.
Run with RUST_BACKTRACE=full to include source snippets.

bentobox19 · 2022-07-05T02:57:47Z

@gakonst

I filled an issue with the panic bug here: #2206

Anonymous events fail at verbosity 4+.

onbjerg

Small nits. Regarding my comments on the API/behavior, I would give @mds1 final word on it since he is more in touch with actually using it (I don't write much Solidity these days)

onbjerg · 2022-07-05T08:15:01Z

evm/src/executor/inspector/cheatcodes/mod.rs

@@ -74,6 +74,9 @@ pub struct Cheatcodes {
    /// Recorded storage reads and writes
    pub accesses: Option<RecordAccess>,

+    /// Recorded logs
+    pub recorded_logs: Option<RecordedLogs>,


Might be better to have a boolean indicating whether we are recording or not so you can do something like:

vm.recordLogs(); // some calls (lets say call a, b and c) vm.getRecordedLogs(); // gets logs for calls a, b and c // perform call d and call e vm.getRecordedLogs(); // gets logs for calls d and e

Additionally I think a call to vm.getRecordedLogs should only return logs between the call to getRecordedLogs and the previous call to recordLogs or getRecordedLogs to allow for the pattern above. Currently this is the behavior:

vm.recordLogs(); // some calls (lets say call a, b and c) vm.getRecordedLogs(); // gets logs for calls a, b and c // perform call d and call e vm.getRecordedLogs(); // gets logs for calls a, b, c, d and e

To discard logs for the first 3 calls you would have to call recordLogs again to reset the buffer

onbjerg · 2022-07-05T08:15:31Z

evm/src/executor/inspector/cheatcodes/env.rs

+    state.recorded_logs = Some(Default::default());
+}
+
+fn get_recorded_logs(state: &mut Cheatcodes) -> Bytes {


Imo this should clear the state.recorded_logs vec (see reasoning below)

Will clone state.recorded_logs and then call start_record_logs() to reset them.

You can also use std::mem::take instead

onbjerg · 2022-07-05T08:18:34Z

evm/src/executor/inspector/cheatcodes/env.rs

+            .map(|entry| {
+                Token::Tuple(
+                    [
+                        Token::Array(


Vec<H256> and Vec<u8> implement the Tokenizable trait, which also means it implements the Tokenize trait, so I think it should be possible to just call entry.topics.into_tokens() and entry.data.into_tokens()?

Some hair pulling here, but managed to refashion this part of the code

ethers::abi::encode( &recorded_logs .entries .iter() .map(|entry| { Token::Tuple(vec![ entry.topics.clone().into_token(), Token::Bytes(entry.data.clone()), ]) }) .collect::<Vec<Token>>() .into_tokens(), ) .into()

Sample output object:

This maps to (bytes32[], bytes)[] or Log[] with struct Log {bytes32[] topics; bytes data;}

[ Tuple([ Array([ FixedBytes([97, 251, 125, ...]), FixedBytes([... 0, 1])]), Bytes([... 128, 64, 178, 137, 171, 233, 51, 52, 165, 227, ...])]), Tuple([ Array([ FixedBytes([122, 249, 45, ...]), FixedBytes([... 0, 2]), FixedBytes([... 0, 3])]), Bytes([... 171, 233, 51, 52, 165, 227, 102, 39, 81, 170, ...])]), ...

Using both .into_token() and into_tokens().

into_tokens() gives you as output a [Array[ ....

entry.data.clone().into_token() will give you Array([Uint(0), Uint(0), instead of the desired Bytes([0, 0, 0, 0, 0,

bentobox19 · 2022-07-05T12:35:23Z

Thank you for your feedback @onbjerg. We wait for @mds1 comments then?

mds1 · 2022-07-05T13:20:36Z

@bentobox19 The proposed API looks great to me, thank you! 👌

bentobox19 · 2022-07-05T13:27:35Z

EDIT: @mds1 , Are we keeping the API that is currently at the PR, or should we implement the proposakl of @onbjerg

mds1 · 2022-07-05T13:33:19Z

Yea to clarify I think the below VM interfaces look good:

struct Log {bytes32[] topics; bytes data;}
function recordLogs() external;
function getRecordedLogs() external returns (Log[] memory);

And I think the above suggestion of behavior from @onbjerg is good too:

vm.recordLogs();
// some calls (lets say call a, b and c)
vm.getRecordedLogs(); // gets logs for calls a, b and c
// perform call d and call e
vm.getRecordedLogs(); // gets logs for calls d and e

gakonst · 2022-07-05T16:59:36Z

Great - let's address the @onbjerg code review comments, and given we like the API we can get it over the line!

bentobox19 · 2022-07-05T18:48:31Z

@mds1 @onbjerg changes implemented.

onbjerg

smallest nit (see https://doc.rust-lang.org/std/option/enum.Option.html#method.replace)

evm/src/executor/inspector/cheatcodes/env.rs

onbjerg

Rebased, looks good to merge when CI passes 😄 Great job!

onbjerg · 2022-07-06T18:07:17Z

Any final comments on API @gakonst / @mds1? Otherwise this can be merged :)

mds1 · 2022-07-06T18:11:43Z

Nope, this LGTM!

Thank you @bentobox19! 🎉

gakonst

Awesome. Fantastic. Let's document it in the book?

bentobox19 · 2022-07-06T19:01:06Z

@gakonst I can send a PR to the book repository today

…oundry-rs#2161) * feat(forge): add cheatcodes vm.recordLogs() and vm.getRecordedLogs() * refashion response of vm.getRecordedLogs() * recorded logs get consumed after being read * chore: nits * chore: fmt Co-authored-by: Bjerg <onbjerg@users.noreply.github.com> Co-authored-by: Oliver Nordbjerg <hi@notbjerg.me>

bentobox19 · 2022-07-08T05:31:01Z

@gakonst foundry-rs/book#427

bentobox19 mentioned this pull request Jun 29, 2022

getting values of emitted events #543

Closed

bentobox19 changed the title ~~Add vm.captureLogs() cheatcode~~ feat(forge): add cheatcodes vm.captureLogs() and vm.nextCapturedLog() Jul 1, 2022

onbjerg reviewed Jul 1, 2022

View reviewed changes

mds1 reviewed Jul 1, 2022

View reviewed changes

evm/src/executor/abi.rs Outdated Show resolved Hide resolved

onbjerg mentioned this pull request Jul 1, 2022

Add checkEmit cheatcode to test past log emission #1906

Closed

onbjerg linked an issue Jul 1, 2022 that may be closed by this pull request

getting values of emitted events #543

Closed

onbjerg added the T-feature Type: feature label Jul 1, 2022

bentobox19 changed the title ~~feat(forge): add cheatcodes vm.captureLogs() and vm.nextCapturedLog()~~ feat(forge): add cheatcodes vm.recordLogs() and vm.getRecordedLogs() Jul 1, 2022

bentobox19 marked this pull request as ready for review July 3, 2022 03:37

onbjerg requested changes Jul 5, 2022

View reviewed changes

onbjerg requested changes Jul 6, 2022

View reviewed changes

evm/src/executor/inspector/cheatcodes/env.rs Outdated Show resolved Hide resolved

evm/src/executor/inspector/cheatcodes/env.rs Outdated Show resolved Hide resolved

bentobox19 and others added 5 commits July 6, 2022 17:23

feat(forge): add cheatcodes vm.recordLogs() and vm.getRecordedLogs()

c648cb2

refashion response of vm.getRecordedLogs()

fc18b2a

recorded logs get consumed after being read

75daaa6

chore: nits

448b56a

chore: fmt

4a9d08b

onbjerg approved these changes Jul 6, 2022

View reviewed changes

gakonst approved these changes Jul 6, 2022

View reviewed changes

gakonst merged commit e0fecc3 into foundry-rs:master Jul 6, 2022

mds1 mentioned this pull request Jul 6, 2022

feat: add log cheatcodes and types foundry-rs/forge-std#107

Merged

bentobox19 deleted the feature/capture-logs branch July 6, 2022 18:57

bentobox19 mentioned this pull request Jul 8, 2022

Add documentation for cheatcodes vm.recordLogs() and vm.getRecordedLogs() foundry-rs/book#427

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat(forge): add cheatcodes vm.recordLogs() and vm.getRecordedLogs() #2161

feat(forge): add cheatcodes vm.recordLogs() and vm.getRecordedLogs() #2161

bentobox19 commented Jun 29, 2022 •

edited

onbjerg left a comment

onbjerg Jul 1, 2022

bentobox19 Jul 1, 2022 •

edited

mds1 Jul 1, 2022 •

edited

onbjerg Jul 1, 2022

bentobox19 Jul 1, 2022

bentobox19 commented Jul 1, 2022 •

edited

bentobox19 commented Jul 3, 2022

gakonst commented Jul 4, 2022

bentobox19 commented Jul 5, 2022 •

edited

bentobox19 commented Jul 5, 2022

onbjerg left a comment

onbjerg Jul 5, 2022

onbjerg Jul 5, 2022

bentobox19 Jul 5, 2022 •

edited

onbjerg Jul 6, 2022

onbjerg Jul 5, 2022

bentobox19 Jul 5, 2022

bentobox19 commented Jul 5, 2022

mds1 commented Jul 5, 2022

bentobox19 commented Jul 5, 2022 •

edited

mds1 commented Jul 5, 2022

gakonst commented Jul 5, 2022

bentobox19 commented Jul 5, 2022

onbjerg left a comment

onbjerg left a comment

onbjerg commented Jul 6, 2022

mds1 commented Jul 6, 2022 •

edited

gakonst left a comment

bentobox19 commented Jul 6, 2022

bentobox19 commented Jul 8, 2022

feat(forge): add cheatcodes vm.recordLogs() and vm.getRecordedLogs() #2161

feat(forge): add cheatcodes vm.recordLogs() and vm.getRecordedLogs() #2161

Conversation

bentobox19 commented Jun 29, 2022 • edited

Overview

Motivation

Solution

onbjerg left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bentobox19 Jul 1, 2022 • edited

Choose a reason for hiding this comment

Background

Analysis

Proposal

Wrapping up

mds1 Jul 1, 2022 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bentobox19 commented Jul 1, 2022 • edited

bentobox19 commented Jul 3, 2022

The PR!

gakonst commented Jul 4, 2022

bentobox19 commented Jul 5, 2022 • edited

bentobox19 commented Jul 5, 2022

onbjerg left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bentobox19 Jul 5, 2022 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bentobox19 commented Jul 5, 2022

mds1 commented Jul 5, 2022

bentobox19 commented Jul 5, 2022 • edited

mds1 commented Jul 5, 2022

gakonst commented Jul 5, 2022

bentobox19 commented Jul 5, 2022

onbjerg left a comment

Choose a reason for hiding this comment

onbjerg left a comment

Choose a reason for hiding this comment

onbjerg commented Jul 6, 2022

mds1 commented Jul 6, 2022 • edited

gakonst left a comment

Choose a reason for hiding this comment

bentobox19 commented Jul 6, 2022

bentobox19 commented Jul 8, 2022

bentobox19 commented Jun 29, 2022 •

edited

bentobox19 Jul 1, 2022 •

edited

mds1 Jul 1, 2022 •

edited

bentobox19 commented Jul 1, 2022 •

edited

bentobox19 commented Jul 5, 2022 •

edited

bentobox19 Jul 5, 2022 •

edited

bentobox19 commented Jul 5, 2022 •

edited

mds1 commented Jul 6, 2022 •

edited