interesting
/
go-ethereum
mirror of https://github.com/ethereum/go-ethereum.git
1
0
Fork 0
Code Issues Projects Releases Wiki Activity

cmd/evm, eth/tracers: refactor structlogger and make it streaming (#30806) 

This PR refactors the structlog a bit, making it so that it can be used
in a streaming mode.

-------------

OBS: this PR makes a change in the input `config` config, the third
input-parem field to `debug.traceCall`. Previously, seteting it to e.g.
` {"enableMemory": true, "limit": 1024}` would mean that the response
was limited to `1024` items. Since an 'item' may include both memory and
storage, the actual size of the response was undertermined.
After this change, the response will be limited to `1024` __`bytes`__
(or thereabouts).



-----------


The commandline usage of structlog now uses the streaming mode, leaving
the non-streaming mode of operation for the eth_Call.

There are two benefits of streaming mode 
1. Not have to maintain a long list of operations, 
2. Not have to duplicate / n-plicate data, e.g. memory / stack /
returndata so that each entry has their own private slice.


---------

Co-authored-by: Gary Rong <garyrong0905@gmail.com>
This commit is contained in:
Martin HS 2024-12-04 08:52:59 +01:00 committed by GitHub
parent 84cabb587b
commit f0e7382f38
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
6 changed files with 200 additions and 189 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
cmd/evm/main.go
View File

@ -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
}

29
cmd/evm/runner.go
View File

@ -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)
}
}

19
core/vm/runtime/runtime_test.go
View File

@ -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)
}
}

2
eth/tracers/api_test.go
View File

@ -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")
}

305
eth/tracers/logger/logger.go
View File

@ -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)
}
}
@ -428,62 +488,5 @@ 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
StructLogs []json.RawMessage `json:"structLogs"`
}

24
eth/tracers/tracers_test.go
View File

@ -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()
}
}