diff --git a/cmd/evm/main.go b/cmd/evm/main.go index 750b269906..6e0345ce63 100644 --- a/cmd/evm/main.go +++ b/cmd/evm/main.go @@ -240,13 +240,13 @@ func tracerFromFlags(ctx *cli.Context) *tracing.Hooks { } switch { case ctx.Bool(TraceFlag.Name) && ctx.String(TraceFormatFlag.Name) == "struct": - return logger.NewStructLogger(config).Hooks() + return logger.NewStreamingStructLogger(config, os.Stderr).Hooks() case ctx.Bool(TraceFlag.Name) && ctx.String(TraceFormatFlag.Name) == "json": return logger.NewJSONLogger(config, os.Stderr) case ctx.Bool(MachineFlag.Name): return logger.NewJSONLogger(config, os.Stderr) case ctx.Bool(DebugFlag.Name): - return logger.NewStructLogger(config).Hooks() + return logger.NewStreamingStructLogger(config, os.Stderr).Hooks() default: return nil } diff --git a/cmd/evm/runner.go b/cmd/evm/runner.go index afb0bec0ef..59ad8687d5 100644 --- a/cmd/evm/runner.go +++ b/cmd/evm/runner.go @@ -18,6 +18,7 @@ package main import ( "bytes" + "encoding/hex" "encoding/json" "fmt" "io" @@ -35,6 +36,7 @@ import ( "github.com/ethereum/go-ethereum/core/rawdb" "github.com/ethereum/go-ethereum/core/state" "github.com/ethereum/go-ethereum/core/tracing" + "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/core/vm" "github.com/ethereum/go-ethereum/core/vm/runtime" "github.com/ethereum/go-ethereum/eth/tracers/logger" @@ -205,7 +207,6 @@ func runCmd(ctx *cli.Context) error { var ( tracer *tracing.Hooks - debugLogger *logger.StructLogger prestate *state.StateDB chainConfig *params.ChainConfig sender = common.BytesToAddress([]byte("sender")) @@ -217,10 +218,7 @@ func runCmd(ctx *cli.Context) error { if ctx.Bool(MachineFlag.Name) { tracer = logger.NewJSONLogger(logconfig, os.Stdout) } else if ctx.Bool(DebugFlag.Name) { - debugLogger = logger.NewStructLogger(logconfig) - tracer = debugLogger.Hooks() - } else { - debugLogger = logger.NewStructLogger(logconfig) + tracer = logger.NewStreamingStructLogger(logconfig, os.Stderr).Hooks() } initialGas := ctx.Uint64(GasFlag.Name) @@ -365,12 +363,10 @@ func runCmd(ctx *cli.Context) error { } if ctx.Bool(DebugFlag.Name) { - if debugLogger != nil { - fmt.Fprintln(os.Stderr, "#### TRACE ####") - logger.WriteTrace(os.Stderr, debugLogger.StructLogs()) + if logs := runtimeConfig.State.Logs(); len(logs) > 0 { + fmt.Fprintln(os.Stderr, "### LOGS") + writeLogs(os.Stderr, logs) } - fmt.Fprintln(os.Stderr, "#### LOGS ####") - logger.WriteLogs(os.Stderr, runtimeConfig.State.Logs()) } if bench || ctx.Bool(StatDumpFlag.Name) { @@ -389,3 +385,16 @@ allocated bytes: %d return nil } + +// writeLogs writes vm logs in a readable format to the given writer +func writeLogs(writer io.Writer, logs []*types.Log) { + for _, log := range logs { + fmt.Fprintf(writer, "LOG%d: %x bn=%d txi=%x\n", len(log.Topics), log.Address, log.BlockNumber, log.TxIndex) + + for i, topic := range log.Topics { + fmt.Fprintf(writer, "%08d %x\n", i, topic) + } + fmt.Fprint(writer, hex.Dump(log.Data)) + fmt.Fprintln(writer) + } +} diff --git a/core/vm/runtime/runtime_test.go b/core/vm/runtime/runtime_test.go index 7d1345a57b..0e774a01c2 100644 --- a/core/vm/runtime/runtime_test.go +++ b/core/vm/runtime/runtime_test.go @@ -31,6 +31,7 @@ import ( "github.com/ethereum/go-ethereum/core" "github.com/ethereum/go-ethereum/core/asm" "github.com/ethereum/go-ethereum/core/state" + "github.com/ethereum/go-ethereum/core/tracing" "github.com/ethereum/go-ethereum/core/types" "github.com/ethereum/go-ethereum/core/vm" "github.com/ethereum/go-ethereum/core/vm/program" @@ -670,17 +671,23 @@ func TestColdAccountAccessCost(t *testing.T) { want: 7600, }, } { - tracer := logger.NewStructLogger(nil) + var step = 0 + var have = uint64(0) Execute(tc.code, nil, &Config{ EVMConfig: vm.Config{ - Tracer: tracer.Hooks(), + Tracer: &tracing.Hooks{ + 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) + if step == tc.step { + have = cost + } + step++ + }, + }, }, }) - have := tracer.StructLogs()[tc.step].GasCost if want := tc.want; have != want { - for ii, op := range tracer.StructLogs() { - t.Logf("%d: %v %d", ii, op.OpName(), op.GasCost) - } t.Fatalf("testcase %d, gas report wrong, step %d, have %d want %d", i, tc.step, have, want) } } diff --git a/eth/tracers/api_test.go b/eth/tracers/api_test.go index e5940b6828..e786853ede 100644 --- a/eth/tracers/api_test.go +++ b/eth/tracers/api_test.go @@ -535,7 +535,7 @@ func TestTraceTransaction(t *testing.T) { Gas: params.TxGas, Failed: false, ReturnValue: "", - StructLogs: []logger.StructLogRes{}, + StructLogs: []json.RawMessage{}, }) { t.Error("Transaction tracing result is different") } diff --git a/eth/tracers/logger/logger.go b/eth/tracers/logger/logger.go index bdd4e07055..51b1512d03 100644 --- a/eth/tracers/logger/logger.go +++ b/eth/tracers/logger/logger.go @@ -21,6 +21,7 @@ import ( "encoding/json" "fmt" "io" + "maps" "math/big" "strings" "sync/atomic" @@ -38,15 +39,6 @@ import ( // Storage represents a contract's storage. type Storage map[common.Hash]common.Hash -// Copy duplicates the current storage. -func (s Storage) Copy() Storage { - cpy := make(Storage, len(s)) - for key, value := range s { - cpy[key] = value - } - return cpy -} - // Config are the configuration options for structured logger the EVM type Config struct { EnableMemory bool // enable memory capture @@ -54,15 +46,16 @@ type Config struct { DisableStorage bool // disable storage capture EnableReturnData bool // enable return data capture Debug bool // print output during capture end - Limit int // maximum length of output, but zero means unlimited + Limit int // maximum size of output, but zero means unlimited + // Chain overrides, can be used to execute a trace using future fork rules Overrides *params.ChainConfig `json:"overrides,omitempty"` } //go:generate go run github.com/fjl/gencodec -type StructLog -field-override structLogMarshaling -out gen_structlog.go -// StructLog is emitted to the EVM each cycle and lists information about the current internal state -// prior to the execution of the statement. +// StructLog is emitted to the EVM each cycle and lists information about the +// current internal state prior to the execution of the statement. type StructLog struct { Pc uint64 `json:"pc"` Op vm.OpCode `json:"op"` @@ -102,29 +95,144 @@ func (s *StructLog) ErrorString() string { return "" } +// WriteTo writes the human-readable log data into the supplied writer. +func (s *StructLog) WriteTo(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) + + if len(s.Stack) > 0 { + fmt.Fprintln(writer, "Stack:") + for i := len(s.Stack) - 1; i >= 0; i-- { + fmt.Fprintf(writer, "%08d %s\n", len(s.Stack)-i-1, s.Stack[i].Hex()) + } + } + if len(s.Memory) > 0 { + fmt.Fprintln(writer, "Memory:") + fmt.Fprint(writer, hex.Dump(s.Memory)) + } + if len(s.Storage) > 0 { + fmt.Fprintln(writer, "Storage:") + for h, item := range s.Storage { + fmt.Fprintf(writer, "%x: %x\n", h, item) + } + } + if len(s.ReturnData) > 0 { + fmt.Fprintln(writer, "ReturnData:") + fmt.Fprint(writer, hex.Dump(s.ReturnData)) + } + fmt.Fprintln(writer) +} + +// structLogLegacy stores a structured log emitted by the EVM while replaying a +// transaction in debug mode. It's the legacy format used in tracer. The differences +// between the structLog json and the 'legacy' json are: +// +// op: +// Legacy uses string (e.g. "SSTORE"), non-legacy uses a byte. +// non-legacy has an 'opName' field containing the op name. +// +// gas, gasCost: +// Legacy uses integers, non-legacy hex-strings +// +// memory: +// Legacy uses a list of 64-char strings, each representing 32-byte chunks +// of evm memory. Non-legacy just uses a string of hexdata, no chunking. +// +// storage: +// Legacy has a storage field while non-legacy doesn't. +type structLogLegacy 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"` + ReturnData string `json:"returnData,omitempty"` + Memory *[]string `json:"memory,omitempty"` + Storage *map[string]string `json:"storage,omitempty"` + RefundCounter uint64 `json:"refund,omitempty"` +} + +// toLegacyJSON converts the structLog to legacy json-encoded legacy form. +func (s *StructLog) toLegacyJSON() json.RawMessage { + msg := structLogLegacy{ + Pc: s.Pc, + Op: s.Op.String(), + Gas: s.Gas, + GasCost: s.GasCost, + Depth: s.Depth, + Error: s.ErrorString(), + RefundCounter: s.RefundCounter, + } + if s.Stack != nil { + stack := make([]string, len(s.Stack)) + for i, stackValue := range s.Stack { + stack[i] = stackValue.Hex() + } + msg.Stack = &stack + } + if len(s.ReturnData) > 0 { + msg.ReturnData = hexutil.Bytes(s.ReturnData).String() + } + if s.Memory != nil { + memory := make([]string, 0, (len(s.Memory)+31)/32) + for i := 0; i+32 <= len(s.Memory); i += 32 { + memory = append(memory, fmt.Sprintf("%x", s.Memory[i:i+32])) + } + msg.Memory = &memory + } + if s.Storage != nil { + storage := make(map[string]string) + for i, storageValue := range s.Storage { + storage[fmt.Sprintf("%x", i)] = fmt.Sprintf("%x", storageValue) + } + msg.Storage = &storage + } + element, _ := json.Marshal(msg) + return element +} + // StructLogger is an EVM state logger and implements EVMLogger. // // StructLogger can capture state based on the given Log configuration and also keeps // a track record of modified storage which is used in reporting snapshots of the // contract their storage. +// +// A StructLogger can either yield it's output immediately (streaming) or store for +// later output. type StructLogger struct { cfg Config env *tracing.VMContext storage map[common.Address]Storage - logs []StructLog output []byte err error usedGas uint64 + writer io.Writer // If set, the logger will stream instead of store logs + logs []json.RawMessage // buffer of json-encoded logs + resultSize int + interrupt atomic.Bool // Atomic flag to signal execution interruption reason error // Textual reason for the interruption } -// NewStructLogger returns a new logger +// NewStreamingStructLogger returns a new streaming logger. +func NewStreamingStructLogger(cfg *Config, writer io.Writer) *StructLogger { + l := NewStructLogger(cfg) + l.writer = writer + return l +} + +// NewStructLogger construct a new (non-streaming) struct logger. func NewStructLogger(cfg *Config) *StructLogger { logger := &StructLogger{ storage: make(map[common.Address]Storage), + logs: make([]json.RawMessage, 0), } if cfg != nil { logger.cfg = *cfg @@ -141,44 +249,36 @@ func (l *StructLogger) Hooks() *tracing.Hooks { } } -// Reset clears the data held by the logger. -func (l *StructLogger) Reset() { - l.storage = make(map[common.Address]Storage) - l.output = make([]byte, 0) - l.logs = l.logs[:0] - l.err = nil -} - // OnOpcode logs a new structured log message and pushes it out to the environment // // OnOpcode also tracks SLOAD/SSTORE ops to track storage change. func (l *StructLogger) OnOpcode(pc uint64, opcode byte, gas, cost uint64, scope tracing.OpContext, rData []byte, depth int, err error) { - // If tracing was interrupted, set the error and stop + // If tracing was interrupted, exit if l.interrupt.Load() { return } - // check if already accumulated the specified number of logs - if l.cfg.Limit != 0 && l.cfg.Limit <= len(l.logs) { + // check if already accumulated the size of the response. + if l.cfg.Limit != 0 && l.resultSize > l.cfg.Limit { return } - - op := vm.OpCode(opcode) - memory := scope.MemoryData() - stack := scope.StackData() - // Copy a snapshot of the current memory state to a new buffer - var mem []byte + var ( + op = vm.OpCode(opcode) + memory = scope.MemoryData() + contractAddr = scope.Address() + stack = scope.StackData() + stackLen = len(stack) + ) + log := StructLog{pc, op, gas, cost, nil, len(memory), nil, nil, nil, depth, l.env.StateDB.GetRefund(), err} if l.cfg.EnableMemory { - mem = make([]byte, len(memory)) - copy(mem, memory) + log.Memory = memory } - // Copy a snapshot of the current stack state to a new buffer - var stck []uint256.Int if !l.cfg.DisableStack { - stck = make([]uint256.Int, len(stack)) - copy(stck, stack) + log.Stack = scope.StackData() } - contractAddr := scope.Address() - stackLen := len(stack) + if l.cfg.EnableReturnData { + log.ReturnData = rData + } + // Copy a snapshot of the current storage to a new container var storage Storage if !l.cfg.DisableStorage && (op == vm.SLOAD || op == vm.SSTORE) { @@ -194,7 +294,7 @@ func (l *StructLogger) OnOpcode(pc uint64, opcode byte, gas, cost uint64, scope value = l.env.StateDB.GetState(contractAddr, address) ) l.storage[contractAddr][address] = value - storage = l.storage[contractAddr].Copy() + storage = maps.Clone(l.storage[contractAddr]) } else if op == vm.SSTORE && stackLen >= 2 { // capture SSTORE opcodes and record the written entry in the local storage. var ( @@ -202,17 +302,19 @@ func (l *StructLogger) OnOpcode(pc uint64, opcode byte, gas, cost uint64, scope address = common.Hash(stack[stackLen-1].Bytes32()) ) l.storage[contractAddr][address] = value - storage = l.storage[contractAddr].Copy() + storage = maps.Clone(l.storage[contractAddr]) } } - var rdata []byte - if l.cfg.EnableReturnData { - rdata = make([]byte, len(rData)) - copy(rdata, rData) + log.Storage = storage + + // create a log + if l.writer == nil { + entry := log.toLegacyJSON() + l.resultSize += len(entry) + l.logs = append(l.logs, entry) + return } - // create a new snapshot of the EVM. - log := StructLog{pc, op, gas, cost, mem, len(memory), stck, rdata, storage, depth, l.env.StateDB.GetRefund(), err} - l.logs = append(l.logs, log) + log.WriteTo(l.writer) } // OnExit is called a call frame finishes processing. @@ -246,7 +348,7 @@ func (l *StructLogger) GetResult() (json.RawMessage, error) { Gas: l.usedGas, Failed: failed, ReturnValue: returnVal, - StructLogs: formatLogs(l.StructLogs()), + StructLogs: l.logs, }) } @@ -273,9 +375,6 @@ func (l *StructLogger) OnTxEnd(receipt *types.Receipt, err error) { } } -// StructLogs returns the captured log entries. -func (l *StructLogger) StructLogs() []StructLog { return l.logs } - // Error returns the VM error captured by the trace. func (l *StructLogger) Error() error { return l.err } @@ -283,49 +382,10 @@ func (l *StructLogger) Error() error { return l.err } func (l *StructLogger) Output() []byte { return l.output } // WriteTrace writes a formatted trace to the given writer +// @deprecated func WriteTrace(writer io.Writer, logs []StructLog) { for _, log := range logs { - fmt.Fprintf(writer, "%-16spc=%08d gas=%v cost=%v", log.Op, log.Pc, log.Gas, log.GasCost) - if log.Err != nil { - fmt.Fprintf(writer, " ERROR: %v", log.Err) - } - fmt.Fprintln(writer) - - if len(log.Stack) > 0 { - fmt.Fprintln(writer, "Stack:") - for i := len(log.Stack) - 1; i >= 0; i-- { - fmt.Fprintf(writer, "%08d %s\n", len(log.Stack)-i-1, log.Stack[i].Hex()) - } - } - if len(log.Memory) > 0 { - fmt.Fprintln(writer, "Memory:") - fmt.Fprint(writer, hex.Dump(log.Memory)) - } - if len(log.Storage) > 0 { - fmt.Fprintln(writer, "Storage:") - for h, item := range log.Storage { - fmt.Fprintf(writer, "%x: %x\n", h, item) - } - } - if len(log.ReturnData) > 0 { - fmt.Fprintln(writer, "ReturnData:") - fmt.Fprint(writer, hex.Dump(log.ReturnData)) - } - fmt.Fprintln(writer) - } -} - -// WriteLogs writes vm logs in a readable format to the given writer -func WriteLogs(writer io.Writer, logs []*types.Log) { - for _, log := range logs { - fmt.Fprintf(writer, "LOG%d: %x bn=%d txi=%x\n", len(log.Topics), log.Address, log.BlockNumber, log.TxIndex) - - for i, topic := range log.Topics { - fmt.Fprintf(writer, "%08d %x\n", i, topic) - } - - fmt.Fprint(writer, hex.Dump(log.Data)) - fmt.Fprintln(writer) + log.WriteTo(writer) } } @@ -425,65 +485,8 @@ func (t *mdLogger) OnFault(pc uint64, op byte, gas, cost uint64, scope tracing.O // 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"` - ReturnData string `json:"returnData,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 len(trace.ReturnData) > 0 { - formatted[index].ReturnData = hexutil.Bytes(trace.ReturnData).String() - } - 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 + Gas uint64 `json:"gas"` + Failed bool `json:"failed"` + ReturnValue string `json:"returnValue"` + StructLogs []json.RawMessage `json:"structLogs"` } diff --git a/eth/tracers/tracers_test.go b/eth/tracers/tracers_test.go index 9d8f70386f..13c36379e7 100644 --- a/eth/tracers/tracers_test.go +++ b/eth/tracers/tracers_test.go @@ -31,7 +31,7 @@ import ( "github.com/ethereum/go-ethereum/tests" ) -func BenchmarkTransactionTrace(b *testing.B) { +func BenchmarkTransactionTraceV2(b *testing.B) { key, _ := crypto.HexToECDSA("b71c71a67e1177ad4e901695e1b4b9ee17ae16c6668d313eac2f96dbcda3f291") from := crypto.PubkeyToAddress(key.PublicKey) gas := uint64(1000000) // 1M gas @@ -78,14 +78,8 @@ func BenchmarkTransactionTrace(b *testing.B) { state := tests.MakePreState(rawdb.NewMemoryDatabase(), alloc, false, rawdb.HashScheme) defer state.Close() - // Create the tracer, the EVM environment and run it - tracer := logger.NewStructLogger(&logger.Config{ - Debug: false, - //DisableStorage: true, - //EnableMemory: false, - //EnableReturnData: false, - }) - evm := vm.NewEVM(context, state.StateDB, params.AllEthashProtocolChanges, vm.Config{Tracer: tracer.Hooks()}) + evm := vm.NewEVM(context, state.StateDB, params.AllEthashProtocolChanges, vm.Config{}) + msg, err := core.TransactionToMessage(tx, signer, context.BaseFee) if err != nil { b.Fatalf("failed to prepare transaction for tracing: %v", err) @@ -94,17 +88,15 @@ func BenchmarkTransactionTrace(b *testing.B) { b.ReportAllocs() for i := 0; i < b.N; i++ { - snap := state.StateDB.Snapshot() + tracer := logger.NewStructLogger(&logger.Config{Debug: false}).Hooks() tracer.OnTxStart(evm.GetVMContext(), tx, msg.From) - res, err := core.ApplyMessage(evm, msg, new(core.GasPool).AddGas(tx.Gas())) + evm.Config.Tracer = tracer + + snap := state.StateDB.Snapshot() + _, err := core.ApplyMessage(evm, msg, new(core.GasPool).AddGas(tx.Gas())) if err != nil { b.Fatal(err) } - tracer.OnTxEnd(&types.Receipt{GasUsed: res.UsedGas}, nil) state.StateDB.RevertToSnapshot(snap) - if have, want := len(tracer.StructLogs()), 244752; have != want { - b.Fatalf("trace wrong, want %d steps, have %d", want, have) - } - tracer.Reset() } }