It should be easier to debug consensus failures

[lithp]

What is wrong?

It took me a while to diagnose #1893, if debugging could be made easier that would be helpful during emergencies where Trinity has production users.

1. In order to reproduce the error I was able to use the gethimport script to re-attempt processing the failing block. This was incredibly useful!
   • Documentation on using gethimport, or instructions for using ipython (and how to get an rlp-encoded version of the offending block), would be great things to add to a playbook.
2. When the block failed to import I got an error mentioning mix hashes, apparently the pow failed to validate. This is a very misleading error. Luckily, I had experience with this and knew that commenting out the POW check would help me find the root cause.
   • Switching the order of checks, or catching the POW exception and raising the more-useful exception if it applies, would make debugging faster and more intuitive.
3. After commenting out the POW check I got a better exception, which showed that when Trinity processes the block, it created a block with a different state root, receipts root, and gas cost. In order to drill further down I needed to add some code to BaseVM.import_block which printed each receipt. I was able to compare that with the output from the gethimport script (there's a command to dump the receipts for a block. I then manually compared gas costs until I found the first receipt which did not match.
   • This would have been easier if there was some kind of command to dump the receipts trinity generated during block processing. This could be DEBUG output, or maybe a method callable from ipython which disables all checks and returns as much state as it can?
4. After figuring out which transaction had been processed incorrectly, I asked Geth to create a trace of it. In order to get a trace from geth I had to run geth attach and then debug.standardTraceBlockToFile("[block hash]", {reexec:6000000}).
   • Finding standardTraceBlockToFile and the reexec command required asking in geth's discord channel. More familiarity with geth's docs, or some kind "consensus failre" playbook would have saved me time there.
5. Trinity has no method of creating a trace, it only has DEBUG2 output. This made comparing traces extremely difficult. The Trinity trace was 49236 lines, and the geth trace was 23869 lines. Geth reports gas costs in hexadecimal, while Trinity reports them in decimal.
   • If Trinity used the standard trace format I could have ran diff and looked at the first place they diverged.
6. Once the offending instruction gas cost had been identified finding the actual bug was pretty easy!

[cburgdorf]

Thanks for the writeup, very good points!

Just some quick comments:

Documentation on using gethimport, or instructions for using ipython (and how to get an rlp-encoded version of the offending block), would be great things to add to a playbook.

Just noting that trinity supports import / export commands (just recently added) that lets you do this.

https://github.com/ethereum/trinity/blob/eb00e74249086b10c24f73081131f66d710ddcef/tests/integration/test_trinity_cli.py#L366-L418

We should probably add better coverage for that in the docs. In fact, a whole detailed guide on how to debug consensus errors would be great!

Luckily, I had experience with this and knew that commenting out the POW check would help me find the root cause.

Yes, good point. Just noting that as part of the Clique support we have some refactoring coming that will make it easier to disable the Pow checks. In fact, one could even run Trinity with something like --consensus-engine no-proof