From fb3a081c7e534248437595d42b085a1a7221202b Mon Sep 17 00:00:00 2001 From: Sina Mahmoodi <1591639+s1na@users.noreply.github.com> Date: Wed, 6 Apr 2022 09:34:18 +0200 Subject: [PATCH] eth/tracers: refactor traceTx to separate out struct logging (#24326) * eth/tracers: refactor traceTx to separate out struct logging review fix Update eth/tracers/api.go Co-authored-by: Martin Holst Swende Mv ExecutionResult type to logger package review fix impl GetResult for StructLogger make formatLogs private confused exit and end.. account for intrinsicGas in structlogger, fix TraceCall test Add Stop method to logger Simplify traceTx Fix test rm logger from blockchain test account for refund in structLogger * use tx hooks in struct logger * minor * avoid executionResult in struct logger * revert blockchain test changes --- eth/tracers/api.go | 83 ++++++++--------------- eth/tracers/api_test.go | 33 +++++---- eth/tracers/logger/logger.go | 127 ++++++++++++++++++++++++++++++++--- internal/ethapi/api.go | 63 ----------------- 4 files changed, 167 insertions(+), 139 deletions(-) diff --git a/eth/tracers/api.go b/eth/tracers/api.go index 6055a556e..b7edc2236 100644 --- a/eth/tracers/api.go +++ b/eth/tracers/api.go @@ -862,71 +862,46 @@ func (api *API) TraceCall(ctx context.Context, args ethapi.TransactionArgs, bloc // executes the given message in the provided environment. The return value will // be tracer dependent. func (api *API) traceTx(ctx context.Context, message core.Message, txctx *Context, vmctx vm.BlockContext, statedb *state.StateDB, config *TraceConfig) (interface{}, error) { - // Assemble the structured logger or the JavaScript tracer var ( - tracer vm.EVMLogger + tracer Tracer err error + timeout = defaultTraceTimeout txContext = core.NewEVMTxContext(message) ) - switch { - case config == nil: - tracer = logger.NewStructLogger(nil) - case config.Tracer != nil: - // Define a meaningful timeout of a single transaction trace - timeout := defaultTraceTimeout - if config.Timeout != nil { - if timeout, err = time.ParseDuration(*config.Timeout); err != nil { - return nil, err - } - } - if t, err := New(*config.Tracer, txctx); err != nil { - return nil, err - } else { - deadlineCtx, cancel := context.WithTimeout(ctx, timeout) - go func() { - <-deadlineCtx.Done() - if errors.Is(deadlineCtx.Err(), context.DeadlineExceeded) { - t.Stop(errors.New("execution timeout")) - } - }() - defer cancel() - tracer = t - } - default: - tracer = logger.NewStructLogger(config.Config) + if config == nil { + config = &TraceConfig{} } + // Default tracer is the struct logger + tracer = logger.NewStructLogger(config.Config) + if config.Tracer != nil { + tracer, err = New(*config.Tracer, txctx) + if err != nil { + return nil, err + } + } + // Define a meaningful timeout of a single transaction trace + if config.Timeout != nil { + if timeout, err = time.ParseDuration(*config.Timeout); err != nil { + return nil, err + } + } + deadlineCtx, cancel := context.WithTimeout(ctx, timeout) + go func() { + <-deadlineCtx.Done() + if errors.Is(deadlineCtx.Err(), context.DeadlineExceeded) { + tracer.Stop(errors.New("execution timeout")) + } + }() + defer cancel() + // Run the transaction with tracing enabled. vmenv := vm.NewEVM(vmctx, txContext, statedb, api.backend.ChainConfig(), vm.Config{Debug: true, Tracer: tracer, NoBaseFee: true}) - // Call Prepare to clear out the statedb access list statedb.Prepare(txctx.TxHash, txctx.TxIndex) - - result, err := core.ApplyMessage(vmenv, message, new(core.GasPool).AddGas(message.Gas())) - if err != nil { + if _, err = core.ApplyMessage(vmenv, message, new(core.GasPool).AddGas(message.Gas())); err != nil { return nil, fmt.Errorf("tracing failed: %w", err) } - - // Depending on the tracer type, format and return the output. - switch tracer := tracer.(type) { - case *logger.StructLogger: - // If the result contains a revert reason, return it. - returnVal := fmt.Sprintf("%x", result.Return()) - if len(result.Revert()) > 0 { - returnVal = fmt.Sprintf("%x", result.Revert()) - } - return ðapi.ExecutionResult{ - Gas: result.UsedGas, - Failed: result.Failed(), - ReturnValue: returnVal, - StructLogs: ethapi.FormatLogs(tracer.StructLogs()), - }, nil - - case Tracer: - return tracer.GetResult() - - default: - panic(fmt.Sprintf("bad tracer type %T", tracer)) - } + return tracer.GetResult() } // APIs return the collection of RPC services the tracer package offers. diff --git a/eth/tracers/api_test.go b/eth/tracers/api_test.go index a3c0a7249..af41f05d2 100644 --- a/eth/tracers/api_test.go +++ b/eth/tracers/api_test.go @@ -39,6 +39,7 @@ import ( "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/core/vm" "github.com/ethereum/go-ethereum/crypto" + "github.com/ethereum/go-ethereum/eth/tracers/logger" "github.com/ethereum/go-ethereum/ethdb" "github.com/ethereum/go-ethereum/internal/ethapi" "github.com/ethereum/go-ethereum/params" @@ -213,11 +214,11 @@ func TestTraceCall(t *testing.T) { }, config: nil, expectErr: nil, - expect: ðapi.ExecutionResult{ + expect: &logger.ExecutionResult{ Gas: params.TxGas, Failed: false, ReturnValue: "", - StructLogs: []ethapi.StructLogRes{}, + StructLogs: []logger.StructLogRes{}, }, }, // Standard JSON trace upon the head, plain transfer. @@ -230,11 +231,11 @@ func TestTraceCall(t *testing.T) { }, config: nil, expectErr: nil, - expect: ðapi.ExecutionResult{ + expect: &logger.ExecutionResult{ Gas: params.TxGas, Failed: false, ReturnValue: "", - StructLogs: []ethapi.StructLogRes{}, + StructLogs: []logger.StructLogRes{}, }, }, // Standard JSON trace upon the non-existent block, error expects @@ -259,11 +260,11 @@ func TestTraceCall(t *testing.T) { }, config: nil, expectErr: nil, - expect: ðapi.ExecutionResult{ + expect: &logger.ExecutionResult{ Gas: params.TxGas, Failed: false, ReturnValue: "", - StructLogs: []ethapi.StructLogRes{}, + StructLogs: []logger.StructLogRes{}, }, }, // Standard JSON trace upon the pending block @@ -276,11 +277,11 @@ func TestTraceCall(t *testing.T) { }, config: nil, expectErr: nil, - expect: ðapi.ExecutionResult{ + expect: &logger.ExecutionResult{ Gas: params.TxGas, Failed: false, ReturnValue: "", - StructLogs: []ethapi.StructLogRes{}, + StructLogs: []logger.StructLogRes{}, }, }, } @@ -299,8 +300,12 @@ func TestTraceCall(t *testing.T) { t.Errorf("Expect no error, get %v", err) continue } - if !reflect.DeepEqual(result, testspec.expect) { - t.Errorf("Result mismatch, want %v, get %v", testspec.expect, result) + var have *logger.ExecutionResult + if err := json.Unmarshal(result.(json.RawMessage), &have); err != nil { + t.Errorf("failed to unmarshal result %v", err) + } + if !reflect.DeepEqual(have, testspec.expect) { + t.Errorf("Result mismatch, want %v, get %v", testspec.expect, have) } } } @@ -329,11 +334,15 @@ func TestTraceTransaction(t *testing.T) { if err != nil { t.Errorf("Failed to trace transaction %v", err) } - if !reflect.DeepEqual(result, ðapi.ExecutionResult{ + var have *logger.ExecutionResult + if err := json.Unmarshal(result.(json.RawMessage), &have); err != nil { + t.Errorf("failed to unmarshal result %v", err) + } + if !reflect.DeepEqual(have, &logger.ExecutionResult{ Gas: params.TxGas, Failed: false, ReturnValue: "", - StructLogs: []ethapi.StructLogRes{}, + StructLogs: []logger.StructLogRes{}, }) { t.Error("Transaction tracing result is different") } diff --git a/eth/tracers/logger/logger.go b/eth/tracers/logger/logger.go index fe15c97ef..c4dec9f36 100644 --- a/eth/tracers/logger/logger.go +++ b/eth/tracers/logger/logger.go @@ -18,10 +18,12 @@ package logger import ( "encoding/hex" + "encoding/json" "fmt" "io" "math/big" "strings" + "sync/atomic" "time" "github.com/ethereum/go-ethereum/common" @@ -108,10 +110,15 @@ type StructLogger struct { cfg Config env *vm.EVM - storage map[common.Address]Storage - logs []StructLog - output []byte - err error + storage map[common.Address]Storage + logs []StructLog + output []byte + err error + gasLimit uint64 + usedGas uint64 + + interrupt uint32 // Atomic flag to signal execution interruption + reason error // Textual reason for the interruption } // NewStructLogger returns a new logger @@ -142,13 +149,19 @@ func (l *StructLogger) CaptureStart(env *vm.EVM, from common.Address, to common. // // CaptureState also tracks SLOAD/SSTORE ops to track storage change. func (l *StructLogger) CaptureState(pc uint64, op vm.OpCode, gas, cost uint64, scope *vm.ScopeContext, rData []byte, depth int, err error) { - memory := scope.Memory - stack := scope.Stack - contract := scope.Contract + // If tracing was interrupted, set the error and stop + if atomic.LoadUint32(&l.interrupt) > 0 { + l.env.Cancel() + return + } // check if already accumulated the specified number of logs if l.cfg.Limit != 0 && l.cfg.Limit <= len(l.logs) { return } + + memory := scope.Memory + stack := scope.Stack + contract := scope.Contract // Copy a snapshot of the current memory state to a new buffer var mem []byte if l.cfg.EnableMemory { @@ -221,11 +234,42 @@ func (l *StructLogger) CaptureEnd(output []byte, gasUsed uint64, t time.Duration func (l *StructLogger) CaptureEnter(typ vm.OpCode, from common.Address, to common.Address, input []byte, gas uint64, value *big.Int) { } -func (l *StructLogger) CaptureExit(output []byte, gasUsed uint64, err error) {} +func (l *StructLogger) CaptureExit(output []byte, gasUsed uint64, err error) { +} -func (*StructLogger) CaptureTxStart(gasLimit uint64) {} +func (l *StructLogger) GetResult() (json.RawMessage, error) { + // Tracing aborted + if l.reason != nil { + return nil, l.reason + } + failed := l.err != nil + returnData := common.CopyBytes(l.output) + // Return data when successful and revert reason when reverted, otherwise empty. + returnVal := fmt.Sprintf("%x", returnData) + if failed && l.err != vm.ErrExecutionReverted { + returnVal = "" + } + return json.Marshal(&ExecutionResult{ + Gas: l.usedGas, + Failed: failed, + ReturnValue: returnVal, + StructLogs: formatLogs(l.StructLogs()), + }) +} -func (*StructLogger) CaptureTxEnd(restGas uint64) {} +// Stop terminates execution of the tracer at the first opportune moment. +func (l *StructLogger) Stop(err error) { + l.reason = err + atomic.StoreUint32(&l.interrupt, 1) +} + +func (l *StructLogger) CaptureTxStart(gasLimit uint64) { + l.gasLimit = gasLimit +} + +func (l *StructLogger) CaptureTxEnd(restGas uint64) { + l.usedGas = l.gasLimit - restGas +} // StructLogs returns the captured log entries. func (l *StructLogger) StructLogs() []StructLog { return l.logs } @@ -355,3 +399,66 @@ func (t *mdLogger) CaptureExit(output []byte, gasUsed uint64, err error) {} func (*mdLogger) CaptureTxStart(gasLimit uint64) {} func (*mdLogger) CaptureTxEnd(restGas uint64) {} + +// ExecutionResult groups all structured logs emitted by the EVM +// while replaying a transaction in debug mode as well as transaction +// execution status, the amount of gas used and the return value +type ExecutionResult struct { + Gas uint64 `json:"gas"` + Failed bool `json:"failed"` + ReturnValue string `json:"returnValue"` + StructLogs []StructLogRes `json:"structLogs"` +} + +// StructLogRes stores a structured log emitted by the EVM while replaying a +// transaction in debug mode +type StructLogRes struct { + Pc uint64 `json:"pc"` + Op string `json:"op"` + Gas uint64 `json:"gas"` + GasCost uint64 `json:"gasCost"` + Depth int `json:"depth"` + Error string `json:"error,omitempty"` + Stack *[]string `json:"stack,omitempty"` + Memory *[]string `json:"memory,omitempty"` + Storage *map[string]string `json:"storage,omitempty"` + RefundCounter uint64 `json:"refund,omitempty"` +} + +// formatLogs formats EVM returned structured logs for json output +func formatLogs(logs []StructLog) []StructLogRes { + formatted := make([]StructLogRes, len(logs)) + for index, trace := range logs { + formatted[index] = StructLogRes{ + Pc: trace.Pc, + Op: trace.Op.String(), + Gas: trace.Gas, + GasCost: trace.GasCost, + Depth: trace.Depth, + Error: trace.ErrorString(), + RefundCounter: trace.RefundCounter, + } + if trace.Stack != nil { + stack := make([]string, len(trace.Stack)) + for i, stackValue := range trace.Stack { + stack[i] = stackValue.Hex() + } + formatted[index].Stack = &stack + } + if trace.Memory != nil { + memory := make([]string, 0, (len(trace.Memory)+31)/32) + for i := 0; i+32 <= len(trace.Memory); i += 32 { + memory = append(memory, fmt.Sprintf("%x", trace.Memory[i:i+32])) + } + formatted[index].Memory = &memory + } + if trace.Storage != nil { + storage := make(map[string]string) + for i, storageValue := range trace.Storage { + storage[fmt.Sprintf("%x", i)] = fmt.Sprintf("%x", storageValue) + } + formatted[index].Storage = &storage + } + } + return formatted +} diff --git a/internal/ethapi/api.go b/internal/ethapi/api.go index 491c9b134..d08767379 100644 --- a/internal/ethapi/api.go +++ b/internal/ethapi/api.go @@ -1122,69 +1122,6 @@ func (s *PublicBlockChainAPI) EstimateGas(ctx context.Context, args TransactionA return DoEstimateGas(ctx, s.b, args, bNrOrHash, s.b.RPCGasCap()) } -// ExecutionResult groups all structured logs emitted by the EVM -// while replaying a transaction in debug mode as well as transaction -// execution status, the amount of gas used and the return value -type ExecutionResult struct { - Gas uint64 `json:"gas"` - Failed bool `json:"failed"` - ReturnValue string `json:"returnValue"` - StructLogs []StructLogRes `json:"structLogs"` -} - -// StructLogRes stores a structured log emitted by the EVM while replaying a -// transaction in debug mode -type StructLogRes struct { - Pc uint64 `json:"pc"` - Op string `json:"op"` - Gas uint64 `json:"gas"` - GasCost uint64 `json:"gasCost"` - Depth int `json:"depth"` - Error string `json:"error,omitempty"` - Stack *[]string `json:"stack,omitempty"` - Memory *[]string `json:"memory,omitempty"` - Storage *map[string]string `json:"storage,omitempty"` - RefundCounter uint64 `json:"refund,omitempty"` -} - -// FormatLogs formats EVM returned structured logs for json output -func FormatLogs(logs []logger.StructLog) []StructLogRes { - formatted := make([]StructLogRes, len(logs)) - for index, trace := range logs { - formatted[index] = StructLogRes{ - Pc: trace.Pc, - Op: trace.Op.String(), - Gas: trace.Gas, - GasCost: trace.GasCost, - Depth: trace.Depth, - Error: trace.ErrorString(), - RefundCounter: trace.RefundCounter, - } - if trace.Stack != nil { - stack := make([]string, len(trace.Stack)) - for i, stackValue := range trace.Stack { - stack[i] = stackValue.Hex() - } - formatted[index].Stack = &stack - } - if trace.Memory != nil { - memory := make([]string, 0, (len(trace.Memory)+31)/32) - for i := 0; i+32 <= len(trace.Memory); i += 32 { - memory = append(memory, fmt.Sprintf("%x", trace.Memory[i:i+32])) - } - formatted[index].Memory = &memory - } - if trace.Storage != nil { - storage := make(map[string]string) - for i, storageValue := range trace.Storage { - storage[fmt.Sprintf("%x", i)] = fmt.Sprintf("%x", storageValue) - } - formatted[index].Storage = &storage - } - } - return formatted -} - // RPCMarshalHeader converts the given header to the RPC output . func RPCMarshalHeader(head *types.Header) map[string]interface{} { result := map[string]interface{}{