Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

feat(cheatcodes): mark unmatched expectedEmits as unemitted #8686

Draft
wants to merge 2 commits into
base: master
Choose a base branch
from
Draft

feat(cheatcodes): mark unmatched expectedEmits as unemitted #8686

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
50ddba2
feat(cheatcodes): mark unmatched expectedEmits as unemitted
topocount Aug 17, 2024
2d9590e
fix: address review from @klkvr
topocount Sep 17, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions Cargo.lock
View file
Open in desktop

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

3 changes: 3 additions & 0 deletions Cargo.toml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -231,6 +231,7 @@ chrono = { version = "0.4", default-features = false, features = [
"std",
] }
color-eyre = "0.6"
owo-colors = "3"
derive_more = { version = "1.0", features = ["full"] }
dunce = "1"
evm-disassembler = "0.5"
Expand Down Expand Up @@ -297,3 +298,5 @@ comfy-table = "7"
# alloy-transport-http = { git = "https://github.com/alloy-rs/alloy", rev = "7fab7ee" }
# alloy-transport-ipc = { git = "https://github.com/alloy-rs/alloy", rev = "7fab7ee" }
# alloy-transport-ws = { git = "https://github.com/alloy-rs/alloy", rev = "7fab7ee" }
# revm-inspectors = { path = "../revm-inspectors" }
# revm-inspectors = { git = "https://github.com/topocount/revm-inspectors", rev = "0ec9274" }
7 changes: 6 additions & 1 deletion crates/cheatcodes/assets/cheatcodes.json
View file
Open in desktop

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

3 changes: 3 additions & 0 deletions crates/cheatcodes/spec/src/vm.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,9 @@ interface Vm {
/// Error thrown by cheatcodes.
error CheatcodeError(string message);

/// Error thrown by unemitted events
error UnemittedEventError(uint16 positionExpected);

/// A modification applied to either `msg.sender` or `tx.origin`. Returned by `readCallers`.
enum CallerMode {
/// No caller modification is currently active.
Expand Down
18 changes: 14 additions & 4 deletions crates/cheatcodes/src/inspector.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,7 +22,7 @@ use crate::{
};
use alloy_primitives::{hex, Address, Bytes, Log, TxKind, B256, U256};
use alloy_rpc_types::request::{TransactionInput, TransactionRequest};
use alloy_sol_types::{SolCall, SolInterface, SolValue};
use alloy_sol_types::{SolCall, SolError, SolInterface};
use foundry_common::{evm::Breakpoints, TransactionMaybeSigned, SELECTOR_LEN};
use foundry_config::Config;
use foundry_evm_core::{
Expand Down Expand Up @@ -400,6 +400,8 @@ pub struct Cheatcodes {
pub expected_calls: ExpectedCallTracker,
/// Expected emits
pub expected_emits: VecDeque<ExpectedEmit>,
/// counter for expected emits that have been matched and cleared
pub expected_emits_offset: u16,

/// Map of context depths to memory offset ranges that may be written to within the call depth.
pub allowed_mem_writes: FxHashMap<u64, Vec<Range<u64>>>,
Expand Down Expand Up @@ -478,6 +480,7 @@ impl Cheatcodes {
mocked_functions: Default::default(),
expected_calls: Default::default(),
expected_emits: Default::default(),
expected_emits_offset: Default::default(),
allowed_mem_writes: Default::default(),
broadcast: Default::default(),
broadcastable_transactions: Default::default(),
Expand Down Expand Up @@ -1356,15 +1359,22 @@ impl<DB: DatabaseExt> Inspector<DB> for Cheatcodes {
!call.is_static;
if should_check_emits {
// Not all emits were matched.
if self.expected_emits.iter().any(|expected| !expected.found) {
if let Some(not_found) = self.expected_emits.iter().find(|expected| !expected.found) {
outcome.result.result = InstructionResult::Revert;
outcome.result.output = "log != expected log".abi_encode().into();
// Where the revert is set and where color mode might be
// indicated for a given event that wasn't matched
outcome.result.output = Vm::UnemittedEventError {
positionExpected: not_found.sequence + self.expected_emits_offset,
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this is incorrect as sequence only knows about events which came after expectEmit which might not always be the only events emitted during execution

I think we'd want to directly use tracing inspector indexes here, which should be possible after #8696

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

hey @topocount #8696 just got merged and CheatcodesExecutor was extended with tracing_inspector fn which provides a reference to a tracing inspector from which you can check the log indicies directly

that way sequence value can be just set to something like tracer.traces().nodes().last().expect("no trace nodes").logs.len()

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I should have time to work on this this week

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@klkvr I've added tracer.traces().nodes().last().expect("no trace nodes").logs.len() to expect_emit but still need the offset to cover an edge case where a prior call completes successfully, otherwise that prior call is erroneously highlighted red instead.

not_found.sequence holds the tracer length call from from when the expected emit payload is initially pushed onto the stack.

Copy link
Author

@topocount topocount Sep 17, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This comment is incorrect after my debugging outline below
hmm there are still edge cases that aren't satisfied by this, namely if multiple expectedEmits are added for a given call, the incorrect one (the one that is matched) is highlighted. I need to dig into this more.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

it doesn't look like this is incrementing. Is this array lazily constructed then?

that way sequence value can be just set to something like tracer.traces().nodes().last().expect("no trace nodes").logs.len()

Copy link
Author

@topocount topocount Sep 17, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Here's a debug trace where we're expecting the same event twice:

Click here 
[crates/cheatcodes/src/inspector.rs:1366:17] &self.expected_emits = [
    ExpectedEmit {
        depth: 1,
        log: Some(
            LogData {
                topics: [
                    0xf6ef72180c46cadbda80997bfa03fc39b76911c9bc988da15e4a47d55d687a31,
                ],
                data: 0x00000000000000000000000000000000000000000000000000000000000000010000000000000000000000000000000000000000000000000000000000000005,
            },
        ),
        checks: [
            true,
            false,
            false,
            false,
            true,
        ],
        address: Some(
            0x5615deb798bb3e4dfa0139dfa1b3d433cc23b72f,
        ),
        anonymous: false,
        found: false,
        sequence: 0,
    },
    ExpectedEmit {
        depth: 1,
        log: Some(
            LogData {
                topics: [
                    0xf6ef72180c46cadbda80997bfa03fc39b76911c9bc988da15e4a47d55d687a31,
                ],
                data: 0x00000000000000000000000000000000000000000000000000000000000000010000000000000000000000000000000000000000000000000000000000000005,
            },
        ),
        checks: [
            true,
            false,
            false,
            false,
            true,
        ],
        address: Some(
            0x5615deb798bb3e4dfa0139dfa1b3d433cc23b72f,
        ),
        anonymous: false,
        found: true,
        sequence: 0,
    },
]

}
.abi_encode()
.into();
return outcome;
} else {
// All emits were found, we're good.
// Clear the queue, as we expect the user to declare more events for the next call
// if they wanna match further events.
self.expected_emits.clear()
self.expected_emits_offset += self.expected_emits.len() as u16;
self.expected_emits.clear();
}
}

Expand Down
119 changes: 105 additions & 14 deletions crates/cheatcodes/src/test/expect.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,8 +1,11 @@
use crate::{Cheatcode, Cheatcodes, CheatsCtxt, DatabaseExt, Error, Result, Vm::*};
use crate::{
Cheatcode, Cheatcodes, CheatcodesExecutor, CheatsCtxt, DatabaseExt, Error, Result, Vm::*,
};
use alloy_primitives::{address, hex, Address, Bytes, LogData as RawLog, U256};
use alloy_sol_types::{SolError, SolValue};
use foundry_common::ContractsByArtifact;
use foundry_evm_core::decode::RevertDecoder;
use foundry_evm_traces::TracingInspector;
use revm::interpreter::{
return_ok, InstructionResult, Interpreter, InterpreterAction, InterpreterResult,
};
Expand Down Expand Up @@ -102,6 +105,8 @@ pub struct ExpectedEmit {
pub anonymous: bool,
/// Whether the log was actually found in the subcalls
pub found: bool,
/// the order in which the log was expected
pub sequence: u16,
}

impl Cheatcode for expectCall_0Call {
Expand Down Expand Up @@ -206,10 +211,20 @@ impl Cheatcode for expectCallMinGas_1Call {
}

impl Cheatcode for expectEmit_0Call {
fn apply_stateful<DB: DatabaseExt>(&self, ccx: &mut CheatsCtxt<DB>) -> Result {
fn apply_full<DB: DatabaseExt, E: CheatcodesExecutor>(
&self,
ccx: &mut CheatsCtxt<DB>,
executor: &mut E,
) -> Result {
let Self { checkTopic1, checkTopic2, checkTopic3, checkData } = *self;

let Some(tracer) = executor.tracing_inspector().and_then(|t| t.as_ref()) else {
return Ok(Default::default());
};

expect_emit(
ccx.state,
tracer,
ccx.ecx.journaled_state.depth(),
[true, checkTopic1, checkTopic2, checkTopic3, checkData],
None,
Expand All @@ -219,10 +234,19 @@ impl Cheatcode for expectEmit_0Call {
}

impl Cheatcode for expectEmit_1Call {
fn apply_stateful<DB: DatabaseExt>(&self, ccx: &mut CheatsCtxt<DB>) -> Result {
fn apply_full<DB: DatabaseExt, E: CheatcodesExecutor>(
&self,
ccx: &mut CheatsCtxt<DB>,
executor: &mut E,
) -> Result {
let Self { checkTopic1, checkTopic2, checkTopic3, checkData, emitter } = *self;
let Some(tracer) = executor.tracing_inspector().and_then(|t| t.as_ref()) else {
return Ok(Default::default());
};

expect_emit(
ccx.state,
tracer,
ccx.ecx.journaled_state.depth(),
[true, checkTopic1, checkTopic2, checkTopic3, checkData],
Some(emitter),
Expand All @@ -232,24 +256,53 @@ impl Cheatcode for expectEmit_1Call {
}

impl Cheatcode for expectEmit_2Call {
fn apply_stateful<DB: DatabaseExt>(&self, ccx: &mut CheatsCtxt<DB>) -> Result {
fn apply_full<DB: DatabaseExt, E: CheatcodesExecutor>(
&self,
ccx: &mut CheatsCtxt<DB>,
executor: &mut E,
) -> Result {
let Self {} = self;
expect_emit(ccx.state, ccx.ecx.journaled_state.depth(), [true; 5], None, false)
let Some(tracer) = executor.tracing_inspector().and_then(|t| t.as_ref()) else {
return Ok(Default::default());
};
expect_emit(ccx.state, tracer, ccx.ecx.journaled_state.depth(), [true; 5], None, false)
}
}

impl Cheatcode for expectEmit_3Call {
fn apply_stateful<DB: DatabaseExt>(&self, ccx: &mut CheatsCtxt<DB>) -> Result {
fn apply_full<DB: DatabaseExt, E: CheatcodesExecutor>(
&self,
ccx: &mut CheatsCtxt<DB>,
executor: &mut E,
) -> Result {
let Self { emitter } = *self;
expect_emit(ccx.state, ccx.ecx.journaled_state.depth(), [true; 5], Some(emitter), false)
let Some(tracer) = executor.tracing_inspector().and_then(|t| t.as_ref()) else {
return Ok(Default::default());
};
expect_emit(
ccx.state,
tracer,
ccx.ecx.journaled_state.depth(),
[true; 5],
Some(emitter),
false,
)
}
}

impl Cheatcode for expectEmitAnonymous_0Call {
fn apply_stateful<DB: DatabaseExt>(&self, ccx: &mut CheatsCtxt<DB>) -> Result {
fn apply_full<DB: DatabaseExt, E: CheatcodesExecutor>(
&self,
ccx: &mut CheatsCtxt<DB>,
executor: &mut E,
) -> Result {
let Self { checkTopic0, checkTopic1, checkTopic2, checkTopic3, checkData } = *self;
let Some(tracer) = executor.tracing_inspector().and_then(|t| t.as_ref()) else {
return Ok(Default::default());
};
expect_emit(
ccx.state,
tracer,
ccx.ecx.journaled_state.depth(),
[checkTopic0, checkTopic1, checkTopic2, checkTopic3, checkData],
None,
Expand All @@ -259,10 +312,18 @@ impl Cheatcode for expectEmitAnonymous_0Call {
}

impl Cheatcode for expectEmitAnonymous_1Call {
fn apply_stateful<DB: DatabaseExt>(&self, ccx: &mut CheatsCtxt<DB>) -> Result {
fn apply_full<DB: DatabaseExt, E: CheatcodesExecutor>(
&self,
ccx: &mut CheatsCtxt<DB>,
executor: &mut E,
) -> Result {
let Self { checkTopic0, checkTopic1, checkTopic2, checkTopic3, checkData, emitter } = *self;
let Some(tracer) = executor.tracing_inspector().and_then(|t| t.as_ref()) else {
return Ok(Default::default());
};
expect_emit(
ccx.state,
tracer,
ccx.ecx.journaled_state.depth(),
[checkTopic0, checkTopic1, checkTopic2, checkTopic3, checkData],
Some(emitter),
Expand All @@ -272,16 +333,37 @@ impl Cheatcode for expectEmitAnonymous_1Call {
}

impl Cheatcode for expectEmitAnonymous_2Call {
fn apply_stateful<DB: DatabaseExt>(&self, ccx: &mut CheatsCtxt<DB>) -> Result {
fn apply_full<DB: DatabaseExt, E: CheatcodesExecutor>(
&self,
ccx: &mut CheatsCtxt<DB>,
executor: &mut E,
) -> Result {
let Self {} = self;
expect_emit(ccx.state, ccx.ecx.journaled_state.depth(), [true; 5], None, true)
let Some(tracer) = executor.tracing_inspector().and_then(|t| t.as_ref()) else {
return Ok(Default::default());
};
expect_emit(ccx.state, tracer, ccx.ecx.journaled_state.depth(), [true; 5], None, true)
}
}

impl Cheatcode for expectEmitAnonymous_3Call {
fn apply_stateful<DB: DatabaseExt>(&self, ccx: &mut CheatsCtxt<DB>) -> Result {
fn apply_full<DB: DatabaseExt, E: CheatcodesExecutor>(
&self,
ccx: &mut CheatsCtxt<DB>,
executor: &mut E,
) -> Result {
let Self { emitter } = *self;
expect_emit(ccx.state, ccx.ecx.journaled_state.depth(), [true; 5], Some(emitter), true)
let Some(tracer) = executor.tracing_inspector().and_then(|t| t.as_ref()) else {
return Ok(Default::default());
};
expect_emit(
ccx.state,
tracer,
ccx.ecx.journaled_state.depth(),
[true; 5],
Some(emitter),
true,
)
}
}

Expand Down Expand Up @@ -459,12 +541,21 @@ fn expect_call(

fn expect_emit(
state: &mut Cheatcodes,
tracer: &TracingInspector,
depth: u64,
checks: [bool; 5],
address: Option<Address>,
anonymous: bool,
) -> Result {
let expected_emit = ExpectedEmit { depth, checks, address, found: false, log: None, anonymous };
let expected_emit = ExpectedEmit {
depth,
checks,
address,
found: false,
log: None,
anonymous,
sequence: tracer.traces().nodes().last().expect("no traces").logs.len() as u16,
};
if let Some(found_emit_pos) = state.expected_emits.iter().position(|emit| emit.found) {
// The order of emits already found (back of queue) should not be modified, hence push any
// new emit before first found emit.
Expand Down
3 changes: 3 additions & 0 deletions crates/evm/core/src/decode.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -180,6 +180,9 @@ impl RevertDecoder {
let e = Vm::expectRevert_1Call::abi_decode_raw(data, false).ok()?;
return self.maybe_decode(&e.revertData[..], status);
}
Vm::UnemittedEventError::SELECTOR => {
return Some("log != expected log".to_string());
}
_ => {}
}

Expand Down
1 change: 1 addition & 0 deletions crates/evm/traces/Cargo.toml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -36,6 +36,7 @@ eyre.workspace = true
futures.workspace = true
itertools.workspace = true
serde.workspace = true
owo-colors.workspace = true
tokio = { workspace = true, features = ["time", "macros"] }
tracing.workspace = true
rustc-hash.workspace = true
Expand Down
19 changes: 17 additions & 2 deletions crates/evm/traces/src/decoder/mod.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@ use crate::{
use alloy_dyn_abi::{DecodedEvent, DynSolValue, EventExt, FunctionExt, JsonAbiExt};
use alloy_json_abi::{Error, Event, Function, JsonAbi};
use alloy_primitives::{Address, LogData, Selector, B256};
use alloy_sol_types::SolError;
use foundry_common::{
abi::get_indexed_event, fmt::format_token, get_contract_name, ContractsByArtifact, SELECTOR_LEN,
};
Expand All @@ -24,6 +25,7 @@ use foundry_evm_core::{
},
};
use itertools::Itertools;
use owo_colors::OwoColorize;
use revm_inspectors::tracing::types::{DecodedCallLog, DecodedCallTrace};
use rustc_hash::FxHashMap;
use std::{
Expand Down Expand Up @@ -327,10 +329,23 @@ impl CallTraceDecoder {
pub async fn populate_traces(&self, traces: &mut Vec<CallTraceNode>) {
for node in traces {
node.trace.decoded = self.decode_function(&node.trace).await;

for log in node.logs.iter_mut() {
log.decoded = self.decode_event(&log.raw_log).await;
}

if let Ok(e) = Vm::UnemittedEventError::abi_decode(&node.trace.output, false) {
Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I could actually add the unmatched event name to the revert error here, if that's desirable.

let log_name = node.logs[e.positionExpected as usize]
.decoded
.name
.as_mut()
.expect("already decoded");

// set color to red fo the given event Id
node.logs[e.positionExpected as usize].decoded.name =
Some(log_name.red().to_string());
}

if let Some(debug) = self.debug_identifier.as_ref() {
if let Some(identified) = self.contracts.get(&node.trace.address) {
debug.identify_node_steps(node, get_contract_name(identified))
Expand Down Expand Up @@ -475,7 +490,7 @@ impl CallTraceDecoder {
"parseJsonBytes32Array" |
"writeJson" |
// `keyExists` is being deprecated in favor of `keyExistsJson`. It will be removed in future versions.
"keyExists" |
"keyExists" |
"keyExistsJson" |
"serializeBool" |
"serializeUint" |
Expand All @@ -491,7 +506,7 @@ impl CallTraceDecoder {
let mut decoded = func.abi_decode_input(&data[SELECTOR_LEN..], false).ok()?;
let token = if func.name.as_str() == "parseJson" ||
// `keyExists` is being deprecated in favor of `keyExistsJson`. It will be removed in future versions.
func.name.as_str() == "keyExists" ||
func.name.as_str() == "keyExists" ||
func.name.as_str() == "keyExistsJson"
{
"<JSON file>"
Expand Down
Loading