fuzz console log & test cases

[Azleal]

Motivation

As discussed in #3844 , when using fuzz test, console.log doesn't work as expected(display console log info). This PR added a new fuzz config show_execution_logs, with which user could decide if the full console log should be displayed. by defaut, the value is false, so it won't affect any fuzz test prior to this change will be made.

Solution

A logs field is added to CaseOutcome to keep track of logs that generated in a single fuzz test. And collect logs in FuzzTestData after each fuzz test finished. then use the config show_logs in FuzzConfig to decide if full console log output should be displayed. if not, the console.log behavior is the same as what it is now.

Also, you can use /// forge-config: default.fuzz.show-logs = true to enable fuzz test console log per test.

4 test cases is added, to test if the new config works as expected.

[Azleal]

hi @grandizzy , please review this, there's a failed test case in test integration, and i believe it has nothing to do with my pr. btw, I think the docs should be updated if the pr is merged. but I didn't find where to update the docs. please tell me if this work needs to be done, and i'll update it.

[grandizzy]

Thank you, nice progress!

I was thinking more along the lines of #3844 requirement, that is to print logs during the test rather than after the test is completed (good for long campaigns where one would like to get feedback during execution). So instead storing logs for all fuzz cases (which would also require more resources for executing these test) we can print logs right after the executor call (if show-execution-logs enabled), smth like adding

        if self.config.show_execution_logs {
            for log in decode_console_logs(&call.logs) {
                println!("  {log}");
            }
        }

right after

foundry/crates/evm/evm/src/executors/fuzz/mod.rs

Lines 213 to 222 in 15652dc

	pub fn single_fuzz(
	&self,
	address: Address,
	should_fail: bool,
	calldata: alloy_primitives::Bytes,
	) -> Result<FuzzOutcome, TestCaseError> {
	let mut call = self
	.executor
	.call_raw(self.sender, address, calldata.clone(), U256::ZERO)
	.map_err(|_| TestCaseError::fail(FuzzError::FailedContractCall))?;

Would be nice to extend this to invariant testing as well (would probably require the config to be a general one like show_fuzz_logs and apply to both fuzz and invariant) but can be handled in a separate PR.

[grandizzy]

hi @grandizzy , please review this, there's a failed test case in test integration, and i believe it has nothing to do with my pr. btw, I think the docs should be updated if the pr is merged. but I didn't find where to update the docs. please tell me if this work needs to be done, and i'll update it.

Yep, would be great to follow up with docs update PR after this one is merged. The repo with book is https://github.com/foundry-rs/book

[Azleal]

Thank you, nice progress!

I was thinking more along the lines of #3844 requirement, that is to print logs during the test rather than after the test is completed (good for long campaigns where one would like to get feedback during execution). So instead storing logs for all fuzz cases (which would also require more resources for executing these test) we can print logs right after the executor call (if show-execution-logs enabled), smth like adding

        if self.config.show_execution_logs {
            for log in decode_console_logs(&call.logs) {
                println!("  {log}");
            }
        }

right after

foundry/crates/evm/evm/src/executors/fuzz/mod.rs

Lines 213 to 222 in 15652dc

	pub fn single_fuzz(
	&self,
	address: Address,
	should_fail: bool,
	calldata: alloy_primitives::Bytes,
	) -> Result<FuzzOutcome, TestCaseError> {
	let mut call = self
	.executor
	.call_raw(self.sender, address, calldata.clone(), U256::ZERO)
	.map_err(|_| TestCaseError::fail(FuzzError::FailedContractCall))?;

Would be nice to extend this to invariant testing as well (would probably require the config to be a general one like show_fuzz_logs and apply to both fuzz and invariant) but can be handled in a separate PR.

ok, I got your points. Although show-execution-logs is under fuzz config section, it's clearer to use show_fuzz_logs and this convention could also be applied to invariant tests. I'm on this.

[Azleal]

Thank you, nice progress!

I was thinking more along the lines of #3844 requirement, that is to print logs during the test rather than after the test is completed (good for long campaigns where one would like to get feedback during execution). So instead storing logs for all fuzz cases (which would also require more resources for executing these test) we can print logs right after the executor call (if show-execution-logs enabled), smth like adding

        if self.config.show_execution_logs {
            for log in decode_console_logs(&call.logs) {
                println!("  {log}");
            }
        }

right after

foundry/crates/evm/evm/src/executors/fuzz/mod.rs

Lines 213 to 222 in 15652dc

	pub fn single_fuzz(
	&self,
	address: Address,
	should_fail: bool,
	calldata: alloy_primitives::Bytes,
	) -> Result<FuzzOutcome, TestCaseError> {
	let mut call = self
	.executor
	.call_raw(self.sender, address, calldata.clone(), U256::ZERO)
	.map_err(|_| TestCaseError::fail(FuzzError::FailedContractCall))?;

Would be nice to extend this to invariant testing as well (would probably require the config to be a general one like show_fuzz_logs and apply to both fuzz and invariant) but can be handled in a separate PR.

hi @grandizzy
After walking though the execution process. I don't think we could print the fuzz console logs right after the executor call. here's why:

1. the console.log should also be controlled by verbosity, only verbosity >= 2 is allowed to display logs.
2. all logs should be printed under respective test results, which means that we have to keep the logs until it should be displayed.

related code:

foundry/crates/forge/bin/cmd/test/mod.rs

Lines 455 to 465 in 8b694bb

	if verbosity >= 2 {
	// We only decode logs from Hardhat and DS-style console events
	let console_logs = decode_console_logs(&result.logs);
	if !console_logs.is_empty() {
	println!("Logs:");
	for log in console_logs {
	println!(" {log}");
	}
	println!();
	}
	}

wdyt

[grandizzy]

hi @grandizzy After walking though the execution process. I don't think we could print the fuzz console logs right after the executor call. here's why:

1. the console.log should also be controlled by `verbosity`, only `verbosity >= 2` is allowed to display logs.

Yeah, I think the show fuzz logs config could supersede the verbosity, so don't think this is a biggie

2. all logs should be printed under respective test results, which means that we have to keep the logs until it should be displayed.

Good point, if we're not displaying under their own test then running multiple fuzz tests at the same time could become a mess. So let's stick with the impl of gather logs and displaying them at the end, let's keep for fuzz only for now and extend to invariants after. There's FuzzTestData that's already ref celled, so pls add that to it (instead declaring the logs: RefCell<Vec<Log>>)

foundry/crates/evm/evm/src/executors/fuzz/mod.rs

Lines 25 to 40 in 15652dc

	/// Contains data collected during fuzz test runs.
	#[derive(Default)]
	pub struct FuzzTestData {
	// Stores the first fuzz case.
	pub first_case: Option<FuzzCase>,
	// Stored gas usage per fuzz case.
	pub gas_by_case: Vec<(u64, u64)>,
	// Stores the result and calldata of the last failed call, if any.
	pub counterexample: (Bytes, RawCallResult),
	// Stores up to `max_traces_to_collect` traces.
	pub traces: Vec<CallTraceArena>,
	// Stores breakpoints for the last fuzz case.
	pub breakpoints: Option<Breakpoints>,
	// Stores coverage information for all fuzz cases.
	pub coverage: Option<HitMaps>,
	}

[Azleal]

hi @grandizzy After walking though the execution process. I don't think we could print the fuzz console logs right after the executor call. here's why:

1. the console.log should also be controlled by `verbosity`, only `verbosity >= 2` is allowed to display logs.

Yeah, I think the show fuzz logs config could supersede the verbosity, so don't think this is a biggie

2. all logs should be printed under respective test results, which means that we have to keep the logs until it should be displayed.

Good point, if we're not displaying under their own test then running multiple fuzz tests at the same time could become a mess. So let's stick with the impl of gather logs and displaying them at the end, let's keep for fuzz only for now and extend to invariants after. There's FuzzTestData that's already ref celled, so pls add that to it (instead declaring the logs: RefCell<Vec<Log>>)

foundry/crates/evm/evm/src/executors/fuzz/mod.rs

Lines 25 to 40 in 15652dc

	/// Contains data collected during fuzz test runs.
	#[derive(Default)]
	pub struct FuzzTestData {
	// Stores the first fuzz case.
	pub first_case: Option<FuzzCase>,
	// Stored gas usage per fuzz case.
	pub gas_by_case: Vec<(u64, u64)>,
	// Stores the result and calldata of the last failed call, if any.
	pub counterexample: (Bytes, RawCallResult),
	// Stores up to `max_traces_to_collect` traces.
	pub traces: Vec<CallTraceArena>,
	// Stores breakpoints for the last fuzz case.
	pub breakpoints: Option<Breakpoints>,
	// Stores coverage information for all fuzz cases.
	pub coverage: Option<HitMaps>,
	}

do you mean that I should define a new field like logs in FuzzTestData to store logs, or I could make use of logs in counterexample or traces?

[grandizzy]

hi @grandizzy After walking though the execution process. I don't think we could print the fuzz console logs right after the executor call. here's why:

1. the console.log should also be controlled by `verbosity`, only `verbosity >= 2` is allowed to display logs.

Yeah, I think the show fuzz logs config could supersede the verbosity, so don't think this is a biggie

2. all logs should be printed under respective test results, which means that we have to keep the logs until it should be displayed.

Good point, if we're not displaying under their own test then running multiple fuzz tests at the same time could become a mess. So let's stick with the impl of gather logs and displaying them at the end, let's keep for fuzz only for now and extend to invariants after. There's FuzzTestData that's already ref celled, so pls add that to it (instead declaring the logs: RefCell<Vec<Log>>)

foundry/crates/evm/evm/src/executors/fuzz/mod.rs

Lines 25 to 40 in 15652dc

	/// Contains data collected during fuzz test runs.
	#[derive(Default)]
	pub struct FuzzTestData {
	// Stores the first fuzz case.
	pub first_case: Option<FuzzCase>,
	// Stored gas usage per fuzz case.
	pub gas_by_case: Vec<(u64, u64)>,
	// Stores the result and calldata of the last failed call, if any.
	pub counterexample: (Bytes, RawCallResult),
	// Stores up to `max_traces_to_collect` traces.
	pub traces: Vec<CallTraceArena>,
	// Stores breakpoints for the last fuzz case.
	pub breakpoints: Option<Breakpoints>,
	// Stores coverage information for all fuzz cases.
	pub coverage: Option<HitMaps>,
	}

do you mean that I should define a new field like logs in FuzzTestData to store logs, or I could make use of logs in counterexample or traces?

Yeah, I mean new field in struct instead
https://github.com/foundry-rs/foundry/pull/8387/files#diff-12784ea10f5753f595ab88ff54a8d09ecdd044d6a19676229f601a1bffe702e6R96

[Azleal]

Thank you, nice progress!

I was thinking more along the lines of #3844 requirement, that is to print logs during the test rather than after the test is completed (good for long campaigns where one would like to get feedback during execution). So instead storing logs for all fuzz cases (which would also require more resources for executing these test) we can print logs right after the executor call (if show-execution-logs enabled), smth like adding

        if self.config.show_execution_logs {
            for log in decode_console_logs(&call.logs) {
                println!("  {log}");
            }
        }

right after

foundry/crates/evm/evm/src/executors/fuzz/mod.rs

Lines 213 to 222 in 15652dc

	pub fn single_fuzz(
	&self,
	address: Address,
	should_fail: bool,
	calldata: alloy_primitives::Bytes,
	) -> Result<FuzzOutcome, TestCaseError> {
	let mut call = self
	.executor
	.call_raw(self.sender, address, calldata.clone(), U256::ZERO)
	.map_err(|_| TestCaseError::fail(FuzzError::FailedContractCall))?;

Would be nice to extend this to invariant testing as well (would probably require the config to be a general one like show_fuzz_logs and apply to both fuzz and invariant) but can be handled in a separate PR.

@grandizzy Can we just use show_logs in FuzzConfig? Because I noticed that, there are runs in both FuzzConfig and InvariantConfig, and share the same meaning as runs for fuzz test or invariants test. wdyt

And do I need to add something like fuzz_show_logs here👇🏻 for users to use environment FOUNDRY_FUZZ_SHOW_LOGS?

foundry/crates/forge/bin/cmd/test/mod.rs

Lines 105 to 114 in 0116be1

	/// Set seed used to generate randomness during your fuzz runs.
	#[arg(long)]
	pub fuzz_seed: Option<U256>,
	#[arg(long, env = "FOUNDRY_FUZZ_RUNS", value_name = "RUNS")]
	pub fuzz_runs: Option<u64>,
	/// File to rerun fuzz failures from.
	#[arg(long)]
	pub fuzz_input_file: Option<String>,

[grandizzy]

@grandizzy Can we just use show_logs in FuzzConfig? Because I noticed that, there are runs in both FuzzConfig and InvariantConfig, and share the same meaning as runs for fuzz test or invariants test. wdyt

yes, that should work

And do I need to add something like fuzz_show_logs here👇🏻 for users to use environment FOUNDRY_FUZZ_SHOW_LOGS?

nope, that's not needed

[Azleal]

@grandizzy Can we just use show_logs in FuzzConfig? Because I noticed that, there are runs in both FuzzConfig and InvariantConfig, and share the same meaning as runs for fuzz test or invariants test. wdyt

yes, that should work

well, I think this is my final commit. please review this to see if any change should be made. @grandizzy

[grandizzy]

looks good, think we can simplify a little bit, pls check

[grandizzy]

lgtm, thank you! clippy failure not related

[Azleal]

lgtm, thank you! clippy failure not related

Thank you, @grandizzy, for your patience and guidance throughout this PR. You're so meticulous. I'm new to Rust, and every time I thought there was nothing to optimize, your review showed me a better way. 😄👍🏻

Hopefully, this PR will not be reverted again.

[mattsse]

ty