diff --git a/cmd/evm/internal/t8ntool/file_tracer.go b/cmd/evm/internal/t8ntool/file_tracer.go index 38fc35bd32..d1068cb6ad 100644 --- a/cmd/evm/internal/t8ntool/file_tracer.go +++ b/cmd/evm/internal/t8ntool/file_tracer.go @@ -148,5 +148,10 @@ func (l *fileWritingTracer) hooks() *tracing.Hooks { l.inner.OnSystemCallEnd() } }, + OnGasChange: func(old, new uint64, reason tracing.GasChangeReason) { + if l.inner.OnGasChange != nil { + l.inner.OnGasChange(old, new, reason) + } + }, } } diff --git a/cmd/evm/testdata/32/trace-0-0x47806361c0fa084be3caa18afe8c48156747c01dbdfc1ee11b5aecdbe4fcf23e.jsonl b/cmd/evm/testdata/32/trace-0-0x47806361c0fa084be3caa18afe8c48156747c01dbdfc1ee11b5aecdbe4fcf23e.jsonl index b6c5237baa..8278b462ca 100644 --- a/cmd/evm/testdata/32/trace-0-0x47806361c0fa084be3caa18afe8c48156747c01dbdfc1ee11b5aecdbe4fcf23e.jsonl +++ b/cmd/evm/testdata/32/trace-0-0x47806361c0fa084be3caa18afe8c48156747c01dbdfc1ee11b5aecdbe4fcf23e.jsonl @@ -44,8 +44,7 @@ {"pc":38,"op":82,"gas":"0x65ee4","gasCost":"0x6","memSize":0,"stack":["0x10","0x0"],"depth":2,"refund":0,"opName":"MSTORE"} {"pc":39,"op":96,"gas":"0x65ede","gasCost":"0x3","memSize":32,"stack":[],"depth":2,"refund":0,"opName":"PUSH1"} {"pc":41,"op":96,"gas":"0x65edb","gasCost":"0x3","memSize":32,"stack":["0x20"],"depth":2,"refund":0,"opName":"PUSH1"} -{"pc":43,"op":253,"gas":"0x65ed8","gasCost":"0x0","memSize":32,"stack":["0x20","0x0"],"depth":2,"refund":0,"opName":"REVERT"} -{"pc":43,"op":253,"gas":"0x65ed8","gasCost":"0x0","memSize":32,"stack":[],"depth":2,"refund":0,"opName":"REVERT","error":"execution reverted"} +{"pc":43,"op":253,"gas":"0x65ed8","gasCost":"0x0","memSize":32,"stack":["0x20","0x0"],"depth":2,"refund":0,"opName":"REVERT","error":"execution reverted"} {"output":"0000000000000000000000000000000000000000000000000000000000000010","gasUsed":"0x2e44","error":"execution reverted"} {"pc":69,"op":96,"gas":"0x67976","gasCost":"0x3","memSize":0,"stack":["0x0"],"depth":1,"refund":0,"opName":"PUSH1"} {"pc":71,"op":85,"gas":"0x67973","gasCost":"0x1388","memSize":0,"stack":["0x0","0x2"],"depth":1,"refund":4800,"opName":"SSTORE"} diff --git a/core/tracing/gen_gas_change_reason_stringer.go b/core/tracing/gen_gas_change_reason_stringer.go index e64be781a6..dbe87cbdde 100644 --- a/core/tracing/gen_gas_change_reason_stringer.go +++ b/core/tracing/gen_gas_change_reason_stringer.go @@ -28,21 +28,22 @@ func _() { _ = x[GasChangeWitnessCodeChunk-17] _ = x[GasChangeWitnessContractCollisionCheck-18] _ = x[GasChangeTxDataFloor-19] + _ = x[GasChangeCallOpCodeDynamic-20] _ = x[GasChangeIgnored-255] } const ( - _GasChangeReason_name_0 = "UnspecifiedTxInitialBalanceTxIntrinsicGasTxRefundsTxLeftOverReturnedCallInitialBalanceCallLeftOverReturnedCallLeftOverRefundedCallContractCreationCallContractCreation2CallCodeStorageCallOpCodeCallPrecompiledContractCallStorageColdAccessCallFailedExecutionWitnessContractInitWitnessContractCreationWitnessCodeChunkWitnessContractCollisionCheckTxDataFloor" + _GasChangeReason_name_0 = "UnspecifiedTxInitialBalanceTxIntrinsicGasTxRefundsTxLeftOverReturnedCallInitialBalanceCallLeftOverReturnedCallLeftOverRefundedCallContractCreationCallContractCreation2CallCodeStorageCallOpCodeCallPrecompiledContractCallStorageColdAccessCallFailedExecutionWitnessContractInitWitnessContractCreationWitnessCodeChunkWitnessContractCollisionCheckTxDataFloorCallOpCodeDynamic" _GasChangeReason_name_1 = "Ignored" ) var ( - _GasChangeReason_index_0 = [...]uint16{0, 11, 27, 41, 50, 68, 86, 106, 126, 146, 167, 182, 192, 215, 236, 255, 274, 297, 313, 342, 353} + _GasChangeReason_index_0 = [...]uint16{0, 11, 27, 41, 50, 68, 86, 106, 126, 146, 167, 182, 192, 215, 236, 255, 274, 297, 313, 342, 353, 370} ) func (i GasChangeReason) String() string { switch { - case i <= 19: + case i <= 20: return _GasChangeReason_name_0[_GasChangeReason_index_0[i]:_GasChangeReason_index_0[i+1]] case i == 255: return _GasChangeReason_name_1 diff --git a/core/tracing/hooks.go b/core/tracing/hooks.go index 0485f7a3eb..2e7ede315b 100644 --- a/core/tracing/hooks.go +++ b/core/tracing/hooks.go @@ -339,6 +339,9 @@ const ( // GasChangeTxDataFloor is the amount of extra gas the transaction has to pay to reach the minimum gas requirement for the // transaction data. This change will always be a negative change. GasChangeTxDataFloor GasChangeReason = 19 + // GasChangeCallOpCodeDynamic is the amount of dynamic gas that will be charged for an opcode executed by the EVM. + // It will be emitted after the `OnOpcode` callback. So the cost should be attributed to the last instance of `OnOpcode`. + GasChangeCallOpCodeDynamic GasChangeReason = 20 // GasChangeIgnored is a special value that can be used to indicate that the gas change should be ignored as // it will be "manually" tracked by a direct emit of the gas change event. diff --git a/core/vm/interpreter.go b/core/vm/interpreter.go index 34d19008da..707511d9d7 100644 --- a/core/vm/interpreter.go +++ b/core/vm/interpreter.go @@ -195,8 +195,8 @@ func (in *EVMInterpreter) Run(contract *Contract, input []byte, readOnly bool) ( // For optimisation reason we're using uint64 as the program counter. // It's theoretically possible to go above 2^64. The YP defines the PC // to be uint256. Practically much less so feasible. - pc = uint64(0) // program counter - cost uint64 + pc = uint64(0) // program counter + cost, dynamicCost uint64 // copies used by tracer pcCopy uint64 // needed for the deferred EVMLogger gasCopy uint64 // for EVMLogger to log gas remaining before execution @@ -234,7 +234,7 @@ func (in *EVMInterpreter) Run(contract *Contract, input []byte, readOnly bool) ( for { if debug { // Capture pre-execution values for tracing. - logged, pcCopy, gasCopy = false, pc, contract.Gas + logged, pcCopy, gasCopy, dynamicCost = false, pc, contract.Gas, 0 } if in.evm.chainRules.IsEIP4762 && !contract.IsDeployment && !contract.IsSystemCall { @@ -286,7 +286,6 @@ func (in *EVMInterpreter) Run(contract *Contract, input []byte, readOnly bool) ( } // Consume the gas and return an error if not enough gas is available. // cost is explicitly set so that the capture state defer method can get the proper cost - var dynamicCost uint64 dynamicCost, err = operation.dynamicGas(in.evm, contract, stack, mem, memorySize) cost += dynamicCost // for tracing if err != nil { @@ -303,10 +302,15 @@ func (in *EVMInterpreter) Run(contract *Contract, input []byte, readOnly bool) ( // Do tracing before potential memory expansion if debug { if in.evm.Config.Tracer.OnGasChange != nil { - in.evm.Config.Tracer.OnGasChange(gasCopy, gasCopy-cost, tracing.GasChangeCallOpCode) + // Trace the constant cost only + in.evm.Config.Tracer.OnGasChange(gasCopy, gasCopy-operation.constantGas, tracing.GasChangeCallOpCode) } if in.evm.Config.Tracer.OnOpcode != nil { - in.evm.Config.Tracer.OnOpcode(pc, byte(op), gasCopy, cost, callContext, in.returnData, in.evm.depth, VMErrorFromErr(err)) + in.evm.Config.Tracer.OnOpcode(pc, byte(op), gasCopy, operation.constantGas, callContext, in.returnData, in.evm.depth, VMErrorFromErr(err)) + // If any, trace the dynamic cost as well + if in.evm.Config.Tracer.OnGasChange != nil && dynamicCost > 0 { + in.evm.Config.Tracer.OnGasChange(gasCopy-operation.constantGas, gasCopy-cost, tracing.GasChangeCallOpCodeDynamic) + } logged = true } } diff --git a/core/vm/runtime/runtime_test.go b/core/vm/runtime/runtime_test.go index d75a5b0459..227a470d7f 100644 --- a/core/vm/runtime/runtime_test.go +++ b/core/vm/runtime/runtime_test.go @@ -667,6 +667,11 @@ func TestColdAccountAccessCost(t *testing.T) { Execute(tc.code, nil, &Config{ EVMConfig: vm.Config{ Tracer: &tracing.Hooks{ + OnGasChange: func(old, new uint64, reason tracing.GasChangeReason) { + if step-1 == tc.step && reason == tracing.GasChangeCallOpCodeDynamic { + have += old - new + } + }, OnOpcode: func(pc uint64, op byte, gas, cost uint64, scope tracing.OpContext, rData []byte, depth int, err error) { // Uncomment to investigate failures: //t.Logf("%d: %v %d", step, vm.OpCode(op).String(), cost) @@ -700,10 +705,15 @@ func TestRuntimeJSTracer(t *testing.T) { this.exits++; this.gasUsed = res.getGasUsed(); }}`, - `{enters: 0, exits: 0, enterGas: 0, gasUsed: 0, steps:0, + `{enters: 0, exits: 0, enterGas: 0, gasUsed: 0, steps:0, dynamicGas:0, fault: function() {}, result: function() { - return [this.enters, this.exits,this.enterGas,this.gasUsed, this.steps].join(",") + return [this.enters, this.exits,this.enterGas,this.gasUsed, this.steps, this.dynamicGas].join(",") + }, + gas: function(change) { + if (change.getReason() == "CallOpCodeDynamic") { + this.dynamicGas += change.getOld() - change.getNew(); + } }, enter: function(frame) { this.enters++; @@ -726,7 +736,7 @@ func TestRuntimeJSTracer(t *testing.T) { Push(0). // value Op(vm.CREATE). Op(vm.POP).Bytes(), - results: []string{`"1,1,952853,6,12"`, `"1,1,952853,6,0"`}, + results: []string{`"1,1,952853,6,12"`, `"1,1,952853,6,0,5"`}, }, { // CREATE2 code: program.New().MstoreSmall(initcode, 0). @@ -736,27 +746,27 @@ func TestRuntimeJSTracer(t *testing.T) { Push(0). // value Op(vm.CREATE2). Op(vm.POP).Bytes(), - results: []string{`"1,1,952844,6,13"`, `"1,1,952844,6,0"`}, + results: []string{`"1,1,952844,6,13"`, `"1,1,952844,6,0,11"`}, }, { // CALL code: program.New().Call(nil, 0xbb, 0, 0, 0, 0, 0).Op(vm.POP).Bytes(), - results: []string{`"1,1,981796,6,13"`, `"1,1,981796,6,0"`}, + results: []string{`"1,1,981796,6,13"`, `"1,1,981796,6,0,984296"`}, }, { // CALLCODE code: program.New().CallCode(nil, 0xcc, 0, 0, 0, 0, 0).Op(vm.POP).Bytes(), - results: []string{`"1,1,981796,6,13"`, `"1,1,981796,6,0"`}, + results: []string{`"1,1,981796,6,13"`, `"1,1,981796,6,0,984296"`}, }, { // STATICCALL code: program.New().StaticCall(nil, 0xdd, 0, 0, 0, 0).Op(vm.POP).Bytes(), - results: []string{`"1,1,981799,6,12"`, `"1,1,981799,6,0"`}, + results: []string{`"1,1,981799,6,12"`, `"1,1,981799,6,0,984299"`}, }, { // DELEGATECALL code: program.New().DelegateCall(nil, 0xee, 0, 0, 0, 0).Op(vm.POP).Bytes(), - results: []string{`"1,1,981799,6,12"`, `"1,1,981799,6,0"`}, + results: []string{`"1,1,981799,6,12"`, `"1,1,981799,6,0,984299"`}, }, { // CALL self-destructing contract code: program.New().Call(nil, 0xff, 0, 0, 0, 0, 0).Op(vm.POP).Bytes(), - results: []string{`"2,2,0,5003,12"`, `"2,2,0,5003,0"`}, + results: []string{`"2,2,0,5003,12"`, `"2,2,0,5003,0,984296"`}, }, } calleeCode := []byte{ @@ -921,6 +931,11 @@ func TestDelegatedAccountAccessCost(t *testing.T) { State: statedb, EVMConfig: vm.Config{ Tracer: &tracing.Hooks{ + OnGasChange: func(old, new uint64, reason tracing.GasChangeReason) { + if step-1 == tc.step && reason == tracing.GasChangeCallOpCodeDynamic { + have += old - new + } + }, OnOpcode: func(pc uint64, op byte, gas, cost uint64, scope tracing.OpContext, rData []byte, depth int, err error) { // Uncomment to investigate failures: t.Logf("%d: %v %d", step, vm.OpCode(op).String(), cost) diff --git a/eth/tracers/js/goja.go b/eth/tracers/js/goja.go index 7ec737f4e4..4719865def 100644 --- a/eth/tracers/js/goja.go +++ b/eth/tracers/js/goja.go @@ -129,17 +129,20 @@ type jsTracer struct { step goja.Callable enter goja.Callable exit goja.Callable + gas goja.Callable // Underlying structs being passed into JS log *steplog frame *callframe frameResult *callframeResult + gasChange *gasChange // Goja-wrapping of types prepared for JS consumption logValue goja.Value dbValue goja.Value frameValue goja.Value frameResultValue goja.Value + gasChangeValue goja.Value } // newJsTracer instantiates a new JS tracer instance. code is a @@ -202,6 +205,7 @@ func newJsTracer(code string, ctx *tracers.Context, cfg json.RawMessage, chainCo if hasEnter != hasExit { return nil, errors.New("trace object must expose either both or none of enter() and exit()") } + t.gas, _ = goja.AssertFunction(obj.Get("gas")) t.traceFrame = hasEnter t.obj = obj t.step = step @@ -230,18 +234,21 @@ func newJsTracer(code string, ctx *tracers.Context, cfg json.RawMessage, chainCo } t.frame = &callframe{vm: vm, toBig: t.toBig, toBuf: t.toBuf} t.frameResult = &callframeResult{vm: vm, toBuf: t.toBuf} + t.gasChange = &gasChange{vm: vm} t.frameValue = t.frame.setupObject() t.frameResultValue = t.frameResult.setupObject() t.logValue = t.log.setupObject() + t.gasChangeValue = t.gasChange.setupObject() return &tracers.Tracer{ Hooks: &tracing.Hooks{ - OnTxStart: t.OnTxStart, - OnTxEnd: t.OnTxEnd, - OnEnter: t.OnEnter, - OnExit: t.OnExit, - OnOpcode: t.OnOpcode, - OnFault: t.OnFault, + OnTxStart: t.OnTxStart, + OnTxEnd: t.OnTxEnd, + OnEnter: t.OnEnter, + OnExit: t.OnExit, + OnOpcode: t.OnOpcode, + OnFault: t.OnFault, + OnGasChange: t.OnGasChange, }, GetResult: t.GetResult, Stop: t.Stop, @@ -329,6 +336,20 @@ func (t *jsTracer) onStart(from common.Address, to common.Address, create bool, t.ctx["value"] = valueBig } +// OnGasChange keeps track of the changes in available gas +func (t *jsTracer) OnGasChange(old, new uint64, reason tracing.GasChangeReason) { + if t.gas == nil { + return + } + + t.gasChange.old = old + t.gasChange.new = new + t.gasChange.reason = reason + if _, err := t.gas(t.obj, t.gasChangeValue); err != nil { + t.onError("gas", err) + } +} + // OnOpcode implements the Tracer interface to trace a single step of VM execution. func (t *jsTracer) OnOpcode(pc uint64, op byte, gas, cost uint64, scope tracing.OpContext, rData []byte, depth int, err error) { if !t.traceStep { @@ -1043,3 +1064,23 @@ func (l *steplog) setupObject() *goja.Object { o.Set("contract", l.contract.setupObject()) return o } + +type gasChange struct { + vm *goja.Runtime + + old, new uint64 + reason tracing.GasChangeReason +} + +func (g *gasChange) GetOld() uint64 { return g.old } +func (g *gasChange) GetNew() uint64 { return g.new } +func (g *gasChange) GetReason() string { return g.reason.String() } + +func (g *gasChange) setupObject() *goja.Object { + o := g.vm.NewObject() + // Setup basic fields. + o.Set("getOld", g.vm.ToValue(g.GetOld)) + o.Set("getNew", g.vm.ToValue(g.GetNew)) + o.Set("getReason", g.vm.ToValue(g.GetReason)) + return o +} diff --git a/eth/tracers/js/internal/tracers/call_tracer_legacy.js b/eth/tracers/js/internal/tracers/call_tracer_legacy.js index 0760bb1e3f..e03acb8610 100644 --- a/eth/tracers/js/internal/tracers/call_tracer_legacy.js +++ b/eth/tracers/js/internal/tracers/call_tracer_legacy.js @@ -24,8 +24,12 @@ // an inner call. descended: false, + // keeps track of last pushed call to attribute the next dynamic cost with + lastPushedCall: undefined, + // step is invoked for every opcode that the VM executes. step: function(log, db) { + this.lastPushedCall = undefined // Capture any errors immediately var error = log.getError(); if (error !== undefined) { @@ -52,6 +56,7 @@ value: '0x' + log.stack.peek(0).toString(16) }; this.callstack.push(call); + this.lastPushedCall = call this.descended = true return; } @@ -61,14 +66,16 @@ if (this.callstack[left-1].calls === undefined) { this.callstack[left-1].calls = []; } - this.callstack[left-1].calls.push({ - type: op, - from: toHex(log.contract.getAddress()), - to: toHex(toAddress(log.stack.peek(0).toString(16))), - gasIn: log.getGas(), + var call = { + type: op, + from: toHex(log.contract.getAddress()), + to: toHex(toAddress(log.stack.peek(0).toString(16))), + gasIn: log.getGas(), gasCost: log.getCost(), - value: '0x' + db.getBalance(log.contract.getAddress()).toString(16) - }); + value: '0x' + db.getBalance(log.contract.getAddress()).toString(16) + } + this.callstack[left - 1].calls.push(call); + this.lastPushedCall = call return } // If a new method invocation is being done, add to the call stack @@ -98,6 +105,7 @@ call.value = '0x' + log.stack.peek(2).toString(16); } this.callstack.push(call); + this.lastPushedCall = call this.descended = true return; } @@ -161,6 +169,13 @@ } }, + gas: function(change) { + if (this.lastPushedCall !== undefined && change.getReason() == "CallOpCodeDynamic") { + this.lastPushedCall.gasCost += change.getOld() - change.getNew(); + this.lastPushedCall = undefined + } + }, + // fault is invoked when the actual execution of an opcode fails. fault: function(log, db) { // If the topmost call already reverted, don't handle the additional fault again diff --git a/eth/tracers/logger/logger.go b/eth/tracers/logger/logger.go index 824a5e0c3e..a6ea730f37 100644 --- a/eth/tracers/logger/logger.go +++ b/eth/tracers/logger/logger.go @@ -17,6 +17,7 @@ package logger import ( + "bytes" "encoding/hex" "encoding/json" "errors" @@ -96,12 +97,19 @@ func (s *StructLog) ErrorString() string { // WriteTo writes the human-readable log data into the supplied writer. func (s *StructLog) WriteTo(writer io.Writer) { + s.writeHeaderTo(writer) + s.writeVmStateTo(writer) +} + +func (s *StructLog) writeHeaderTo(writer io.Writer) { fmt.Fprintf(writer, "%-16spc=%08d gas=%v cost=%v", s.Op, s.Pc, s.Gas, s.GasCost) if s.Err != nil { fmt.Fprintf(writer, " ERROR: %v", s.Err) } fmt.Fprintln(writer) +} +func (s *StructLog) writeVmStateTo(writer io.Writer) { if len(s.Stack) > 0 { fmt.Fprintln(writer, "Stack:") for i := len(s.Stack) - 1; i >= 0; i-- { @@ -157,7 +165,7 @@ type structLogLegacy struct { } // toLegacyJSON converts the structLog to legacy json-encoded legacy form. -func (s *StructLog) toLegacyJSON() json.RawMessage { +func (s *StructLog) toLegacyJSON() structLogLegacy { msg := structLogLegacy{ Pc: s.Pc, Op: s.Op.String(), @@ -195,8 +203,8 @@ func (s *StructLog) toLegacyJSON() json.RawMessage { } msg.Storage = &storage } - element, _ := json.Marshal(msg) - return element + + return msg } // StructLogger is an EVM state logger and implements EVMLogger. @@ -223,6 +231,11 @@ type StructLogger struct { interrupt atomic.Bool // Atomic flag to signal execution interruption reason error // Textual reason for the interruption skip bool // skip processing hooks. + + // stitching context + stitchingBuffer bytes.Buffer + inflightLog StructLog + legacyInflightLog structLogLegacy } // NewStreamingStructLogger returns a new streaming logger. @@ -252,6 +265,24 @@ func (l *StructLogger) Hooks() *tracing.Hooks { OnSystemCallEnd: l.OnSystemCallEnd, OnExit: l.OnExit, OnOpcode: l.OnOpcode, + OnGasChange: l.OnGasChange, + } +} + +// OnFault logs failing opcodes +func (l *StructLogger) OnFault(pc uint64, op byte, gas, cost uint64, scope tracing.OpContext, depth int, err error) { + if l.skip { + return + } + l.inflightLog.Err = err + l.flushInflightLog() +} + +// OnGasChange logs the dynamic and refunded gas amounts +func (l *StructLogger) OnGasChange(old, new uint64, reason tracing.GasChangeReason) { + if reason == tracing.GasChangeCallOpCodeDynamic { + l.inflightLog.GasCost += old - new + l.inflightLog.RefundCounter = l.env.StateDB.GetRefund() } } @@ -263,6 +294,7 @@ func (l *StructLogger) OnOpcode(pc uint64, opcode byte, gas, cost uint64, scope if l.interrupt.Load() { return } + l.flushInflightLog() // Processing a system call. if l.skip { return @@ -279,6 +311,7 @@ func (l *StructLogger) OnOpcode(pc uint64, opcode byte, gas, cost uint64, scope stackLen = len(stack) ) log := StructLog{pc, op, gas, cost, nil, len(memory), nil, nil, nil, depth, l.env.StateDB.GetRefund(), err} + l.inflightLog = log if l.cfg.EnableMemory { log.Memory = memory } @@ -319,12 +352,31 @@ func (l *StructLogger) OnOpcode(pc uint64, opcode byte, gas, cost uint64, scope // create a log if l.writer == nil { - entry := log.toLegacyJSON() + l.legacyInflightLog = log.toLegacyJSON() + } else { + log.writeVmStateTo(&l.stitchingBuffer) + } + if opcode == byte(vm.STOP) { + l.flushInflightLog() + } +} + +func (l *StructLogger) flushInflightLog() { + // emptyLegacy is used as a sentinel value + var emptyLegacy structLogLegacy + if l.writer == nil && l.legacyInflightLog != emptyLegacy { + l.legacyInflightLog.GasCost = l.inflightLog.GasCost + l.legacyInflightLog.Error = l.inflightLog.ErrorString() + l.legacyInflightLog.RefundCounter = l.inflightLog.RefundCounter + entry, _ := json.Marshal(l.legacyInflightLog) l.resultSize += len(entry) l.logs = append(l.logs, entry) - return + l.legacyInflightLog = emptyLegacy + } else if l.stitchingBuffer.Len() > 0 { + l.inflightLog.writeHeaderTo(l.writer) + l.writer.Write(l.stitchingBuffer.Bytes()) } - log.WriteTo(l.writer) + l.stitchingBuffer.Reset() } // OnExit is called a call frame finishes processing. @@ -414,6 +466,11 @@ type mdLogger struct { cfg *Config env *tracing.VMContext skip bool + + // stitching context + stitchingBuffer bytes.Buffer + cost uint64 + refund uint64 } // NewMarkdownLogger creates a logger which outputs information in a format adapted @@ -435,6 +492,7 @@ func (t *mdLogger) Hooks() *tracing.Hooks { OnExit: t.OnExit, OnOpcode: t.OnOpcode, OnFault: t.OnFault, + OnGasChange: t.OnGasChange, } } @@ -493,14 +551,26 @@ func (t *mdLogger) OnExit(depth int, output []byte, gasUsed uint64, err error, r } } +// OnGasChange tracks the dynamic gas and refund amounts +func (t *mdLogger) OnGasChange(old, new uint64, reason tracing.GasChangeReason) { + if reason == tracing.GasChangeCallOpCodeDynamic { + t.cost += old - new + t.refund = t.env.StateDB.GetRefund() + } +} + // OnOpcode also tracks SLOAD/SSTORE ops to track storage change. func (t *mdLogger) OnOpcode(pc uint64, op byte, gas, cost uint64, scope tracing.OpContext, rData []byte, depth int, err error) { + t.flushInflightLog() + if t.skip { return } stack := scope.StackData() - fmt.Fprintf(t.out, "| %4d | %10v | %3d |%10v |", pc, vm.OpCode(op).String(), - cost, t.env.StateDB.GetRefund()) + t.cost = cost + t.refund = t.env.StateDB.GetRefund() + fmt.Fprintf(&t.stitchingBuffer, "| %4d | %10v | %s |%s |", pc, vm.OpCode(op).String(), + /* placeholders */ "%3d", "%10v") if !t.cfg.DisableStack { // format stack @@ -509,11 +579,14 @@ func (t *mdLogger) OnOpcode(pc uint64, op byte, gas, cost uint64, scope tracing. a = append(a, elem.Hex()) } b := fmt.Sprintf("[%v]", strings.Join(a, ",")) - fmt.Fprintf(t.out, "%10v |", b) + fmt.Fprintf(&t.stitchingBuffer, "%10v |", b) } - fmt.Fprintln(t.out, "") + fmt.Fprintln(&t.stitchingBuffer, "") if err != nil { - fmt.Fprintf(t.out, "Error: %v\n", err) + fmt.Fprintf(&t.stitchingBuffer, "Error: %v\n", err) + } + if op == byte(vm.STOP) { + t.flushInflightLog() } } @@ -521,7 +594,15 @@ func (t *mdLogger) OnFault(pc uint64, op byte, gas, cost uint64, scope tracing.O if t.skip { return } - fmt.Fprintf(t.out, "\nError: at pc=%d, op=%v: %v\n", pc, op, err) + t.flushInflightLog() + fmt.Fprintf(t.out, "Error: at pc=%d, op=%v: %v\n", pc, op, err) +} + +func (t *mdLogger) flushInflightLog() { + if t.stitchingBuffer.Len() > 0 { + fmt.Fprintf(t.out, t.stitchingBuffer.String(), t.cost, t.refund) + t.stitchingBuffer.Reset() + } } // ExecutionResult groups all structured logs emitted by the EVM diff --git a/eth/tracers/logger/logger_json.go b/eth/tracers/logger/logger_json.go index 52ac3945d4..7977cc09db 100644 --- a/eth/tracers/logger/logger_json.go +++ b/eth/tracers/logger/logger_json.go @@ -20,6 +20,7 @@ import ( "encoding/json" "io" "math/big" + "slices" "github.com/ethereum/go-ethereum/common" "github.com/ethereum/go-ethereum/common/hexutil" @@ -27,6 +28,7 @@ import ( "github.com/ethereum/go-ethereum/core/tracing" "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/core/vm" + "github.com/holiman/uint256" ) //go:generate go run github.com/fjl/gencodec -type callFrame -field-override callFrameMarshaling -out gen_callframe.go @@ -59,6 +61,9 @@ type jsonLogger struct { cfg *Config env *tracing.VMContext hooks *tracing.Hooks + + // stitchingContext + inflightLog StructLog } // NewJSONLogger creates a new EVM tracer that prints execution steps as JSON objects @@ -68,12 +73,14 @@ func NewJSONLogger(cfg *Config, writer io.Writer) *tracing.Hooks { if l.cfg == nil { l.cfg = &Config{} } + l.inflightLog = StructLog{Depth: -1, Memory: []byte{}, Stack: []uint256.Int{}, ReturnData: []byte{}} l.hooks = &tracing.Hooks{ OnTxStart: l.OnTxStart, OnSystemCallStart: l.onSystemCallStart, OnExit: l.OnExit, OnOpcode: l.OnOpcode, OnFault: l.OnFault, + OnGasChange: l.OnGasChange, } return l.hooks } @@ -85,6 +92,7 @@ func NewJSONLoggerWithCallFrames(cfg *Config, writer io.Writer) *tracing.Hooks { if l.cfg == nil { l.cfg = &Config{} } + l.inflightLog = StructLog{Depth: -1, Memory: []byte{}, Stack: []uint256.Int{}, ReturnData: []byte{}} l.hooks = &tracing.Hooks{ OnTxStart: l.OnTxStart, OnSystemCallStart: l.onSystemCallStart, @@ -92,20 +100,38 @@ func NewJSONLoggerWithCallFrames(cfg *Config, writer io.Writer) *tracing.Hooks { OnExit: l.OnExit, OnOpcode: l.OnOpcode, OnFault: l.OnFault, + OnGasChange: l.OnGasChange, } return l.hooks } func (l *jsonLogger) OnFault(pc uint64, op byte, gas uint64, cost uint64, scope tracing.OpContext, depth int, err error) { - // TODO: Add rData to this interface as well - l.OnOpcode(pc, op, gas, cost, scope, nil, depth, err) + l.inflightLog.Err = err + l.flushInflightLog() +} + +func (l *jsonLogger) OnGasChange(old, new uint64, reason tracing.GasChangeReason) { + if reason == tracing.GasChangeCallOpCodeDynamic { + l.inflightLog.GasCost += old - new + l.inflightLog.RefundCounter = l.env.StateDB.GetRefund() + } +} + +func (l *jsonLogger) flushInflightLog() { + if l.inflightLog.Depth != -1 { + l.encoder.Encode(l.inflightLog) + } + l.inflightLog.Depth = -1 // Signify no inflight log } func (l *jsonLogger) OnOpcode(pc uint64, op byte, gas, cost uint64, scope tracing.OpContext, rData []byte, depth int, err error) { - memory := scope.MemoryData() - stack := scope.StackData() + l.flushInflightLog() + memoryBuf := l.inflightLog.Memory[:0] + stackBuf := l.inflightLog.Stack[:0] + rDataBuf := l.inflightLog.ReturnData[:0] - log := StructLog{ + memory := scope.MemoryData() + l.inflightLog = StructLog{ Pc: pc, Op: vm.OpCode(op), Gas: gas, @@ -114,17 +140,27 @@ func (l *jsonLogger) OnOpcode(pc uint64, op byte, gas, cost uint64, scope tracin Depth: depth, RefundCounter: l.env.StateDB.GetRefund(), Err: err, + Memory: memoryBuf, + Stack: stackBuf, + ReturnData: rDataBuf, } + + // Since we are holding on to the data for a little longer and it might get modified before + // we know about it. We need to make copies here. if l.cfg.EnableMemory { - log.Memory = memory + l.inflightLog.Memory = append(slices.Grow(memoryBuf, len(memory)), memory...) } if !l.cfg.DisableStack { - log.Stack = stack + stack := scope.StackData() + l.inflightLog.Stack = append(slices.Grow(stackBuf, len(stack)), stack...) } if l.cfg.EnableReturnData { - log.ReturnData = rData + l.inflightLog.ReturnData = append(slices.Grow(rDataBuf, len(rData)), rData...) + } + + if op == byte(vm.STOP) { + l.flushInflightLog() } - l.encoder.Encode(log) } func (l *jsonLogger) onSystemCallStart() { @@ -139,6 +175,7 @@ func (l *jsonLogger) onSystemCallStart() { // OnEnter is not enabled by default. func (l *jsonLogger) OnEnter(depth int, typ byte, from common.Address, to common.Address, input []byte, gas uint64, value *big.Int) { + l.flushInflightLog() frame := callFrame{ op: vm.OpCode(typ), From: from, @@ -153,6 +190,7 @@ func (l *jsonLogger) OnEnter(depth int, typ byte, from common.Address, to common } func (l *jsonLogger) OnExit(depth int, output []byte, gasUsed uint64, err error, reverted bool) { + l.flushInflightLog() type endLog struct { Output string `json:"output"` GasUsed math.HexOrDecimal64 `json:"gasUsed"`