feat: identify internal function invocations in traces

[klkvr]

Motivation

Introduces --decode-internal flag for forge test, cast run and cast call --trace which enables decoding of internal functions in traces

Example

Example trace of random Uniswap V3 swap:

Solution

To determine when we are jumping in/out of functions we are using source map Jump key. However, it is not really reliable, especially after optimizations. Almost in all cases there are mismatches between number of "in"s and "out"s, so we need additional processing to correctly display subset of functions which are correctly reported.

Main implementation of this tracing is in DebugTraceIdentifier: https://github.com/foundry-rs/foundry/blob/216e9da8a28fcc57bcba1c6c4986aa5353472cc5/crates/evm/traces/src/debug/mod.rs

The only issue with this approach is that we are losing data about entire stack of internal functions which were joined before revert

I've used default tracer from revm-inspectors instead of traces collected by Debugger to allow easier integration into printing logic. Using it required a small patch to inspectors: paradigmxyz/revm-inspectors#150

This approach is enough to implement flamegraphs in a similar way, and can probably be extended to smarter tracking of stack/memory/calldata to also resolve input and output parameters of internal functions

Printing logic is a bit ugly at the moment

Closes: #3999 + Closes: #4351

[klkvr]

Added tracking of inputs and ouputs as well. It is currently not able to decode user-defined types such as structs and enums, tracking those would probably require smarter AST analysis.

Currently --decode-internal is pretty expensive in terms of memory usage because each step is being tracked for each test. We are only interested in JUMPs and JUMPDESTs, so it might make sense to add a configuration option for TracingInspector to only collect steps with specific opcodes.

[mattsse]

only briefly skimmed parts of it.

I think this makes sense, I'd appreciate a few more docs, and I'll take a closer look

[mattsse]

this is a bit hard to follow,
I wonder if we can encapsulate these two bools into an enum TracingKid or smth, because debug also implies tracing, right?

[mattsse]

lgtm

pending @DaniPopes

[klkvr]

Updated --decode-internal flag to accept a regex similar to --debug. On large suites --decode-internal easily results in OOM, so I think it's better to restrict its usage in such way

[DaniPopes]

Yeah same problem as in the debugger caused by memory snapshots

[DaniPopes]

Maybe we can disable memory decoding by default to avoid the memory consumption issue?

[klkvr]

Maybe we can disable memory decoding by default to avoid the memory consumption issue?

Yeah, I though about disabling memory tracking if more than one test matched filters. Though not sure how to make this intuitive

Should it be two separate flags, one of which does not require the test function filter?

[klkvr]

Updated forge test --decode-internal flag to only accept test function parameter optionally:

--decode-internal [<TEST_FUNCTION>]
  Whether to identify internal functions in traces.
  
  If no argument is passed to this flag, it will trace internal functions scope and decode stack parameters, but parameters stored in memory (such as bytes or arrays) will not be
  decoded.
  
  To decode memory parameters, you should pass an argument with a test function name, similarly to --debug and --match-test.
  
  If more than one test matches your specified criteria, you must add additional filters until only one test is found (see --match-contract and --match-path).

[Philogy]

Hey @klkvr, great work on this PR!

Just wanted to follow up on your comment about source maps getting messed up by the optimization step: do you mean that they're actually broken and it'd be useful to open an issue in solc or just that optimization fundamentally obfuscates the origin of an opcode as they could be reduced to fewer operations?

[klkvr]

@Philogy it's hard to tell, I've definitely seen situations in which source maps would point to completely unrelated chunck of code for some of the instructions after optimizations. However, I wouldn't be surprised if this has a reasonable explanation related to how inlining works internally. Sourcemaps are documented very briefly so it's hard to tell how they should behave and what we should consider a bug, and whether we can trust them after certain number of optimizations at all

[m-waqas88]

Version: forge 0.2.0 (41d4e54 2024-09-17T00:21:10.066464000Z)

Hey guys, really appreciate your efforts. I am actually facing an issue, when using --decode-internal flag, the value of arguments shown in the trace is actually wrong, as you can see I have logged the actual values pass as arguments. epoch is the first parameter and account is the second one. Console logging is showing correct values but in call trace (as function inputs) this value is incorrect.

Notes:

• In foundry.toml --via-ir is set to true (I cannot disable it otherwise it will throw stack too deep error)
• forge test --mp VaultWY.t.sol --mt test_WY_withdrawAndClaim -vvv --decode-internal --fork-url <fork-url>

@klkvr

[m-waqas88]

Version: forge 0.2.0 (41d4e54 2024-09-17T00:21:10.066464000Z)

Hey guys, really appreciate your efforts. I am actually facing an issue, when using --decode-internal flag, the value of arguments shown in the trace is actually wrong, as you can see I have logged the actual values pass as arguments. epoch is the first parameter and account is the second one. Console logging is showing correct values but in call trace (as function inputs) this value is incorrect.

Notes:

• In foundry.toml --via-ir is set to true (I cannot disable it otherwise it will throw stack too deep error)
• forge test --mp VaultWY.t.sol --mt test_WY_withdrawAndClaim -vvv --decode-internal --fork-url <fork-url>

@klkvr

Ok I got it. first parameter 1335805085125855948948476260874682295582732906387 is the decimal representation of the address --> waqas, and the second parameter is the hex representation of zero 0.