Merge pull request #426 from nspcc-dev/logger_247

Change fmt.Println to log, close #247.

cli/vm/vm.go

@@ -48,7 +48,7 @@ func inspect(ctx *cli.Context) error {
 	if err != nil {
 		return cli.NewExitError(err, 1)
 	}
-	v := vm.New(0)
+	v := vm.New()
 	v.LoadScript(b)
 	v.PrintOps()
 	return nil

pkg/core/blockchain.go

@@ -416,7 +416,7 @@ func (bc *Blockchain) storeBlock(block *Block) error {
 			contracts[contract.ScriptHash()] = contract
 
 		case *transaction.InvocationTX:
-			vm := vm.New(vm.ModeMute)
+			vm := vm.New()
 			vm.SetCheckedHash(tx.VerificationHash().Bytes())
 			vm.SetScriptGetter(func(hash util.Uint160) []byte {
 				cs := bc.GetContractState(hash)
@@ -430,7 +430,7 @@ func (bc *Blockchain) storeBlock(block *Block) error {
 			vm.RegisterInteropFuncs(systemInterop.getSystemInteropMap())
 			vm.RegisterInteropFuncs(systemInterop.getNeoInteropMap())
 			vm.LoadScript(t.Script)
-			vm.Run()
+			err := vm.Run()
 			if !vm.HasFailed() {
 				_, err := systemInterop.mem.Persist()
 				if err != nil {
@@ -440,6 +440,7 @@ func (bc *Blockchain) storeBlock(block *Block) error {
 				log.WithFields(log.Fields{
 					"tx":    tx.Hash().ReverseString(),
 					"block": block.Index,
+					"err":   err,
 				}).Warn("contract invocation failed")
 			}
 		}
@@ -1103,7 +1104,7 @@ func (bc *Blockchain) verifyHashAgainstScript(hash util.Uint160, witness *transa
 		}
 	}
 
-	vm := vm.New(vm.ModeMute)
+	vm := vm.New()
 	vm.SetCheckedHash(checkedHash.Bytes())
 	vm.SetScriptGetter(func(hash util.Uint160) []byte {
 		cs := bc.GetContractState(hash)
@@ -1116,9 +1117,9 @@ func (bc *Blockchain) verifyHashAgainstScript(hash util.Uint160, witness *transa
 	vm.RegisterInteropFuncs(interopCtx.getNeoInteropMap())
 	vm.LoadScript(verification)
 	vm.LoadScript(witness.InvocationScript)
-	vm.Run()
+	err := vm.Run()
 	if vm.HasFailed() {
-		return errors.Errorf("vm failed to execute the script")
+		return errors.Errorf("vm failed to execute the script with error: %s", err)
 	}
 	resEl := vm.Estack().Pop()
 	if resEl != nil {

pkg/core/storage/boltdb_store.go

@@ -7,6 +7,7 @@ import (
 	"path"
 
 	"github.com/etcd-io/bbolt"
+	log "github.com/sirupsen/logrus"
 	"github.com/syndtr/goleveldb/leveldb/util"
 )
 
@@ -110,7 +111,7 @@ func (s *BoltDBStore) Seek(key []byte, f func(k, v []byte)) {
 		return nil
 	})
 	if err != nil {
-		fmt.Println("error while executing seek in boltDB")
+		log.Error("error while executing seek in boltDB")
 	}
 }
 

pkg/rpc/request.go

@@ -2,7 +2,6 @@ package rpc
 
 import (
 	"encoding/json"
-	"fmt"
 	"io"
 	"net/http"
 
@@ -114,7 +113,12 @@ func (r Request) writeServerResponse(w http.ResponseWriter, response Response) {
 	encoder := json.NewEncoder(w)
 	err := encoder.Encode(response)
 
+	logFields := log.Fields{
+		"err":    err,
+		"method": r.Method,
+	}
+
 	if err != nil {
-		fmt.Println(err)
+		log.WithFields(logFields).Error("Error encountered while encoding response")
 	}
 }

pkg/vm/cli/cli.go

@@ -169,7 +169,7 @@ type VMCLI struct {
 // New returns a new VMCLI object.
 func New() *VMCLI {
 	vmcli := VMCLI{
-		vm:    vm.New(0),
+		vm:    vm.New(),
 		shell: ishell.New(),
 	}
 	vmcli.shell.Set(vmKey, vmcli.vm)
@@ -286,16 +286,40 @@ func handleRun(c *ishell.Context) {
 		}
 		v.LoadArgs(method, params)
 	}
-	v.Run()
+	runVMWithHandling(c, v)
 	changePrompt(c, v)
 }
 
+// runVMWithHandling runs VM with handling errors and additional state messages.
+func runVMWithHandling(c *ishell.Context, v *vm.VM) {
+	err := v.Run()
+	if err != nil {
+		c.Err(err)
+		return
+	}
+
+	var message string
+	switch {
+	case v.HasFailed():
+		message = "FAILED"
+	case v.HasHalted():
+		message = v.Stack("estack")
+	case v.AtBreakpoint():
+		ctx := v.Context()
+		i, op := ctx.CurrInstr()
+		message = fmt.Sprintf("at breakpoint %d (%s)\n", i, op.String())
+	}
+	if message != "" {
+		c.Printf(message)
+	}
+}
+
 func handleCont(c *ishell.Context) {
 	if !checkVMIsReady(c) {
 		return
 	}
 	v := getVMFromContext(c)
-	v.Run()
+	runVMWithHandling(c, v)
 	changePrompt(c, v)
 }
 
@@ -317,7 +341,7 @@ func handleStep(c *ishell.Context) {
 		}
 	}
 	v.AddBreakPointRel(n)
-	v.Run()
+	runVMWithHandling(c, v)
 	changePrompt(c, v)
 }
 
@@ -338,14 +362,19 @@ func handleStepType(c *ishell.Context, stepType string) {
 		return
 	}
 	v := getVMFromContext(c)
+	var err error
 	switch stepType {
 	case "into":
-		v.StepInto()
+		err = v.StepInto()
 	case "out":
-		v.StepOut()
+		err = v.StepOut()
 	case "over":
-		v.StepOver()
+		err = v.StepOver()
 	}
+	if err != nil {
+		c.Err(err)
+	}
+	handleIP(c)
 	changePrompt(c, v)
 }
 
@@ -367,7 +396,7 @@ func changePrompt(c ishell.Actions, v *vm.VM) {
 
 // Run waits for user input from Stdin and executes the passed command.
 func (c *VMCLI) Run() error {
-	printLogo()
+	printLogo(c.shell)
 	c.shell.Run()
 	return nil
 }
@@ -418,7 +447,7 @@ func parseArgs(args []string) ([]vm.StackItem, error) {
 	return items, nil
 }
 
-func printLogo() {
+func printLogo(c *ishell.Shell) {
 	logo := `
     _   ____________        __________      _    ____  ___
    / | / / ____/ __ \      / ____/ __ \    | |  / /  |/  /
@@ -426,7 +455,7 @@ func printLogo() {
  / /|  / /___/ /_/ /_____/ /_/ / /_/ /_____/ |/ / /  / /  
 /_/ |_/_____/\____/      \____/\____/      |___/_/  /_/   
 `
-	fmt.Print(logo)
+	c.Print(logo)
-	fmt.Println()
+	c.Println()
-	fmt.Println()
+	c.Println()
 }

pkg/vm/compiler/compiler.go

@@ -107,7 +107,7 @@ func CompileAndInspect(src string) error {
 		return err
 	}
 
-	v := vm.New(0)
+	v := vm.New()
 	v.LoadScript(b)
 	v.PrintOps()
 	return nil

pkg/vm/tests/vm_test.go

@@ -8,6 +8,7 @@ import (
 	"github.com/CityOfZion/neo-go/pkg/vm"
 	"github.com/CityOfZion/neo-go/pkg/vm/compiler"
 	"github.com/stretchr/testify/assert"
+	"github.com/stretchr/testify/require"
 )
 
 type testCase struct {
@@ -24,14 +25,16 @@ func runTestCases(t *testing.T, tcases []testCase) {
 
 func eval(t *testing.T, src string, result interface{}) {
 	vm := vmAndCompile(t, src)
-	vm.Run()
+	err := vm.Run()
+	require.NoError(t, err)
 	assertResult(t, vm, result)
 }
 
 func evalWithArgs(t *testing.T, src string, op []byte, args []vm.StackItem, result interface{}) {
 	vm := vmAndCompile(t, src)
 	vm.LoadArgs(op, args)
-	vm.Run()
+	err := vm.Run()
+	require.NoError(t, err)
 	assertResult(t, vm, result)
 }
 
@@ -42,7 +45,7 @@ func assertResult(t *testing.T, vm *vm.VM, result interface{}) {
 }
 
 func vmAndCompile(t *testing.T, src string) *vm.VM {
-	vm := vm.New(vm.ModeMute)
+	vm := vm.New()
 
 	storePlugin := newStoragePlugin()
 	vm.RegisterInteropFunc("Neo.Storage.Get", storePlugin.Get, 1)

pkg/vm/vm.go

@@ -5,7 +5,6 @@ import (
 	"encoding/binary"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"math/big"
 	"os"
 	"reflect"
@@ -15,15 +14,25 @@ import (
 	"github.com/CityOfZion/neo-go/pkg/crypto/hash"
 	"github.com/CityOfZion/neo-go/pkg/crypto/keys"
 	"github.com/CityOfZion/neo-go/pkg/util"
+	"github.com/pkg/errors"
 )
 
-// Mode configures behaviour of the VM.
+type errorAtInstruct struct {
-type Mode uint
+	ip  int
+	op  Instruction
+	err interface{}
+}
 
-// Available VM Modes.
+func (e *errorAtInstruct) Error() string {
-var (
+	return fmt.Sprintf("error encountered at instruction %d (%s): %s", e.ip, e.op, e.err)
-	ModeMute Mode = 1 << 0
+}
-)
+
+func newError(ip int, op Instruction, err interface{}) *errorAtInstruct {
+	return &errorAtInstruct{ip: ip, op: op, err: err}
+}
+
+// StateMessage is a vm state message which could be used as additional info for example by cli.
+type StateMessage string
 
 const (
 	// MaxArraySize is the maximum array size allowed in the VM.
@@ -50,8 +59,6 @@ type VM struct {
 	estack *Stack // execution stack.
 	astack *Stack // alt stack.
 
-	// Mute all output after execution.
-	mute bool
 	// Hash to verify in CHECKSIG/CHECKMULTISIG.
 	checkhash []byte
 }
@@ -63,7 +70,7 @@ type InteropFuncPrice struct {
 }
 
 // New returns a new VM object ready to load .avm bytecode scripts.
-func New(mode Mode) *VM {
+func New() *VM {
 	vm := &VM{
 		interop:   make(map[string]InteropFuncPrice),
 		getScript: nil,
@@ -72,9 +79,6 @@ func New(mode Mode) *VM {
 		estack:    NewStack("evaluation"),
 		astack:    NewStack("alt"),
 	}
-	if mode == ModeMute {
-		vm.mute = true
-	}
 
 	// Register native interop hooks.
 	vm.RegisterInteropFunc("Neo.Runtime.Log", runtimeLog, 1)
@@ -83,12 +87,12 @@ func New(mode Mode) *VM {
 	return vm
 }
 
-// RegisterInteropFunc will register the given InteropFunc to the VM.
+// RegisterInteropFunc registers the given InteropFunc to the VM.
 func (v *VM) RegisterInteropFunc(name string, f InteropFunc, price int) {
 	v.interop[name] = InteropFuncPrice{f, price}
 }
 
-// RegisterInteropFuncs will register all interop functions passed in a map in
+// RegisterInteropFuncs registers all interop functions passed in a map in
 // the VM. Effectively it's a batched version of RegisterInteropFunc.
 func (v *VM) RegisterInteropFuncs(interops map[string]InteropFuncPrice) {
 	// We allow reregistration here.
@@ -97,22 +101,22 @@ func (v *VM) RegisterInteropFuncs(interops map[string]InteropFuncPrice) {
 	}
 }
 
-// Estack will return the evaluation stack so interop hooks can utilize this.
+// Estack returns the evaluation stack so interop hooks can utilize this.
 func (v *VM) Estack() *Stack {
 	return v.estack
 }
 
-// Astack will return the alt stack so interop hooks can utilize this.
+// Astack returns the alt stack so interop hooks can utilize this.
 func (v *VM) Astack() *Stack {
 	return v.astack
 }
 
-// Istack will return the invocation stack so interop hooks can utilize this.
+// Istack returns the invocation stack so interop hooks can utilize this.
 func (v *VM) Istack() *Stack {
 	return v.istack
 }
 
-// LoadArgs will load in the arguments used in the Mian entry point.
+// LoadArgs loads in the arguments used in the Mian entry point.
 func (v *VM) LoadArgs(method []byte, args []StackItem) {
 	if len(args) > 0 {
 		v.estack.PushVal(args)
@@ -122,7 +126,7 @@ func (v *VM) LoadArgs(method []byte, args []StackItem) {
 	}
 }
 
-// PrintOps will print the opcodes of the current loaded program to stdout.
+// PrintOps prints the opcodes of the current loaded program to stdout.
 func (v *VM) PrintOps() {
 	w := tabwriter.NewWriter(os.Stdout, 0, 0, 4, ' ', 0)
 	fmt.Fprintln(w, "INDEX\tOPCODE\tPARAMETER\t")
@@ -180,7 +184,7 @@ func (v *VM) AddBreakPointRel(n int) {
 	v.AddBreakPoint(ctx.ip + n)
 }
 
-// LoadFile will load a program from the given path, ready to execute it.
+// LoadFile loads a program from the given path, ready to execute it.
 func (v *VM) LoadFile(path string) error {
 	b, err := ioutil.ReadFile(path)
 	if err != nil {
@@ -199,7 +203,7 @@ func (v *VM) Load(prog []byte) {
 	v.istack.PushVal(NewContext(prog))
 }
 
-// LoadScript will load a script from the internal script table. It
+// LoadScript loads a script from the internal script table. It
 // will immediately push a new context created from this script to
 // the invocation stack and starts executing it.
 func (v *VM) LoadScript(b []byte) {
@@ -241,17 +245,17 @@ func (v *VM) Stack(n string) string {
 	return buildStackOutput(s)
 }
 
-// Ready return true if the VM ready to execute the loaded program.
+// Ready returns true if the VM ready to execute the loaded program.
 // Will return false if no program is loaded.
 func (v *VM) Ready() bool {
 	return v.istack.Len() > 0
 }
 
 // Run starts the execution of the loaded program.
-func (v *VM) Run() {
+func (v *VM) Run() error {
 	if !v.Ready() {
-		fmt.Println("no program loaded")
+		v.state = faultState
-		return
+		return errors.New("no program loaded")
 	}
 
 	v.state = noneState
@@ -262,40 +266,33 @@ func (v *VM) Run() {
 			v.state |= breakState
 		}
 		switch {
-		case v.state.HasFlag(faultState):
+		case v.state.HasFlag(faultState), v.state.HasFlag(haltState), v.state.HasFlag(breakState):
-			fmt.Println("FAULT")
+			return errors.New("VM stopped")
-			return
-		case v.state.HasFlag(haltState):
-			if !v.mute {
-				fmt.Println(v.Stack("estack"))
-			}
-			return
-		case v.state.HasFlag(breakState):
-			ctx := v.Context()
-			i, op := ctx.CurrInstr()
-			fmt.Printf("at breakpoint %d (%s)\n", i, op.String())
-			return
 		case v.state == noneState:
-			v.Step()
+			if err := v.Step(); err != nil {
+				return err
+			}
+		default:
+			v.state = faultState
+			return errors.New("unknown state")
 		}
 	}
 }
 
 // Step 1 instruction in the program.
-func (v *VM) Step() {
+func (v *VM) Step() error {
 	ctx := v.Context()
 	op, param, err := ctx.Next()
 	if err != nil {
-		log.Printf("error encountered at instruction %d (%s)", ctx.ip, op)
-		log.Println(err)
 		v.state = faultState
+		return newError(ctx.ip, op, err)
 	}
-	v.execute(ctx, op, param)
+	return v.execute(ctx, op, param)
 }
 
-// StepInto behaves the same as “step over” in case if the line does not contain a function it otherwise
+// StepInto behaves the same as “step over” in case if the line does not contain a function. Otherwise
 // the debugger will enter the called function and continue line-by-line debugging there.
-func (v *VM) StepInto() {
+func (v *VM) StepInto() error {
 	ctx := v.Context()
 
 	if ctx == nil {
@@ -303,29 +300,31 @@ func (v *VM) StepInto() {
 	}
 
 	if v.HasStopped() {
-		return
+		return nil
 	}
 
 	if ctx != nil && ctx.prog != nil {
 		op, param, err := ctx.Next()
 		if err != nil {
-			log.Printf("error encountered at instruction %d (%s)", ctx.ip, op)
-			log.Println(err)
 			v.state = faultState
+			return newError(ctx.ip, op, err)
+		}
+		vErr := v.execute(ctx, op, param)
+		if vErr != nil {
+			return vErr
 		}
-		v.execute(ctx, op, param)
-		i, op := ctx.CurrInstr()
-		fmt.Printf("at breakpoint %d (%s)\n", i, op.String())
 	}
 
 	cctx := v.Context()
 	if cctx != nil && cctx.atBreakPoint() {
 		v.state = breakState
 	}
+	return nil
 }
 
 // StepOut takes the debugger to the line where the current function was called.
-func (v *VM) StepOut() {
+func (v *VM) StepOut() error {
+	var err error
 	if v.state == breakState {
 		v.state = noneState
 	} else {
@@ -334,15 +333,17 @@ func (v *VM) StepOut() {
 
 	expSize := v.istack.len
 	for v.state.HasFlag(noneState) && v.istack.len >= expSize {
-		v.StepInto()
+		err = v.StepInto()
 	}
+	return err
 }
 
 // StepOver takes the debugger to the line that will step over a given line.
 // If the line contains a function the function will be executed and the result returned without debugging each line.
-func (v *VM) StepOver() {
+func (v *VM) StepOver() error {
+	var err error
 	if v.HasStopped() {
-		return
+		return err
 	}
 
 	if v.state == breakState {
@@ -353,11 +354,12 @@ func (v *VM) StepOver() {
 
 	expSize := v.istack.len
 	for {
-		v.StepInto()
+		err = v.StepInto()
 		if !(v.state.HasFlag(noneState) && v.istack.len > expSize) {
 			break
 		}
 	}
+	return err
 }
 
 // HasFailed returns whether VM is in the failed state now. Usually used to
@@ -371,6 +373,16 @@ func (v *VM) HasStopped() bool {
 	return v.state.HasFlag(haltState) || v.state.HasFlag(faultState)
 }
 
+// HasHalted returns whether VM is in Halt state.
+func (v *VM) HasHalted() bool {
+	return v.state.HasFlag(haltState)
+}
+
+// AtBreakpoint returns whether VM is at breakpoint.
+func (v *VM) AtBreakpoint() bool {
+	return v.state.HasFlag(breakState)
+}
+
 // SetCheckedHash sets checked hash for CHECKSIG and CHECKMULTISIG instructions.
 func (v *VM) SetCheckedHash(h []byte) {
 	v.checkhash = make([]byte, len(h))
@@ -383,14 +395,13 @@ func (v *VM) SetScriptGetter(gs func(util.Uint160) []byte) {
 }
 
 // execute performs an instruction cycle in the VM. Acting on the instruction (opcode).
-func (v *VM) execute(ctx *Context, op Instruction, parameter []byte) {
+func (v *VM) execute(ctx *Context, op Instruction, parameter []byte) (err error) {
 	// Instead of polluting the whole VM logic with error handling, we will recover
-	// each panic at a central point, putting the VM in a fault state.
+	// each panic at a central point, putting the VM in a fault state and setting error.
 	defer func() {
-		if err := recover(); err != nil {
+		if errRecover := recover(); errRecover != nil {
-			log.Printf("error encountered at instruction %d (%s)", ctx.ip, op)
-			log.Println(err)
 			v.state = faultState
+			err = newError(ctx.ip, op, errRecover)
 		}
 	}()
 
@@ -440,6 +451,7 @@ func (v *VM) execute(ctx *Context, op Instruction, parameter []byte) {
 			panic("can't TUCK with a one-element stack")
 		}
 		v.estack.InsertAt(a, 2)
+
 	case CAT:
 		b := v.estack.Pop().Bytes()
 		a := v.estack.Pop().Bytes()
@@ -448,6 +460,7 @@ func (v *VM) execute(ctx *Context, op Instruction, parameter []byte) {
 		}
 		ab := append(a, b...)
 		v.estack.PushVal(ab)
+
 	case SUBSTR:
 		l := int(v.estack.Pop().BigInt().Int64())
 		if l < 0 {
@@ -466,6 +479,7 @@ func (v *VM) execute(ctx *Context, op Instruction, parameter []byte) {
 			last = len(s)
 		}
 		v.estack.PushVal(s[o:last])
+
 	case LEFT:
 		l := int(v.estack.Pop().BigInt().Int64())
 		if l < 0 {
@@ -476,6 +490,7 @@ func (v *VM) execute(ctx *Context, op Instruction, parameter []byte) {
 			l = t
 		}
 		v.estack.PushVal(s[:l])
+
 	case RIGHT:
 		l := int(v.estack.Pop().BigInt().Int64())
 		if l < 0 {
@@ -483,6 +498,7 @@ func (v *VM) execute(ctx *Context, op Instruction, parameter []byte) {
 		}
 		s := v.estack.Pop().Bytes()
 		v.estack.PushVal(s[len(s)-l:])
+
 	case XDROP:
 		n := int(v.estack.Pop().BigInt().Int64())
 		if n < 0 {
@@ -967,7 +983,10 @@ func (v *VM) execute(ctx *Context, op Instruction, parameter []byte) {
 
 	case CALL:
 		v.istack.PushVal(ctx.Copy())
-		v.execute(v.Context(), JMP, parameter)
+		err = v.execute(v.Context(), JMP, parameter)
+		if err != nil {
+			return
+		}
 
 	case SYSCALL:
 		ifunc, ok := v.interop[string(parameter)]
@@ -1167,6 +1186,7 @@ func (v *VM) execute(ctx *Context, op Instruction, parameter []byte) {
 	default:
 		panic(fmt.Sprintf("unknown opcode %s", op.String()))
 	}
+	return
 }
 
 func cloneIfStruct(item StackItem) StackItem {
@@ -1195,8 +1215,3 @@ func validateMapKey(key *Element) {
 		panic("key can't be a collection")
 	}
 }
-
-func init() {
-	log.SetPrefix("NEO-GO-VM > ")
-	log.SetFlags(0)
-}