feat: decode Hardhat console logs in traces (#6504)

* chore: add tracing to trace decoder

* cleanup hh console

* feat: decode Hardhat console logs in traces

* chore: clippy

crates/evm/core/src/abi/hardhat_console.rs

@@ -1,3 +1,4 @@
+use alloy_primitives::Selector;
 use alloy_sol_types::sol;
 use foundry_macros::ConsoleFmt;
 use once_cell::sync::Lazy;
@@ -10,25 +11,34 @@ sol!(
     "src/abi/HardhatConsole.json"
 );
 
-/// If the input starts with a known `hardhat/console.log` `uint` selector, then this will replace
-/// it with the selector `abigen!` bindings expect.
-pub fn patch_hardhat_console_selector(input: &mut [u8]) {
-    if let Some(selector) = input.get_mut(..4) {
-        let selector: &mut [u8; 4] = selector.try_into().unwrap();
-        if let Some(generated_selector) = HARDHAT_CONSOLE_SELECTOR_PATCHES.get(selector) {
-            *selector = *generated_selector;
-        }
+/// Patches the given Hardhat `console` function selector to its ABI-normalized form.
+///
+/// See [`HARDHAT_CONSOLE_SELECTOR_PATCHES`] for more details.
+pub fn patch_hh_console_selector(input: &mut [u8]) {
+    if let Some(selector) = hh_console_selector(input) {
+        input[..4].copy_from_slice(selector.as_slice());
+    }
+}
+
+/// Returns the ABI-normalized selector for the given Hardhat `console` function selector.
+///
+/// See [`HARDHAT_CONSOLE_SELECTOR_PATCHES`] for more details.
+pub fn hh_console_selector(input: &[u8]) -> Option<&'static Selector> {
+    if let Some(selector) = input.get(..4) {
+        let selector: &[u8; 4] = selector.try_into().unwrap();
+        HARDHAT_CONSOLE_SELECTOR_PATCHES.get(selector).map(Into::into)
+    } else {
+        None
     }
 }
 
-/// This contains a map with all the  `hardhat/console.log` log selectors that use `uint` or `int`
-/// as key and the selector of the call with `uint256`,
+/// Maps all the `hardhat/console.log` log selectors that use the legacy ABI (`int`, `uint`) to
+/// their normalized counterparts (`int256`, `uint256`).
 ///
-/// This is a bit terrible but a workaround for the differing selectors used by hardhat and the call
-/// bindings which `abigen!` creates. `hardhat/console.log` logs its events in functions that accept
-/// `uint` manually as `abi.encodeWithSignature("log(int)", p0)`, but `abigen!` uses `uint256` for
-/// its call bindings (`HardhatConsoleCalls`) as generated by solc.
-static HARDHAT_CONSOLE_SELECTOR_PATCHES: Lazy<HashMap<[u8; 4], [u8; 4]>> = Lazy::new(|| {
+/// `hardhat/console.log` logs its events manually, and in functions that accept integers they're
+/// encoded as `abi.encodeWithSignature("log(int)", p0)`, which is not the canonical ABI encoding
+/// for `int` that Solc (and [`sol!`]) uses.
+pub static HARDHAT_CONSOLE_SELECTOR_PATCHES: Lazy<HashMap<[u8; 4], [u8; 4]>> = Lazy::new(|| {
     HashMap::from([
         // log(bool,uint256,uint256,address)
         ([241, 97, 178, 33], [0, 221, 135, 185]),
@@ -549,7 +559,7 @@ mod tests {
     fn hardhat_console_patch() {
         for (hh, generated) in HARDHAT_CONSOLE_SELECTOR_PATCHES.iter() {
             let mut hh = *hh;
-            patch_hardhat_console_selector(&mut hh);
+            patch_hh_console_selector(&mut hh);
             assert_eq!(hh, *generated);
         }
     }

crates/evm/core/src/abi/mod.rs

@@ -6,4 +6,7 @@ mod console;
 pub use console::Console;
 
 mod hardhat_console;
-pub use hardhat_console::{patch_hardhat_console_selector, HardhatConsole};
+pub use hardhat_console::{
+    hh_console_selector, patch_hh_console_selector, HardhatConsole,
+    HARDHAT_CONSOLE_SELECTOR_PATCHES,
+};

crates/evm/evm/src/inspectors/logs.rs

@@ -3,7 +3,7 @@ use alloy_sol_types::{SolEvent, SolInterface, SolValue};
 use ethers_core::types::Log;
 use foundry_common::{fmt::ConsoleFmt, types::ToEthers, ErrorExt};
 use foundry_evm_core::{
-    abi::{patch_hardhat_console_selector, Console, HardhatConsole},
+    abi::{patch_hh_console_selector, Console, HardhatConsole},
     constants::HARDHAT_CONSOLE_ADDRESS,
 };
 use revm::{
@@ -23,7 +23,7 @@ pub struct LogCollector {
 impl LogCollector {
     fn hardhat_log(&mut self, mut input: Vec<u8>) -> (InstructionResult, Bytes) {
         // Patch the Hardhat-style selector (`uint` instead of `uint256`)
-        patch_hardhat_console_selector(&mut input);
+        patch_hh_console_selector(&mut input);
 
         // Decode the call
         let decoded = match HardhatConsole::HardhatConsoleCalls::abi_decode(&input, false) {

crates/evm/traces/src/decoder/mod.rs

@@ -7,7 +7,7 @@ use alloy_json_abi::{Event, Function, JsonAbi as Abi};
 use alloy_primitives::{Address, Selector, B256};
 use foundry_common::{abi::get_indexed_event, fmt::format_token, SELECTOR_LEN};
 use foundry_evm_core::{
-    abi::{Console, HardhatConsole, Vm},
+    abi::{Console, HardhatConsole, Vm, HARDHAT_CONSOLE_SELECTOR_PATCHES},
     constants::{
         CALLER, CHEATCODE_ADDRESS, DEFAULT_CREATE2_DEPLOYER, HARDHAT_CONSOLE_ADDRESS,
         TEST_CONTRACT_ADDRESS,
@@ -17,6 +17,7 @@ use foundry_evm_core::{
 use itertools::Itertools;
 use once_cell::sync::OnceCell;
 use std::collections::{hash_map::Entry, BTreeMap, HashMap};
+use tracing::field;
 
 mod precompiles;
 
@@ -117,6 +118,23 @@ impl CallTraceDecoder {
     }
 
     fn init() -> Self {
+        /// All functions from the Hardhat console ABI.
+        ///
+        /// See [`HARDHAT_CONSOLE_SELECTOR_PATCHES`] for more details.
+        fn hh_funcs() -> impl Iterator<Item = (Selector, Function)> {
+            let functions = HardhatConsole::abi::functions();
+            let mut functions: Vec<_> =
+                functions.into_values().flatten().map(|func| (func.selector(), func)).collect();
+            let len = functions.len();
+            // `functions` is the list of all patched functions; duplicate the unpatched ones
+            for (unpatched, patched) in HARDHAT_CONSOLE_SELECTOR_PATCHES.iter() {
+                if let Some((_, func)) = functions[..len].iter().find(|(sel, _)| sel == patched) {
+                    functions.push((unpatched.into(), func.clone()));
+                }
+            }
+            functions.into_iter()
+        }
+
         Self {
             contracts: Default::default(),
 
@@ -129,11 +147,14 @@ impl CallTraceDecoder {
             ]
             .into(),
 
-            functions: HardhatConsole::abi::functions()
-                .into_values()
-                .chain(Vm::abi::functions().into_values())
-                .flatten()
-                .map(|func| (func.selector(), vec![func]))
+            functions: hh_funcs()
+                .chain(
+                    Vm::abi::functions()
+                        .into_values()
+                        .flatten()
+                        .map(|func| (func.selector(), func)),
+                )
+                .map(|(selector, func)| (selector, vec![func]))
                 .collect(),
 
             events: Console::abi::events()
@@ -223,14 +244,17 @@ impl CallTraceDecoder {
     }
 
     async fn decode_function(&self, trace: &mut CallTrace) {
+        let span = trace_span!("decode_function", label = field::Empty).entered();
+
         // Decode precompile
         if precompiles::decode(trace, 1) {
-            return
+            return;
         }
 
         // Set label
         if trace.label.is_none() {
             if let Some(label) = self.labels.get(&trace.address) {
+                span.record("label", label);
                 trace.label = Some(label.clone());
             }
         }
@@ -245,8 +269,9 @@ impl CallTraceDecoder {
         let TraceCallData::Raw(cdata) = &trace.data else { return };
 
         if trace.address == DEFAULT_CREATE2_DEPLOYER {
+            trace!("decoded as create2");
             trace.data = TraceCallData::Decoded { signature: "create2".to_string(), args: vec![] };
-            return
+            return;
         }
 
         if cdata.len() >= SELECTOR_LEN {
@@ -273,15 +298,15 @@ impl CallTraceDecoder {
             let signature =
                 if cdata.is_empty() && has_receive { "receive()" } else { "fallback()" }.into();
             let args = if cdata.is_empty() { Vec::new() } else { vec![cdata.to_string()] };
+            trace!(?signature, ?args, "decoded fallback data");
             trace.data = TraceCallData::Decoded { signature, args };
 
             if let TraceRetData::Raw(rdata) = &trace.output {
                 if !trace.success {
-                    trace.output = TraceRetData::Decoded(decode::decode_revert(
-                        rdata,
-                        Some(&self.errors),
-                        Some(trace.status),
-                    ));
+                    let decoded =
+                        decode::decode_revert(rdata, Some(&self.errors), Some(trace.status));
+                    trace!(?decoded, "decoded fallback output");
+                    trace.output = TraceRetData::Decoded(decoded);
                 }
             }
         }
@@ -305,8 +330,10 @@ impl CallTraceDecoder {
                 }
             }
         }
-        trace.data =
-            TraceCallData::Decoded { signature: func.signature(), args: args.unwrap_or_default() };
+
+        let signature = func.signature();
+        trace!(?signature, ?args, "decoded function input");
+        trace.data = TraceCallData::Decoded { signature, args: args.unwrap_or_default() };
     }
 
     /// Custom decoding for cheatcode inputs.
@@ -377,34 +404,36 @@ impl CallTraceDecoder {
     /// Decodes a function's output into the given trace.
     fn decode_function_output(&self, trace: &mut CallTrace, funcs: &[Function]) {
         let TraceRetData::Raw(data) = &trace.output else { return };
+        let mut s = None;
         if trace.success {
             if trace.address == CHEATCODE_ADDRESS {
-                if let Some(decoded) =
-                    funcs.iter().find_map(|func| self.decode_cheatcode_outputs(func))
-                {
-                    trace.output = TraceRetData::Decoded(decoded);
-                    return
-                }
+                s = funcs.iter().find_map(|func| self.decode_cheatcode_outputs(func));
             }
 
-            if let Some(values) =
-                funcs.iter().find_map(|func| func.abi_decode_output(data, false).ok())
-            {
-                // Functions coming from an external database do not have any outputs specified,
-                // and will lead to returning an empty list of values.
-                if values.is_empty() {
-                    return
+            if s.is_some() {
+                if let Some(values) =
+                    funcs.iter().find_map(|func| func.abi_decode_output(data, false).ok())
+                {
+                    // Functions coming from an external database do not have any outputs specified,
+                    // and will lead to returning an empty list of values.
+                    if !values.is_empty() {
+                        s = Some(
+                            values
+                                .iter()
+                                .map(|value| self.apply_label(value))
+                                .format(", ")
+                                .to_string(),
+                        );
+                    }
                 }
-                trace.output = TraceRetData::Decoded(
-                    values.iter().map(|value| self.apply_label(value)).format(", ").to_string(),
-                );
             }
         } else {
-            trace.output = TraceRetData::Decoded(decode::decode_revert(
-                data,
-                Some(&self.errors),
-                Some(trace.status),
-            ));
+            s = decode::maybe_decode_revert(data, Some(&self.errors), Some(trace.status));
+        }
+
+        if let Some(decoded) = s {
+            trace!(?decoded, "decoded function output");
+            trace.output = TraceRetData::Decoded(decoded);
         }
     }
 
@@ -440,8 +469,10 @@ impl CallTraceDecoder {
         for event in events {
             if let Ok(decoded) = event.decode_log(raw_log, false) {
                 let params = reconstruct_params(event, &decoded);
+                let name = event.name.clone();
+                trace!(?name, ?params, "decoded event");
                 *log = TraceLog::Decoded(
-                    event.name.clone(),
+                    name,
                     params
                         .into_iter()
                         .zip(event.inputs.iter())
@@ -452,7 +483,7 @@ impl CallTraceDecoder {
                         })
                         .collect(),
                 );
-                break
+                break;
             }
         }
     }

crates/evm/traces/src/decoder/precompiles.rs

@@ -76,6 +76,7 @@ pub(super) fn decode(trace: &mut CallTrace, _chain_id: u64) -> bool {
 
     // TODO: Other chain precompiles
 
+    trace!(?signature, ?args, "decoded precompile call");
     trace.data = TraceCallData::Decoded { signature: signature.to_string(), args };
     trace.label = Some("PRECOMPILES".into());
 

crates/forge/tests/it/repros.rs

@@ -5,6 +5,11 @@ use alloy_primitives::{address, Address};
 use ethers_core::abi::{Event, EventParam, Log, LogParam, ParamType, RawLog, Token};
 use forge::result::TestStatus;
 use foundry_config::{fs_permissions::PathPermission, Config, FsPermissions};
+use foundry_evm::{
+    constants::HARDHAT_CONSOLE_ADDRESS,
+    traces::{CallTraceDecoder, TraceCallData, TraceKind},
+    utils::CallKind,
+};
 use foundry_test_utils::Filter;
 
 /// Creates a test that runs `testdata/repros/Issue{issue}.t.sol`.
@@ -214,3 +219,44 @@ test_repro!(6355, false, None, |res| {
 
 // https://github.com/foundry-rs/foundry/issues/6437
 test_repro!(6437);
+
+// Test we decode Hardhat console logs AND traces correctly.
+// https://github.com/foundry-rs/foundry/issues/6501
+test_repro!(6501, false, None, |res| {
+    let mut res = res.remove("repros/Issue6501.t.sol:Issue6501Test").unwrap();
+    let test = res.test_results.remove("test_hhLogs()").unwrap();
+    assert_eq!(test.status, TestStatus::Success);
+    assert_eq!(test.decoded_logs, ["a".to_string(), "1".to_string(), "b 2".to_string()]);
+
+    let (kind, mut traces) = test.traces[1].clone();
+    assert_eq!(kind, TraceKind::Execution);
+
+    let test_call = traces.arena.first().unwrap();
+    assert_eq!(test_call.idx, 0);
+    assert_eq!(test_call.children, [1, 2, 3]);
+    assert_eq!(test_call.trace.depth, 0);
+    assert!(test_call.trace.success);
+
+    CallTraceDecoder::new().decode(&mut traces).await;
+
+    let expected = [
+        ("log(string)", vec!["\"a\""]),
+        ("log(uint256)", vec!["1"]),
+        ("log(string,uint256)", vec!["\"b\"", "2"]),
+    ];
+    for (node, expected) in traces.arena[1..=3].iter().zip(expected) {
+        let trace = &node.trace;
+        assert_eq!(trace.kind, CallKind::StaticCall);
+        assert_eq!(trace.address, HARDHAT_CONSOLE_ADDRESS);
+        assert_eq!(trace.label, Some("console".into()));
+        assert_eq!(trace.depth, 1);
+        assert!(trace.success);
+        assert_eq!(
+            trace.data,
+            TraceCallData::Decoded {
+                signature: expected.0.into(),
+                args: expected.1.into_iter().map(ToOwned::to_owned).collect(),
+            }
+        );
+    }
+});

testdata/repros/Issue6501.t.sol

@@ -0,0 +1,14 @@
+// SPDX-License-Identifier: MIT OR Apache-2.0
+pragma solidity 0.8.18;
+
+import "ds-test/test.sol";
+import "../logs/console.sol";
+
+// https://github.com/foundry-rs/foundry/issues/6501
+contract Issue6501Test is DSTest {
+    function test_hhLogs() public {
+        console.log("a");
+        console.log(uint256(1));
+        console.log("b", uint256(2));
+    }
+}