towards a standard EVM trace format

[cdetrio]

Towards a standard EVM trace format

The purpose of this standard trace format is to facilitate automated equivalence testing of different EVM implementations.

• steps are logged with the state of the environment (stack, gas remaining, program counter, etc.) immediately before execution of the opcode.
• call stack depth starts at zero

Temporary workarounds

• steps that result in exceptions (e.g. OOG exceptions) are logged as if they were successful
  • except for invalid opcode exceptions, which are not logged
    • invalid opcode exception is easy to check for before execution
    • it is easier to remove them from the log than to converge on a standard error code
  • it is useful to see in a trace the operation that caused an OOG exception, or a stack underflow, etc.
  • but it complicates the tracing logic if the result of an operation needs to be known before it is logged

Noted quirks

geth logs STOP operations on all successful exits, even when there is no STOP opcode. For example, where pyethereum logs:

TRACE:eth.vm.op	{"event": "eth.vm.op.vm", "level": "TRACE", "op": "SSTORE", "stack": ["b'133001'", "b'2'"], "gas": "b'20030'", "inst": 85, "pc": "b'72'", "steps": 32, "depth": 132}
TRACE:eth.vm.exit {"event": "eth.vm.exit.exit", "level": "TRACE", "cause": "CODE OUT OF RANGE"}

geth will log:

{"pc":72,"op":85,"gas":"0x4e3e","gasCost":"0x4e20","memory":"0x","memSize":0,"stack":["0x20789","0x2"],"depth":133,"error":null,"opName":"SSTORE"}
{"pc":73,"op":0,"gas":"0x1e","gasCost":"0x0","memory":"0x","memSize":0,"stack":[],"depth":133,"error":null,"opName":"STOP"}

Example trace

This trace is produced by executing the stCallCodes/callcall_00 state test.

{'pc': 0, 'op': 96, 'gas': '0x2d74b8', 'gasCost': '0x3', 'stack': [], 'depth': 0, 'opName': 'PUSH1'}
{'pc': 2, 'op': 96, 'gas': '0x2d74b5', 'gasCost': '0x3', 'stack': ['0x40'], 'depth': 0, 'opName': 'PUSH1'}
{'pc': 4, 'op': 96, 'gas': '0x2d74b2', 'gasCost': '0x3', 'stack': ['0x40', '0x0'], 'depth': 0, 'opName': 'PUSH1'}
{'pc': 6, 'op': 96, 'gas': '0x2d74af', 'gasCost': '0x3', 'stack': ['0x40', '0x0', '0x40'], 'depth': 0, 'opName': 'PUSH1'}
{'pc': 8, 'op': 96, 'gas': '0x2d74ac', 'gasCost': '0x3', 'stack': ['0x40', '0x0', '0x40', '0x0'], 'depth': 0, 'opName': 'PUSH1'}
{'pc': 10, 'op': 115, 'gas': '0x2d74a9', 'gasCost': '0x3', 'stack': ['0x40', '0x0', '0x40', '0x0', '0x1'], 'depth': 0, 'opName': 'PUSH20'}
{'pc': 31, 'op': 98, 'gas': '0x2d74a6', 'gasCost': '0x3', 'stack': ['0x40', '0x0', '0x40', '0x0', '0x1', '0x1000000000000000000000000000000000000001'], 'depth': 0, 'opName': 'PUSH3'}
{'pc': 35, 'op': 241, 'gas': '0x2d74a3', 'gasCost': '0x57d1a', 'stack': ['0x40', '0x0', '0x40', '0x0', '0x1', '0x1000000000000000000000000000000000000001', '0x55730'], 'depth': 0, 'opName': 'CALL'}
{'pc': 0, 'op': 96, 'gas': '0x5602c', 'gasCost': '0x3', 'stack': [], 'depth': 1, 'opName': 'PUSH1'}
{'pc': 2, 'op': 96, 'gas': '0x56029', 'gasCost': '0x3', 'stack': ['0x40'], 'depth': 1, 'opName': 'PUSH1'}
{'pc': 4, 'op': 96, 'gas': '0x56026', 'gasCost': '0x3', 'stack': ['0x40', '0x0'], 'depth': 1, 'opName': 'PUSH1'}
{'pc': 6, 'op': 96, 'gas': '0x56023', 'gasCost': '0x3', 'stack': ['0x40', '0x0', '0x40'], 'depth': 1, 'opName': 'PUSH1'}
{'pc': 8, 'op': 96, 'gas': '0x56020', 'gasCost': '0x3', 'stack': ['0x40', '0x0', '0x40', '0x0'], 'depth': 1, 'opName': 'PUSH1'}
{'pc': 10, 'op': 115, 'gas': '0x5601d', 'gasCost': '0x3', 'stack': ['0x40', '0x0', '0x40', '0x0', '0x2'], 'depth': 1, 'opName': 'PUSH20'}
{'pc': 31, 'op': 98, 'gas': '0x5601a', 'gasCost': '0x3', 'stack': ['0x40', '0x0', '0x40', '0x0', '0x2', '0x1000000000000000000000000000000000000002'], 'depth': 1, 'opName': 'PUSH3'}
{'pc': 35, 'op': 241, 'gas': '0x56017', 'gasCost': '0x3f67a', 'stack': ['0x40', '0x0', '0x40', '0x0', '0x2', '0x1000000000000000000000000000000000000002', '0x3d090'], 'depth': 1, 'opName': 'CALL'}
{'pc': 0, 'op': 96, 'gas': '0x3d98c', 'gasCost': '0x3', 'stack': [], 'depth': 2, 'opName': 'PUSH1'}
{'pc': 2, 'op': 96, 'gas': '0x3d989', 'gasCost': '0x3', 'stack': ['0x1'], 'depth': 2, 'opName': 'PUSH1'}
{'pc': 4, 'op': 85, 'gas': '0x3d986', 'gasCost': '0x4e20', 'stack': ['0x1', '0x2'], 'depth': 2, 'opName': 'SSTORE'}
{'pc': 5, 'op': 51, 'gas': '0x38b66', 'gasCost': '0x2', 'stack': [], 'depth': 2, 'opName': 'CALLER'}
{'pc': 6, 'op': 96, 'gas': '0x38b64', 'gasCost': '0x3', 'stack': ['0x1000000000000000000000000000000000000001'], 'depth': 2, 'opName': 'PUSH1'}
{'pc': 8, 'op': 85, 'gas': '0x38b61', 'gasCost': '0x4e20', 'stack': ['0x1000000000000000000000000000000000000001', '0x4'], 'depth': 2, 'opName': 'SSTORE'}
{'pc': 9, 'op': 52, 'gas': '0x33d41', 'gasCost': '0x2', 'stack': [], 'depth': 2, 'opName': 'CALLVALUE'}
{'pc': 10, 'op': 96, 'gas': '0x33d3f', 'gasCost': '0x3', 'stack': ['0x2'], 'depth': 2, 'opName': 'PUSH1'}
{'pc': 12, 'op': 85, 'gas': '0x33d3c', 'gasCost': '0x4e20', 'stack': ['0x2', '0x7'], 'depth': 2, 'opName': 'SSTORE'}
{'pc': 13, 'op': 48, 'gas': '0x2ef1c', 'gasCost': '0x2', 'stack': [], 'depth': 2, 'opName': 'ADDRESS'}
{'pc': 14, 'op': 96, 'gas': '0x2ef1a', 'gasCost': '0x3', 'stack': ['0x1000000000000000000000000000000000000002'], 'depth': 2, 'opName': 'PUSH1'}
{'pc': 16, 'op': 85, 'gas': '0x2ef17', 'gasCost': '0x4e20', 'stack': ['0x1000000000000000000000000000000000000002', '0xe6'], 'depth': 2, 'opName': 'SSTORE'}
{'pc': 17, 'op': 50, 'gas': '0x2a0f7', 'gasCost': '0x2', 'stack': [], 'depth': 2, 'opName': 'ORIGIN'}
{'pc': 18, 'op': 96, 'gas': '0x2a0f5', 'gasCost': '0x3', 'stack': ['0xa94f5374fce5edbc8e2a8697c15331677e6ebf0b'], 'depth': 2, 'opName': 'PUSH1'}
{'pc': 20, 'op': 85, 'gas': '0x2a0f2', 'gasCost': '0x4e20', 'stack': ['0xa94f5374fce5edbc8e2a8697c15331677e6ebf0b', '0xe8'], 'depth': 2, 'opName': 'SSTORE'}
{'pc': 21, 'op': 54, 'gas': '0x252d2', 'gasCost': '0x2', 'stack': [], 'depth': 2, 'opName': 'CALLDATASIZE'}
{'pc': 22, 'op': 96, 'gas': '0x252d0', 'gasCost': '0x3', 'stack': ['0x40'], 'depth': 2, 'opName': 'PUSH1'}
{'pc': 24, 'op': 85, 'gas': '0x252cd', 'gasCost': '0x4e20', 'stack': ['0x40', '0xec'], 'depth': 2, 'opName': 'SSTORE'}
{'pc': 25, 'op': 56, 'gas': '0x204ad', 'gasCost': '0x2', 'stack': [], 'depth': 2, 'opName': 'CODESIZE'}
{'pc': 26, 'op': 96, 'gas': '0x204ab', 'gasCost': '0x3', 'stack': ['0x21'], 'depth': 2, 'opName': 'PUSH1'}
{'pc': 28, 'op': 85, 'gas': '0x204a8', 'gasCost': '0x4e20', 'stack': ['0x21', '0xee'], 'depth': 2, 'opName': 'SSTORE'}
{'pc': 29, 'op': 58, 'gas': '0x1b688', 'gasCost': '0x2', 'stack': [], 'depth': 2, 'opName': 'GASPRICE'}
{'pc': 30, 'op': 96, 'gas': '0x1b686', 'gasCost': '0x3', 'stack': ['0x1'], 'depth': 2, 'opName': 'PUSH1'}
{'pc': 32, 'op': 85, 'gas': '0x1b683', 'gasCost': '0x4e20', 'stack': ['0x1', '0xf0'], 'depth': 2, 'opName': 'SSTORE'}
{'pc': 36, 'op': 96, 'gas': '0x2d200', 'gasCost': '0x3', 'stack': ['0x1'], 'depth': 1, 'opName': 'PUSH1'}
{'pc': 38, 'op': 85, 'gas': '0x2d1fd', 'gasCost': '0x4e20', 'stack': ['0x1', '0x1'], 'depth': 1, 'opName': 'SSTORE'}
{'pc': 36, 'op': 96, 'gas': '0x2a7b66', 'gasCost': '0x3', 'stack': ['0x1'], 'depth': 0, 'opName': 'PUSH1'}
{'pc': 38, 'op': 85, 'gas': '0x2a7b63', 'gasCost': '0x4e20', 'stack': ['0x1', '0x0'], 'depth': 0, 'opName': 'SSTORE'}
{"output":"","gasUsed":"0x34775","time":1967173}

[debris]

I like the idea of standarization very much! 👍

But if we are about to do that, there can't be any temporary workarounds. Can't a single operation result in two logs? One created before operation execution with the operation itself and the other one with result of the operation.

[cdetrio]

@debris this is to document a work-in-progress, so hopefully it will see incremental improvement.

If a single operation resulted in two logs, lots of information would be duplicated. I do like the idea of an error field, which would tell whether an operation failed due to an OOG or some other exception. But that would complicate the tracing logic quite a bit, and it would be non-trivial to implement in the clients I've worked with so far. Maybe if the failed operations are logged twice (the second with the failure) it would be easier for clients to implement?

[cdetrio]

see also ethereum/go-ethereum#14900

[chfast]

Can you describe what data is logged? Is logging the stack and memory feasible?

[cdetrio]

The stack is logged on every step. Logging the memory should be feasible, but at the moment its not included in the equivalence test.

[chfast]

Full stack is logged or only the changes?
I need to design the VM trace API. Dumping full stack and memory every step seems like a waste of resources. The listener can reconstruct the stack and the memory on its own.

[cdetrio]

The full stack is logged. I agree that just the changes would be more compact.

[gcolvin]

There is always a STOP opcode, if you count the virtual extension of the code with an indefinite number of zeros. So geth may be right. I suspect eth will also report a STOP for that reason, but am on the road and can't check the code right now.

[gcolvin]

Yes, logging the full stack is horrible. For eth the stack grows towards low addresses, so the code has to copy it all out backwards. Only the changes should be logged.

[chfast]

VM trace data:

1. pc int64 (aka instruction counter) -- number of instructions executed so far in the current call.
2. opcode int64 -- the numeric id of the opcode to be executed.
3. depth int64 -- the current call depth, starting with 0.
4. gas int64 -- the current value of the gas counter. Descending.
5. opcode gas cost int64 -- the full cost of executing the current opcode (including memory costs).
6. result int256be -- the result put on stack after the execution of the opcode.
7. error code int64 -- the information about the failure of execution of the current opcode.
8. memory size int64 -- the current size of the memory.
9. pointer to memory void* -- the pointer to the memory.
10. opcode offset int64 -- the offset of the opcode in the code.

Notes:

• (6) and (7) are hard to do, especially when the current opcode is CALL-like.
• Knowing the gas cost (5) up front for CREATE is impossible. For calls we can assume max cost?
• Instead of dumping the full stack, it is enough to show only the results of opcodes. The listener can reconstruct the full stack on its own.
• Instead of the result (6) we can dump the top stack item. This would be relevant to the previous opcode.
• In (9) we can allow the listener to read the parts of the memory it wants to (based on the memory size (8)). But this might be too intrusive and assumes memory is continuous. Maybe make this param optional?