core/evm, core/vm: improved evm trace output

* Improved the standard evm tracer output and renamed it to WriteTrace
which now takes an io.Writer to write the logs to.
* Added WriteLogs which writes logs to the given writer in a readable
format.
* evm utility now also prints logs generated during the execution.

2 files changed, 49 insertions, 42 deletions

diff --git a/cmd/evm/runner.go b/cmd/evm/runner.go
index 0bed46894..8a71a92f7 100644
--- a/cmd/evm/runner.go
+++ b/cmd/evm/runner.go
@@ -53,7 +53,6 @@ func runCmd(ctx *cli.Context) error {
 		statedb, _ = state.New(common.Hash{}, db)
 		sender     = common.StringToAddress("sender")
 		logger     = vm.NewStructLogger(nil)
-		tstart     = time.Now()
 	)
 	statedb.CreateAccount(sender)
 
@@ -84,36 +83,28 @@ func runCmd(ctx *cli.Context) error {
 		code = common.Hex2Bytes(string(bytes.TrimRight(hexcode, "\n")))
 	}
 
+	runtimeConfig := runtime.Config{
+		Origin:   sender,
+		State:    statedb,
+		GasLimit: ctx.GlobalUint64(GasFlag.Name),
+		GasPrice: utils.GlobalBig(ctx, PriceFlag.Name),
+		Value:    utils.GlobalBig(ctx, ValueFlag.Name),
+		EVMConfig: vm.Config{
+			Tracer:             logger,
+			Debug:              ctx.GlobalBool(DebugFlag.Name),
+			DisableGasMetering: ctx.GlobalBool(DisableGasMeteringFlag.Name),
+		},
+	}
+
+	tstart := time.Now()
 	if ctx.GlobalBool(CreateFlag.Name) {
 		input := append(code, common.Hex2Bytes(ctx.GlobalString(InputFlag.Name))...)
-		ret, _, err = runtime.Create(input, &runtime.Config{
-			Origin:   sender,
-			State:    statedb,
-			GasLimit: ctx.GlobalUint64(GasFlag.Name),
-			GasPrice: utils.GlobalBig(ctx, PriceFlag.Name),
-			Value:    utils.GlobalBig(ctx, ValueFlag.Name),
-			EVMConfig: vm.Config{
-				Tracer:             logger,
-				Debug:              ctx.GlobalBool(DebugFlag.Name),
-				DisableGasMetering: ctx.GlobalBool(DisableGasMeteringFlag.Name),
-			},
-		})
+		ret, _, err = runtime.Create(input, &runtimeConfig)
 	} else {
 		receiver := common.StringToAddress("receiver")
 		statedb.SetCode(receiver, code)
 
-		ret, err = runtime.Call(receiver, common.Hex2Bytes(ctx.GlobalString(InputFlag.Name)), &runtime.Config{
-			Origin:   sender,
-			State:    statedb,
-			GasLimit: ctx.GlobalUint64(GasFlag.Name),
-			GasPrice: utils.GlobalBig(ctx, PriceFlag.Name),
-			Value:    utils.GlobalBig(ctx, ValueFlag.Name),
-			EVMConfig: vm.Config{
-				Tracer:             logger,
-				Debug:              ctx.GlobalBool(DebugFlag.Name),
-				DisableGasMetering: ctx.GlobalBool(DisableGasMeteringFlag.Name),
-			},
-		})
+		ret, err = runtime.Call(receiver, common.Hex2Bytes(ctx.GlobalString(InputFlag.Name)), &runtimeConfig)
 	}
 	vmdone := time.Since(tstart)
 
@@ -121,7 +112,13 @@ func runCmd(ctx *cli.Context) error {
 		statedb.Commit(true)
 		fmt.Println(string(statedb.Dump()))
 	}
-	vm.StdErrFormat(logger.StructLogs())
+
+	if ctx.GlobalBool(DebugFlag.Name) {
+		fmt.Fprintln(os.Stderr, "#### TRACE ####")
+		vm.WriteTrace(os.Stderr, logger.StructLogs())
+		fmt.Fprintln(os.Stderr, "#### LOGS ####")
+		vm.WriteLogs(os.Stderr, statedb.Logs())
+	}
 
 	if ctx.GlobalBool(SysStatFlag.Name) {
 		var mem goruntime.MemStats
@@ -136,7 +133,7 @@ num gc:     %d
 `, mem.Alloc, mem.TotalAlloc, mem.Mallocs, mem.HeapAlloc, mem.HeapObjects, mem.NumGC)
 	}
 
-	fmt.Printf("OUT: 0x%x", ret)
+	fmt.Printf("0x%x", ret)
 	if err != nil {
 		fmt.Printf(" error: %v", err)
 	}
diff --git a/core/vm/logger.go b/core/vm/logger.go
index ccdf21a4b..3d7e1c95f 100644
--- a/core/vm/logger.go
+++ b/core/vm/logger.go
@@ -19,11 +19,12 @@ package vm
 import (
 	"encoding/hex"
 	"fmt"
+	"io"
 	"math/big"
-	"os"
 
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/common/math"
+	"github.com/ethereum/go-ethereum/core/types"
 )
 
 type Storage map[common.Hash]common.Hash
@@ -168,29 +169,38 @@ func (l *StructLogger) StructLogs() []StructLog {
 	return l.logs
 }
 
-// StdErrFormat formats a slice of StructLogs to human readable format
-func StdErrFormat(logs []StructLog) {
-	fmt.Fprintf(os.Stderr, "VM STAT %d OPs\n", len(logs))
+// WriteTrace writes a formatted trace to the given writer
+func WriteTrace(writer io.Writer, logs []StructLog) {
 	for _, log := range logs {
-		fmt.Fprintf(os.Stderr, "PC %08d: %s GAS: %v COST: %v", log.Pc, log.Op, log.Gas, log.GasCost)
+		fmt.Fprintf(writer, "%-10spc=%08d gas=%v cost=%v", log.Op, log.Pc, log.Gas, log.GasCost)
 		if log.Err != nil {
-			fmt.Fprintf(os.Stderr, " ERROR: %v", log.Err)
+			fmt.Fprintf(writer, " ERROR: %v", log.Err)
 		}
-		fmt.Fprintf(os.Stderr, "\n")
-
-		fmt.Fprintln(os.Stderr, "STACK =", len(log.Stack))
+		fmt.Fprintf(writer, "\n")
 
 		for i := len(log.Stack) - 1; i >= 0; i-- {
-			fmt.Fprintf(os.Stderr, "%04d: %x\n", len(log.Stack)-i-1, math.PaddedBigBytes(log.Stack[i], 32))
+			fmt.Fprintf(writer, "%08d  %x\n", len(log.Stack)-i-1, math.PaddedBigBytes(log.Stack[i], 32))
 		}
 
-		fmt.Fprintln(os.Stderr, "MEM =", len(log.Memory))
-		fmt.Fprintln(os.Stderr, hex.Dump(log.Memory))
+		fmt.Fprint(writer, hex.Dump(log.Memory))
 
-		fmt.Fprintln(os.Stderr, "STORAGE =", len(log.Storage))
 		for h, item := range log.Storage {
-			fmt.Fprintf(os.Stderr, "%x: %x\n", h, item)
+			fmt.Fprintf(writer, "%x: %x\n", h, item)
+		}
+		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.Fprintln(os.Stderr)
+
+		fmt.Fprint(writer, hex.Dump(log.Data))
+		fmt.Fprintln(writer)
 	}
 }