chore(gnovm): instrument debug tracing to display the caller site. (#3702)

Running the gnovm with the debug traces enabled (build tag `debug`)
allows to display the details of preprocessing and opcodes operations.

This PR adds the caller location in source (file + line) to each trace,
allowing to identify the calling context of opcodes, to ease
understanding the gnovm behavior.

No change when debug is disabled (the default mode).

Tracing can be activated by: `go run -tags debug ./cmd/gno run args`

Before:

```console
DEBUG: |||| -v (true <untyped> bool)
DEBUG: EXEC: (const (println func(xs ...interface{})()))((const ("i:" string)), i<VPBlock(1,0)>)
DEBUG: |||| -s bodyStmt[0/0/1]=(end)
DEBUG: |||| +o OpPopResults
DEBUG: ||||| +x (const (println func(xs ...interface{})()))((const ("i:" string)), i<VPBlock(1,0)>)
DEBUG: ||||| +o OpEval
DEBUG: |||||| -o OpEval
DEBUG: EVAL: (*gnolang.CallExpr) (const (println func(xs ...interface{})()))((const ("i:" string)), i<VPBlock(1,0)>)
DEBUG: ||||| +o OpPrecall
DEBUG: |||||| +x i<VPBlock(1,0)>
DEBUG: |||||| +o OpEval
DEBUG: ||||||| +x (const ("i:" string))
DEBUG: ||||||| +o OpEval
DEBUG: |||||||| +x (const (println func(xs ...interface{})()))
DEBUG: |||||||| +o OpEval
DEBUG: ||||||||| -o OpEval
DEBUG: EVAL: (*gnolang.ConstExpr) (const (println func(xs ...interface{})()))
DEBUG: |||||||| -x (const (println func(xs ...interface{})()))
DEBUG: |||||||| +v (println func(xs ...interface{})())
DEBUG: |||||||| -o OpEval
DEBUG: EVAL: (*gnolang.ConstExpr) (const ("i:" string))
DEBUG: ||||||| -x (const ("i:" string))
DEBUG: ||||||| +v ("i:" string)
DEBUG: ||||||| -o OpEval
```

After:
```console
DEBUG:   op_exec.go:99  : |||| -v (true <untyped> bool)
DEBUG:   machine.go:1535: EXEC: (const (println func(xs ...interface{})()))((const ("i:" string)), i<VPBlock(1,0)>)
DEBUG:   op_exec.go:484 : |||| -s bodyStmt[0/0/1]=(end)
DEBUG:   op_exec.go:488 : |||| +o OpPopResults
DEBUG:   op_exec.go:493 : ||||| +x (const (println func(xs ...interface{})()))((const ("i:" string)), i<VPBlock(1,0)>)
DEBUG:   op_exec.go:494 : ||||| +o OpEval
DEBUG:   machine.go:1218: |||||| -o OpEval
DEBUG:   machine.go:1380: EVAL: (*gnolang.CallExpr) (const (println func(xs ...interface{})()))((const ("i:" string)), i<VPBlock(1,0)>)
DEBUG:   op_eval.go:243 : ||||| +o OpPrecall
DEBUG:   op_eval.go:247 : |||||| +x i<VPBlock(1,0)>
DEBUG:   op_eval.go:248 : |||||| +o OpEval
DEBUG:   op_eval.go:247 : ||||||| +x (const ("i:" string))
DEBUG:   op_eval.go:248 : ||||||| +o OpEval
DEBUG:   op_eval.go:251 : |||||||| +x (const (println func(xs ...interface{})()))
DEBUG:   op_eval.go:252 : |||||||| +o OpEval
DEBUG:   machine.go:1218: ||||||||| -o OpEval
DEBUG:   machine.go:1380: EVAL: (*gnolang.ConstExpr) (const (println func(xs ...interface{})()))
DEBUG:   op_eval.go:317 : |||||||| -x (const (println func(xs ...interface{})()))
DEBUG:   op_eval.go:319 : |||||||| +v (println func(xs ...interface{})())
DEBUG:   machine.go:1218: |||||||| -o OpEval
DEBUG:   machine.go:1380: EVAL: (*gnolang.ConstExpr) (const ("i:" string))
DEBUG:   op_eval.go:317 : ||||||| -x (const ("i:" string))
DEBUG:   op_eval.go:319 : ||||||| +v ("i:" string)
DEBUG:   machine.go:1218: ||||||| -o OpEval
```

---------

Co-authored-by: Morgan <[email protected]>

Author: mvertes

gnovm/pkg/gnolang/debug.go

@@ -3,6 +3,8 @@ package gnolang
 import (
 	"fmt"
 	"net/http"
+	"path"
+	"runtime"
 	"strings"
 	"time"
 
@@ -48,15 +50,21 @@ var enabled bool = true
 func (debugging) Println(args ...interface{}) {
 	if debug {
 		if enabled {
-			fmt.Println(append([]interface{}{"DEBUG:"}, args...)...)
+			_, file, line, _ := runtime.Caller(2)
+			caller := fmt.Sprintf("%-.12s:%-4d", path.Base(file), line)
+			prefix := fmt.Sprintf("DEBUG: %17s: ", caller)
+			fmt.Println(append([]interface{}{prefix}, args...)...)
 		}
 	}
 }
 
 func (debugging) Printf(format string, args ...interface{}) {
 	if debug {
 		if enabled {
-			fmt.Printf("DEBUG: "+format, args...)
+			_, file, line, _ := runtime.Caller(2)
+			caller := fmt.Sprintf("%.12s:%-4d", path.Base(file), line)
+			prefix := fmt.Sprintf("DEBUG: %17s: ", caller)
+			fmt.Printf(prefix+format, args...)
 		}
 	}
 }

gnovm/pkg/gnolang/machine.go

@@ -3,7 +3,9 @@ package gnolang
 import (
 	"fmt"
 	"io"
+	"path"
 	"reflect"
+	"runtime"
 	"slices"
 	"strconv"
 	"strings"
@@ -2120,17 +2122,23 @@ func (m *Machine) Panic(ex TypedValue) {
 func (m *Machine) Println(args ...interface{}) {
 	if debug {
 		if enabled {
-			s := strings.Repeat("|", m.NumOps)
-			debug.Println(append([]interface{}{s}, args...)...)
+			_, file, line, _ := runtime.Caller(2) // get caller info
+			caller := fmt.Sprintf("%-.12s:%-4d", path.Base(file), line)
+			prefix := fmt.Sprintf("DEBUG: %17s: ", caller)
+			s := prefix + strings.Repeat("|", m.NumOps)
+			fmt.Println(append([]interface{}{s}, args...)...)
 		}
 	}
 }
 
 func (m *Machine) Printf(format string, args ...interface{}) {
 	if debug {
 		if enabled {
-			s := strings.Repeat("|", m.NumOps)
-			debug.Printf(s+" "+format, args...)
+			_, file, line, _ := runtime.Caller(2) // get caller info
+			caller := fmt.Sprintf("%-.12s:%-4d", path.Base(file), line)
+			prefix := fmt.Sprintf("DEBUG: %17s: ", caller)
+			s := prefix + strings.Repeat("|", m.NumOps)
+			fmt.Printf(s+" "+format, args...)
 		}
 	}
 }