cmd/evm: better design on outputs

cmd/evm/internal/t8ntool/file_tracer.go

@@ -17,73 +17,107 @@
 package t8ntool
 
 import (
-	"github.com/ethereum/go-ethereum/common"
-	"github.com/ethereum/go-ethereum/core/tracing"
-	"github.com/ethereum/go-ethereum/core/types"
-	"github.com/ethereum/go-ethereum/eth/tracers"
-	"github.com/ethereum/go-ethereum/eth/tracers/logger"
-	"github.com/ethereum/go-ethereum/log"
-	"github.com/ethereum/go-ethereum/params"
-
 	"encoding/json"
 	"fmt"
 	"io"
 	"math/big"
 	"os"
 	"path/filepath"
+
+	"github.com/ethereum/go-ethereum/common"
+	"github.com/ethereum/go-ethereum/core/tracing"
+	"github.com/ethereum/go-ethereum/core/types"
+	"github.com/ethereum/go-ethereum/eth/tracers"
+	"github.com/ethereum/go-ethereum/log"
 )
 
 // fileWritingTracer wraps either a tracer or a logger. On tx start,
 // it instantiates a tracer/logger, creates a new file to direct output to,
 // and on tx end it closes the file.
 type fileWritingTracer struct {
-	txIndex     int
+	txIndex     int            // transaction counter
-	inner       *tracing.Hooks
+	inner       *tracing.Hooks // inner hooks
-	destination io.WriteCloser
+	destination io.WriteCloser // the currently open file (if any)
-	baseDir     string
+	baseDir     string         // baseDir to write output-files to
-
+	suffix      string         // suffix is the suffix to use when creating files
-	// for json-tracing
-	logConfig *logger.Config
 
 	// for custom tracing
-	tracerName  string
-	tracerConf  json.RawMessage
-	chainConfig *params.ChainConfig
 	getResult func() (json.RawMessage, error)
 }
 
-// jsonToFile creates hooks which uses an underlying jsonlogger, and writes the
+func (l *fileWritingTracer) Write(p []byte) (n int, err error) {
-// jsonl-delimited output to a file, one per tx.
+	if l.destination != nil {
-func jsonToFile(baseDir string, logConfig *logger.Config, callFrames bool) *tracing.Hooks {
+		return l.destination.Write(p)
-	t := &fileWritingTracer{
-		baseDir:   baseDir,
-		logConfig: logConfig,
 	}
-	hooks := t.hooks()
+	log.Warn("Tracer wrote to non-existing output")
-	if !callFrames {
+	// It is tempting to return an error here, however, the json encoder
-		hooks.OnEnter = nil
+	// will no retry writing to an io.Writer once it has returned an error once.
-	}
+	// Therefore, we must squash the error.
-	return hooks
+	return n, nil
 }
 
-// tracerToFile creates hooks which uses an underlying tracer, and writes the
+// newFileWriter creates a set of hooks which wraps inner hooks (typically a logger),
-// json-result to file, one per tx.
+// and writes the output to a file, one file per transaction.
-func tracerToFile(baseDir, tracerName string, traceConfig json.RawMessage, chainConfig *params.ChainConfig) *tracing.Hooks {
+func newFileWriter(baseDir string, innerFn func(out io.Writer) *tracing.Hooks) *tracing.Hooks {
 	t := &fileWritingTracer{
 		baseDir: baseDir,
-		tracerName:  tracerName,
+		suffix:  "jsonl",
-		chainConfig: chainConfig,
+	}
+	t.inner = innerFn(t) // instantiate the inner tracer
+	return t.hooks()
+}
+
+// newResultWriter creates a set of hooks wraps and invokes an underlying tracer,
+// and writes the result (getResult-output) to file, one per transaction.
+func newResultWriter(baseDir string, tracer *tracers.Tracer) *tracing.Hooks {
+	t := &fileWritingTracer{
+		baseDir:   baseDir,
+		getResult: tracer.GetResult,
+		inner:     tracer.Hooks,
+		suffix:    "json",
 	}
 	return t.hooks()
 }
 
+// OnTxStart creates a new output-file specific for this transaction, and invokes
+// the inner OnTxStart handler.
+func (l *fileWritingTracer) OnTxStart(env *tracing.VMContext, tx *types.Transaction, from common.Address) {
+	// Open a new file,
+	fname := filepath.Join(l.baseDir, fmt.Sprintf("trace-%d-%v.%v", l.txIndex, tx.Hash().String(), l.suffix))
+	traceFile, err := os.Create(fname)
+	if err != nil {
+		log.Warn("Failed creating trace-file", "err", err)
+	}
+	log.Info("Created tracing-file", "path", fname)
+	l.destination = traceFile
+
+	if l.inner.OnTxStart != nil {
+		l.inner.OnTxStart(env, tx, from)
+	}
+}
+
+// OnTxEnd writes result (if getResult exist), closes any currently open output-file,
+// and invokes the inner OnTxEnd handler.
+func (l *fileWritingTracer) OnTxEnd(receipt *types.Receipt, err error) {
+	if l.inner.OnTxEnd != nil {
+		l.inner.OnTxEnd(receipt, err)
+	}
+	if l.getResult != nil && l.destination != nil {
+		if result, err := l.getResult(); result != nil {
+			json.NewEncoder(l.destination).Encode(result)
+		} else {
+			log.Warn("Error obtaining tracer result", "err", err)
+		}
+		l.destination.Close()
+		l.destination = nil
+	}
+	l.txIndex++
+}
+
 func (l *fileWritingTracer) hooks() *tracing.Hooks {
-	hooks := &tracing.Hooks{
+	return &tracing.Hooks{
-		OnTxStart: l.OnTxStartJSONL,
+		OnTxStart: l.OnTxStart,
 		OnTxEnd:   l.OnTxEnd,
-		// intentional no-op: we instantiate the l.inner on tx start, which has
-		// not yet happened at this point
-		//OnSystemCallStart: func() {},
 		OnEnter: func(depth int, typ byte, from common.Address, to common.Address, input []byte, gas uint64, value *big.Int) {
 			if l.inner != nil && l.inner.OnEnter != nil {
 				l.inner.OnEnter(depth, typ, from, to, input, gas, value)
@@ -104,66 +138,15 @@ func (l *fileWritingTracer) hooks() *tracing.Hooks {
 				l.inner.OnFault(pc, op, gas, cost, scope, depth, err)
 			}
 		},
+		OnSystemCallStart: func() {
+			if l.inner != nil && l.inner.OnSystemCallStart != nil {
+				l.inner.OnSystemCallStart()
 			}
-	if len(l.tracerName) > 0 { // a custom tracer
+		},
-		hooks.OnTxStart = l.OnTxStartJSON
+		OnSystemCallEnd: func() {
+			if l.inner != nil && l.inner.OnSystemCallEnd != nil {
+				l.inner.OnSystemCallEnd()
 			}
-	return hooks
+		},
-}
-
-// OnTxStartJSONL is the OnTxStart-handler for jsonl logger.
-func (l *fileWritingTracer) OnTxStartJSONL(env *tracing.VMContext, tx *types.Transaction, from common.Address) {
-	// Open a new file,
-	fname := filepath.Join(l.baseDir, fmt.Sprintf("trace-%d-%v.jsonl", l.txIndex, tx.Hash().String()))
-	traceFile, err := os.Create(fname)
-	if err != nil {
-		log.Warn("Failed creating trace-file", "err", err)
-	}
-	log.Debug("Created tracing-file", "path", fname)
-	l.destination = traceFile
-	l.inner = logger.NewJSONLoggerWithCallFrames(l.logConfig, traceFile)
-	if l.inner.OnTxStart != nil {
-		l.inner.OnTxStart(env, tx, from)
 	}
 }
-
-// OnTxStartJSONL is the OnTxStart-handler for custom tracer.
-func (l *fileWritingTracer) OnTxStartJSON(env *tracing.VMContext, tx *types.Transaction, from common.Address) {
-	// Open a new file,
-	fname := filepath.Join(l.baseDir, fmt.Sprintf("trace-%d-%v.json", l.txIndex, tx.Hash().String()))
-	traceFile, err := os.Create(fname)
-	if err != nil {
-		log.Warn("Failed creating trace-file", "err", err)
-	}
-	fmt.Printf("Created tracing-file %v\n", fname)
-	log.Info("Created tracing-file", "path", fname)
-	l.destination = traceFile
-	inner, err := tracers.DefaultDirectory.New(l.tracerName, nil, l.tracerConf, l.chainConfig)
-	if err != nil {
-		log.Warn("Failed instantiating tracer", "err", err)
-		return
-	}
-	l.getResult = inner.GetResult
-	l.inner = inner.Hooks
-	if l.inner.OnTxStart != nil {
-		l.inner.OnTxStart(env, tx, from)
-	}
-}
-
-func (l *fileWritingTracer) OnTxEnd(receipt *types.Receipt, err error) {
-	if l.inner.OnTxEnd != nil {
-		l.inner.OnTxEnd(receipt, err)
-	}
-	if l.getResult != nil {
-		if result, err := l.getResult(); result != nil {
-			json.NewEncoder(l.destination).Encode(result)
-		} else {
-			log.Warn("Error obtaining tracer result", "err", err)
-		}
-	}
-	if l.destination != nil { // Close old file
-		l.destination.Close()
-		l.destination = nil
-	}
-	l.txIndex++
-}

cmd/evm/internal/t8ntool/transition.go

@@ -20,6 +20,7 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
+	"io"
 	"math/big"
 	"os"
 	"path/filepath"
@@ -28,8 +29,10 @@ import (
 	"github.com/ethereum/go-ethereum/common/hexutil"
 	"github.com/ethereum/go-ethereum/consensus/misc/eip1559"
 	"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/eth/tracers"
 	"github.com/ethereum/go-ethereum/eth/tracers/logger"
 	"github.com/ethereum/go-ethereum/log"
 	"github.com/ethereum/go-ethereum/params"
@@ -151,14 +154,27 @@ func Transition(ctx *cli.Context) error {
 	// Configure tracer
 	if ctx.IsSet(TraceTracerFlag.Name) { // Custom tracing
 		config := json.RawMessage(ctx.String(TraceTracerConfigFlag.Name))
-		vmConfig.Tracer = tracerToFile(baseDir, ctx.String(TraceTracerFlag.Name), config, chainConfig)
+		tracer, err := tracers.DefaultDirectory.New(ctx.String(TraceTracerFlag.Name),
+			nil, config, chainConfig)
+		if err != nil {
+			return NewError(ErrorConfig, fmt.Errorf("failed instantiating tracer: %v", err))
+		}
+		vmConfig.Tracer = newResultWriter(baseDir, tracer)
 	} else if ctx.Bool(TraceFlag.Name) { // JSON opcode tracing
 		logConfig := &logger.Config{
 			DisableStack:     ctx.Bool(TraceDisableStackFlag.Name),
 			EnableMemory:     ctx.Bool(TraceEnableMemoryFlag.Name),
 			EnableReturnData: ctx.Bool(TraceEnableReturnDataFlag.Name),
 		}
-		vmConfig.Tracer = jsonToFile(baseDir, logConfig, ctx.Bool(TraceEnableCallFramesFlag.Name))
+		if ctx.Bool(TraceEnableCallFramesFlag.Name) {
+			vmConfig.Tracer = newFileWriter(baseDir, func(out io.Writer) *tracing.Hooks {
+				return logger.NewJSONLoggerWithCallFrames(logConfig, out)
+			})
+		} else {
+			vmConfig.Tracer = newFileWriter(baseDir, func(out io.Writer) *tracing.Hooks {
+				return logger.NewJSONLogger(logConfig, out)
+			})
+		}
 	}
 	// Run the test and aggregate the result
 	s, result, body, err := prestate.Apply(vmConfig, chainConfig, txIt, ctx.Int64(RewardFlag.Name))

cmd/evm/t8n_test.go

@@ -341,6 +341,103 @@ func lineIterator(path string) func() (string, error) {
 	}
 }
 
+// TestT8nTracing is a test that checks the tracing-output from t8n.
+func TestT8nTracing(t *testing.T) {
+	t.Parallel()
+	tt := new(testT8n)
+	tt.TestCmd = cmdtest.NewTestCmd(t, tt)
+	for i, tc := range []struct {
+		base           string
+		input          t8nInput
+		expExitCode    int
+		extraArgs      []string
+		expectedTraces []string
+	}{
+		{
+			base: "./testdata/31",
+			input: t8nInput{
+				"alloc.json", "txs.json", "env.json", "Cancun", "",
+			},
+			extraArgs: []string{"--trace"},
+			expectedTraces: []string{"trace-0-0x88f5fbd1524731a81e49f637aa847543268a5aaf2a6b32a69d2c6d978c45dcfb.jsonl",
+				"trace-1-0x03a7b0a91e61a170d64ea94b8263641ef5a8bbdb10ac69f466083a6789c77fb8.jsonl",
+				"trace-2-0xd96e0ce6418ee3360e11d3c7b6886f5a9a08f7ef183da72c23bb3b2374530128.jsonl"},
+		},
+		{
+			base: "./testdata/31",
+			input: t8nInput{
+				"alloc.json", "txs.json", "env.json", "Cancun", "",
+			},
+			extraArgs: []string{"--trace.tracer", `
+{   count: 0,
+	result: function(){
+		this.count = this.count + 1;
+		return "hello world " + this.count
+	},
+	fault: function(){}
+}`},
+			expectedTraces: []string{"trace-0-0x88f5fbd1524731a81e49f637aa847543268a5aaf2a6b32a69d2c6d978c45dcfb.json",
+				"trace-1-0x03a7b0a91e61a170d64ea94b8263641ef5a8bbdb10ac69f466083a6789c77fb8.json",
+				"trace-2-0xd96e0ce6418ee3360e11d3c7b6886f5a9a08f7ef183da72c23bb3b2374530128.json"},
+		},
+		{
+			base: "./testdata/32",
+			input: t8nInput{
+				"alloc.json", "txs.json", "env.json", "Paris", "",
+			},
+			extraArgs:      []string{"--trace", "--trace.callframes"},
+			expectedTraces: []string{"trace-0-0x47806361c0fa084be3caa18afe8c48156747c01dbdfc1ee11b5aecdbe4fcf23e.jsonl"},
+		},
+	} {
+		args := []string{"t8n"}
+		args = append(args, tc.input.get(tc.base)...)
+		// Place the output somewhere we can find it
+		outdir := t.TempDir()
+		args = append(args, "--output.basedir", outdir)
+		args = append(args, tc.extraArgs...)
+
+		var qArgs []string // quoted args for debugging purposes
+		for _, arg := range args {
+			if len(arg) == 0 {
+				qArgs = append(qArgs, `""`)
+			} else {
+				qArgs = append(qArgs, arg)
+			}
+		}
+		tt.Logf("args: %v\n", strings.Join(qArgs, " "))
+		tt.Run("evm-test", args...)
+		t.Log(string(tt.Output()))
+
+		// Compare the expected traces
+		for _, traceFile := range tc.expectedTraces {
+			haveFn := lineIterator(filepath.Join(outdir, traceFile))
+			wantFn := lineIterator(filepath.Join(tc.base, traceFile))
+
+			for line := 0; ; line++ {
+				want, wErr := wantFn()
+				have, hErr := haveFn()
+				if want != have {
+					t.Fatalf("test %d, trace %v, line %d\nwant: %v\nhave: %v\n",
+						i, traceFile, line, want, have)
+				}
+				if wErr != nil && hErr != nil {
+					break
+				}
+				if wErr != nil {
+					t.Fatal(wErr)
+				}
+				if hErr != nil {
+					t.Fatal(hErr)
+				}
+				t.Logf("%v\n", want)
+			}
+		}
+		if have, want := tt.ExitStatus(), tc.expExitCode; have != want {
+			t.Fatalf("test %d: wrong exit code, have %d, want %d", i, have, want)
+		}
+	}
+}
+
 type t9nInput struct {
 	inTxs  string
 	stFork string

cmd/evm/testdata/31/README.md

@@ -1 +1,11 @@
 This test does some EVM execution, and can be used to test the tracers and trace-outputs.
+This test should yield three output-traces, in separate files
+
+For example:
+```
+[user@work evm]$ go  run . t8n --input.alloc ./testdata/31/alloc.json --input.txs ./testdata/31/txs.json --input.env ./testdata/31/env.json --state.fork Cancun --output.basedir /tmp --trace
+INFO [12-06|09:53:32.123] Created tracing-file                     path=/tmp/trace-0-0x88f5fbd1524731a81e49f637aa847543268a5aaf2a6b32a69d2c6d978c45dcfb.jsonl
+INFO [12-06|09:53:32.124] Created tracing-file                     path=/tmp/trace-1-0x03a7b0a91e61a170d64ea94b8263641ef5a8bbdb10ac69f466083a6789c77fb8.jsonl
+INFO [12-06|09:53:32.125] Created tracing-file                     path=/tmp/trace-2-0xd96e0ce6418ee3360e11d3c7b6886f5a9a08f7ef183da72c23bb3b2374530128.jsonl
+```
+

cmd/evm/testdata/31/trace-0-0x88f5fbd1524731a81e49f637aa847543268a5aaf2a6b32a69d2c6d978c45dcfb.json

@@ -1 +1 @@
-"hello world"
+"hello world 1"

cmd/evm/testdata/31/trace-1-0x03a7b0a91e61a170d64ea94b8263641ef5a8bbdb10ac69f466083a6789c77fb8.json

@@ -0,0 +1 @@
+"hello world 2"

cmd/evm/testdata/31/trace-1-0x03a7b0a91e61a170d64ea94b8263641ef5a8bbdb10ac69f466083a6789c77fb8.jsonl

@@ -0,0 +1,6 @@
+{"pc":0,"op":96,"gas":"0x13498","gasCost":"0x3","memSize":0,"stack":[],"depth":1,"refund":0,"opName":"PUSH1"}
+{"pc":2,"op":96,"gas":"0x13495","gasCost":"0x3","memSize":0,"stack":["0x40"],"depth":1,"refund":0,"opName":"PUSH1"}
+{"pc":4,"op":96,"gas":"0x13492","gasCost":"0x3","memSize":0,"stack":["0x40","0x40"],"depth":1,"refund":0,"opName":"PUSH1"}
+{"pc":6,"op":96,"gas":"0x1348f","gasCost":"0x3","memSize":0,"stack":["0x40","0x40","0x40"],"depth":1,"refund":0,"opName":"PUSH1"}
+{"pc":8,"op":0,"gas":"0x1348c","gasCost":"0x0","memSize":0,"stack":["0x40","0x40","0x40","0x40"],"depth":1,"refund":0,"opName":"STOP"}
+{"output":"","gasUsed":"0xc"}

cmd/evm/testdata/31/trace-2-0xd96e0ce6418ee3360e11d3c7b6886f5a9a08f7ef183da72c23bb3b2374530128.json

@@ -0,0 +1 @@
+"hello world 3"

cmd/evm/testdata/31/trace-2-0xd96e0ce6418ee3360e11d3c7b6886f5a9a08f7ef183da72c23bb3b2374530128.jsonl

@@ -0,0 +1,6 @@
+{"pc":0,"op":96,"gas":"0x13498","gasCost":"0x3","memSize":0,"stack":[],"depth":1,"refund":0,"opName":"PUSH1"}
+{"pc":2,"op":96,"gas":"0x13495","gasCost":"0x3","memSize":0,"stack":["0x40"],"depth":1,"refund":0,"opName":"PUSH1"}
+{"pc":4,"op":96,"gas":"0x13492","gasCost":"0x3","memSize":0,"stack":["0x40","0x40"],"depth":1,"refund":0,"opName":"PUSH1"}
+{"pc":6,"op":96,"gas":"0x1348f","gasCost":"0x3","memSize":0,"stack":["0x40","0x40","0x40"],"depth":1,"refund":0,"opName":"PUSH1"}
+{"pc":8,"op":0,"gas":"0x1348c","gasCost":"0x0","memSize":0,"stack":["0x40","0x40","0x40","0x40"],"depth":1,"refund":0,"opName":"STOP"}
+{"output":"","gasUsed":"0xc"}

cmd/evm/testdata/31/txs.json

@@ -10,5 +10,29 @@
     "r" : "0x0",
     "s" : "0x0",
     "secretKey" : "0x45a915e4d060149eb4365960e6a7a45f334393093061116b197e3240065ff2d8"
+  },
+  {
+    "gas": "0x186a0",
+    "gasPrice": "0x600",
+    "input": "0x",
+    "nonce": "0x1",
+    "to": "0x1111111111111111111111111111111111111111",
+    "value": "0x1",
+    "v" : "0x0",
+    "r" : "0x0",
+    "s" : "0x0",
+    "secretKey" : "0x45a915e4d060149eb4365960e6a7a45f334393093061116b197e3240065ff2d8"
+  },
+  {
+    "gas": "0x186a0",
+    "gasPrice": "0x600",
+    "input": "0x",
+    "nonce": "0x2",
+    "to": "0x1111111111111111111111111111111111111111",
+    "value": "0x1",
+    "v" : "0x0",
+    "r" : "0x0",
+    "s" : "0x0",
+    "secretKey" : "0x45a915e4d060149eb4365960e6a7a45f334393093061116b197e3240065ff2d8"
   }
 ]

eth/tracers/logger/logger_json.go

@@ -70,7 +70,7 @@ func NewJSONLogger(cfg *Config, writer io.Writer) *tracing.Hooks {
 	}
 	l.hooks = &tracing.Hooks{
 		OnTxStart:         l.OnTxStart,
-		//OnSystemCallStart: l.onSystemCallStart,
+		OnSystemCallStart: l.onSystemCallStart,
 		OnExit:            l.OnExit,
 		OnOpcode:          l.OnOpcode,
 		OnFault:           l.OnFault,
@@ -87,7 +87,7 @@ func NewJSONLoggerWithCallFrames(cfg *Config, writer io.Writer) *tracing.Hooks {
 	}
 	l.hooks = &tracing.Hooks{
 		OnTxStart:         l.OnTxStart,
-		//OnSystemCallStart: l.onSystemCallStart,
+		OnSystemCallStart: l.onSystemCallStart,
 		OnEnter:           l.OnEnter,
 		OnExit:            l.OnExit,
 		OnOpcode:          l.OnOpcode,