VM Debugging

[holgerd77]

I am so tired of VM debugging where it becomes extremely hard to follow on the control flow that I would want to add some debugging analog to what is done in the devp2p and client packages. This should make it significantly easier for us to track bugs like in #1076.

This is a first test commit to gather some feedback, I would continue with this tomorrow if there is no significant objection or critics.

This produces output like the following if activated with e.g. DEBUG=vm:tx ts-node test.ts:

(so only the upper part, JSON below is just a console.log() from the script run)

[codecov]

Codecov Report

Merging #1080 (3804232) into master (80093e6) will increase coverage by 0.05%.
The diff coverage is 96.55%.

Flag	Coverage Δ
block	81.15% <ø> (ø)
blockchain	82.83% <ø> (ø)
client	87.09% <ø> (-0.13%)	⬇️
common	86.28% <ø> (ø)
devp2p	82.48% <ø> (+0.16%)	⬆️
ethash	82.08% <ø> (ø)
tx	90.00% <ø> (-0.16%)	⬇️
vm	83.94% <96.55%> (+0.84%)	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

[cgewecke]

100% in favor 🙂

[holgerd77]

Have added some first debug loggers vm:tx, vm:tx:gas and vm:state which can be run all at once with DEBUG=vm:*,vm:tx:gas ts-node test.ts and I can assure you this will be game-changing for both debugging and educational purposes! 😀 😁 😀

Here is a sample run:

[holgerd77]

Ok, have now also adding a debug logger for opcode based logging, this comes in really really handy, e.g. by just logging on all the SSTORE processings with DEBUG=vm:tx,vm:evm,vm:ops:sstore,vm:*:gas ts-node test.ts //cc @jochem-brouwer: 😄

[holgerd77]

Ok, I'll stop here, have also added some additional README instructions, this is now ready for review. 😄

@jochem-brouwer I'll try to add an additional vm:block logger during next week if you think this is a useful addition which should be prioritized since it will get useful for our client runs.

Please note though that this is meant to be a general purpose debugging helper not necessarily (only) meant to be for our client runs but for all sorts of development and user activity (adding new opcodes, testing some functionality changes in the evm.ts code, debugging and/or understanding tx runs,...). Should be very usable for our client testing as well though, as loggers can be arbitrarily combined as necessary. 😁 I also very much assume that we will add additional loggers over time as well as improve on the existing ones.

[jochem-brouwer]

I have a few suggestions after just reading the readme: (can be in a subsequent PR)

• It is very helpful if we know what the current address is we are running operations on. Just the depth is not enough. If we SSTORE, we want to know on which address we are storing. (Same with CREATE)
• It is also very helpful to know if a CALL* / CREATE* succeeds or not. So, if the depth changes and gets lower (so a call returns), then we should check the top of the stack. If this is nonzero, the call/create has succeeded. If this is not the case, then the call/create has failed. (This thus also means that any storage writes / code deposits did not succeed and are reverted). This is somewhat tricky, since if you call an address which has no code, we don't change the depth (it immediately succeeds, and is usually just used to transfer ether).

In general what would also help is to verify our step event against the data which is reported if we call debug_traceTransaction on geth. Then we can figure out exactly at which step our results diverge from that of Geth.

[holgerd77]

Hi Jochem, thanks for the suggestions, just an answer on the first one on a first round:

If I get this right the operations address on a CALL is the to address and on CREATE the created address, right? Both are available in the SSTORE-(or other bytecode)-surrounding log messages. Correct me if I am wrong?

So e.g.

vm:evm New message caller=0x147013436bd5c7def49a8e27c7fba8ac2b9dfe1f gasLimit=276872 to=0x9ca228250f9d8f86c23690074c2b96d5f5479f79 value=0 delegatecall=no +0ms
...and then closing with
vm:evm message checkpoint +96ms

And for CREATE

vm:evm New message caller=0x9ca228250f9d8f86c23690074c2b96d5f5479f79 gasLimit=243805 to= value=0 delegatecall=no +0ms
  vm:evm Message CREATE execution (to undefined) +0ms
  vm:evm Reduce sender (0x9ca228250f9d8f86c23690074c2b96d5f5479f79) balance (-> 40000000000000000) +1ms
  vm:evm Generated CREATE contract address 0x8398ff6c618e9515468c1c4b198d53666cbe8462 +1ms
... and closing again with
vm:evm message checkpoint committed +0ms#

[holgerd77]

Isn't point 2 (CALL / CREATE succeeds or not) included in the message results? 🤔

So e.g.:

vm:evm Received message results gasUsed=106040 execResult: [ gasUsed=106040 exceptionError= returnValue=0000000000000000000000008398ff6c618e9515468c1c4b19... gasRefund=undefined ] +11ms

[cgewecke]

This is really nice.

@jochem-brouwer You mentioned wanting to diff the geth / ethereumjs traces - would the most convenient thing be to have two files with JSONs of the respective traces?

If so debug has custom formatters which might help with this.

I think you could collect the steps into a trace and then write to ejs.vm.<txhash>.json, when DEBUG=vm:savetrace (or something)

[holgerd77]

I would guess this is a good suggestion since comparing might be easiest on a per file basis with some linux CLI tools? @jochem-brouwer WDYT?

[cgewecke]

Out of curiosity - this is a simplification e.g the result is already formatted as COOGResult?

Should COOGResult be removed in this PR?

[holgerd77]

Oh oh oh, this actually sneaked in along doing debugging work for #1076, this shouldn't be here. 😏

@jochem-brouwer just to make you aware, can you please take care of this along working on #1081 respectively along some rebase since you are touching this code anyhow? Thanks!

[cgewecke]

Looks great to me! 💯