diff --git a/cmd/evm/runner.go b/cmd/evm/runner.go index e885ca18ad99..fe6f898c2f31 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" @@ -83,7 +84,6 @@ func runCmd(ctx *cli.Context) error { var ( tracer *tracing.Hooks - debugLogger *logger.StructLogger statedb *state.StateDB chainConfig *params.ChainConfig sender = common.StringToAddress("sender") @@ -93,10 +93,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() } if ctx.String(GenesisFlag.Name) != "" { @@ -226,12 +223,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, statedb.Logs()) } if ctx.Bool(StatDumpFlag.Name) { @@ -255,3 +250,16 @@ Gas used: %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 729cec1909d2..62d47e06a908 100644 --- a/core/vm/runtime/runtime_test.go +++ b/core/vm/runtime/runtime_test.go @@ -678,17 +678,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 66bbfb10f8f7..84fa8539de54 100644 --- a/eth/tracers/api_test.go +++ b/eth/tracers/api_test.go @@ -560,7 +560,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 e21efb739bf5..d1ea48eab39a 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 "" } +// Write writes the human-readable log data into the supplied writer. +func (s *StructLog) Write(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 its 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,32 @@ 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) { - 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() + } + if l.cfg.EnableReturnData { + log.ReturnData = rData } - contractAddr := scope.Address() - stackLen := len(stack) + // 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 +290,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 +298,22 @@ 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() + if l.cfg.Limit != 0 && l.resultSize+len(entry) > l.cfg.Limit { + return + } + 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.Write(l.writer) } // OnExit is called a call frame finishes processing. @@ -246,7 +347,7 @@ func (l *StructLogger) GetResult() (json.RawMessage, error) { Gas: l.usedGas, Failed: failed, ReturnValue: returnVal, - StructLogs: formatLogs(l.StructLogs()), + StructLogs: l.logs, }) } @@ -273,59 +374,16 @@ 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 } // Output returns the VM return value captured by the trace. func (l *StructLogger) Output() []byte { return l.output } -// WriteTrace writes a formatted trace to the given writer +// Deprecated: WriteTrace writes a formatted trace to the given writer. 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.Write(writer) } } @@ -425,65 +483,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/logger/logger_test.go b/eth/tracers/logger/logger_test.go index 8b4aac685a1b..22a80fa9eaeb 100644 --- a/eth/tracers/logger/logger_test.go +++ b/eth/tracers/logger/logger_test.go @@ -24,6 +24,7 @@ import ( "github.com/XinFinOrg/XDPoSChain/common" "github.com/XinFinOrg/XDPoSChain/core/state" + "github.com/XinFinOrg/XDPoSChain/core/tracing" "github.com/XinFinOrg/XDPoSChain/core/vm" "github.com/XinFinOrg/XDPoSChain/params" "github.com/holiman/uint256" @@ -39,6 +40,16 @@ func (*dummyStatedb) SetState(_ common.Address, _ common.Hash, _ common.Hash) co return common.Hash{} } +type dummyOpContext struct{} + +func (dummyOpContext) MemoryData() []byte { return nil } +func (dummyOpContext) StackData() []uint256.Int { return nil } +func (dummyOpContext) Caller() common.Address { return common.Address{} } +func (dummyOpContext) Address() common.Address { return common.Address{} } +func (dummyOpContext) CallValue() *uint256.Int { return new(uint256.Int) } +func (dummyOpContext) CallInput() []byte { return nil } +func (dummyOpContext) ContractCode() []byte { return nil } + func TestStoreCapture(t *testing.T) { var ( logger = NewStructLogger(nil) @@ -91,3 +102,34 @@ func TestStructLogMarshalingOmitEmpty(t *testing.T) { }) } } + +func TestStructLoggerLimitRejectsOversizedEntry(t *testing.T) { + entry := (&StructLog{Op: vm.STOP, RefundCounter: 1337}).toLegacyJSON() + logger := NewStructLogger(&Config{Limit: len(entry) - 1}) + logger.env = &tracing.VMContext{StateDB: &dummyStatedb{}} + + logger.OnOpcode(0, byte(vm.STOP), 0, 0, dummyOpContext{}, nil, 0, nil) + + if len(logger.logs) != 0 { + t.Fatalf("expected oversized entry to be skipped, got %d logs", len(logger.logs)) + } + if logger.resultSize != 0 { + t.Fatalf("expected result size to remain zero, got %d", logger.resultSize) + } +} + +func TestStructLoggerLimitAllowsEntryUpToBoundary(t *testing.T) { + entry := (&StructLog{Op: vm.STOP, RefundCounter: 1337}).toLegacyJSON() + logger := NewStructLogger(&Config{Limit: len(entry)}) + logger.env = &tracing.VMContext{StateDB: &dummyStatedb{}} + + logger.OnOpcode(0, byte(vm.STOP), 0, 0, dummyOpContext{}, nil, 0, nil) + logger.OnOpcode(0, byte(vm.STOP), 0, 0, dummyOpContext{}, nil, 0, nil) + + if len(logger.logs) != 1 { + t.Fatalf("expected exactly one log at the size boundary, got %d", len(logger.logs)) + } + if logger.resultSize != len(entry) { + t.Fatalf("expected result size %d, got %d", len(entry), logger.resultSize) + } +} diff --git a/eth/tracers/tracers_test.go b/eth/tracers/tracers_test.go index e222d590117b..09f46a122d94 100644 --- a/eth/tracers/tracers_test.go +++ b/eth/tracers/tracers_test.go @@ -31,7 +31,7 @@ import ( "github.com/XinFinOrg/XDPoSChain/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 @@ -81,34 +81,26 @@ func BenchmarkTransactionTrace(b *testing.B) { } state := tests.MakePreState(rawdb.NewMemoryDatabase(), alloc) - // 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, nil, params.AllEthashProtocolChanges, vm.Config{Tracer: tracer.Hooks()}) + evm := vm.NewEVM(context, state, nil, params.AllEthashProtocolChanges, vm.Config{}) evm.SetTxContext(txContext) + msg, err := core.TransactionToMessage(tx, signer, nil, nil, context.BaseFee) if err != nil { b.Fatalf("failed to prepare transaction for tracing: %v", err) } + b.ResetTimer() b.ReportAllocs() - for b.Loop() { - snap := state.Snapshot() + for i := 0; i < b.N; i++ { + tracer := logger.NewStructLogger(&logger.Config{Debug: false}).Hooks() tracer.OnTxStart(evm.GetVMContext(), tx, msg.From) - st := core.NewStateTransition(evm, msg, new(core.GasPool).AddGas(tx.Gas())) - res, err := st.TransitionDb(common.Address{}) + evm.Config.Tracer = tracer + + snap := state.Snapshot() + _, err := core.ApplyMessage(evm, msg, new(core.GasPool).AddGas(tx.Gas()), common.Address{}) if err != nil { b.Fatal(err) } - tracer.OnTxEnd(&types.Receipt{GasUsed: res.UsedGas}, nil) state.RevertToSnapshot(snap) - if have, want := len(tracer.StructLogs()), 244752; have != want { - b.Fatalf("trace wrong, want %d steps, have %d", want, have) - } - tracer.Reset() } }