feat(gnovm): add stacktraces and log them in panic messages (#2145)

Closes #1812 #### Summary This pull request introduces a new `StackTrace` mechanism to the `Machine.Exceptions` class, enhancing its exception handling capabilities by generating and appending detailed stacktraces during panic situations. **Panic Handling:** - When a panic occurs, the current stack state is copied and appended to the exception details. - This includes the value of the panic, the last call frame, and the copied stack trace. **Code Example:** ```go package main func main() { f() } func f() { defer func() { panic("third") }() defer func() { panic("second") }() panic("first") } ``` **Sample Output:** ``` Stacktrace: Exception 0: panic((const ("first" <untyped> string))) main/files/panic0b.gno:14 f<VPBlock(3,1)>() main/files/panic0b.gno:4 Exception 1: panic((const ("second" <untyped> string))) main/files/panic0b.gno:12 f<VPBlock(3,1)>() main/files/panic0b.gno:4 Exception 2: panic((const ("third" <untyped> string))) main/files/panic0b.gno:9 f<VPBlock(3,1)>() main/files/panic0b.gno:4 ``` <details><summary>Contributors' checklist...</summary> - [ ] Added new tests, or not needed, or not feasible - [ ] Provided an example (e.g. screenshot) to aid review or the PR is self-explanatory - [ ] Updated the official documentation or not needed - [ ] No breaking changes were made, or a `BREAKING CHANGE: xxx` message was included in the description - [ ] Added references to related issues and PRs - [ ] Provided any useful hints for running manual tests - [ ] Added new benchmarks to [generated graphs](https://gnoland.github.io/benchmarks), if any. More info [here](https://github.com/gnolang/gno/blob/master/.benchmarks/README.md). </details> --------- Co-authored-by: Morgan <[email protected]>
gnolang · Aug 2, 2024 · 56f8357 · 56f8357
1 parent 14b9015
commit 56f8357
Show file tree

Hide file tree

Showing 26 changed files with 947 additions and 51 deletions.
diff --git a/gno.land/cmd/gnoland/testdata/panic.txtar b/gno.land/cmd/gnoland/testdata/panic.txtar
@@ -0,0 +1,27 @@
+# test panic 
+
+loadpkg gno.land/r/demo/panic $WORK
+
+# start a new node
+gnoland start
+
+
+! gnokey maketx call -pkgpath gno.land/r/demo/panic --func Trigger --gas-fee 1000000ugnot --gas-wanted 2000000 --broadcast -chainid=tendermint_test test1
+
+stderr 'p\<VPBlock\(3\,0\)\>\(\)'
+stderr 'gno.land/r/demo/panic/panic.gno:5'
+stderr 'pkg\<VPBlock\(1\,0\)\>\.Trigger\(\)'
+stderr 'gno.land/r/demo/panic/panic.gno:9'
+
+-- panic.gno --
+package main
+
+func p() {
+   i := "here"
+	panic(i)
+}
+
+func Trigger() {
+	p()
+}
+
diff --git a/gno.land/pkg/sdk/vm/keeper.go b/gno.land/pkg/sdk/vm/keeper.go
@@ -537,12 +537,15 @@ func (vm *VMKeeper) Call(ctx sdk.Context, msg MsgCall) (res string, err error) {
 	m.SetActivePackage(mpv)
 	defer func() {
 		if r := recover(); r != nil {
-			switch r.(type) {
+			switch r := r.(type) {
 			case store.OutOfGasException: // panic in consumeGas()
 				panic(r)
+			case gno.UnhandledPanicError:
+				err = errors.Wrap(fmt.Errorf("%v", r.Error()), "VM call panic: %s\nStacktrace: %s\n",
+					r.Error(), m.ExceptionsStacktrace())
 			default:
-				err = errors.Wrap(fmt.Errorf("%v", r), "VM call panic: %v\n%s\n",
-					r, m.String())
+				err = errors.Wrap(fmt.Errorf("%v", r), "VM call panic: %v\nMachine State:%s\nStacktrace: %s\n",
+					r, m.String(), m.Stacktrace().String())
 				return
 			}
 		}

diff --git a/gnovm/cmd/gno/run.go b/gnovm/cmd/gno/run.go
@@ -188,8 +188,14 @@ func listNonTestFiles(dir string) ([]string, error) {
 func runExpr(m *gno.Machine, expr string) {
 	defer func() {
 		if r := recover(); r != nil {
-			fmt.Printf("panic running expression %s: %v\n%s\n",
-				expr, r, m.String())
+			switch r := r.(type) {
+			case gno.UnhandledPanicError:
+				fmt.Printf("panic running expression %s: %v\nStacktrace: %s\n",
+					expr, r.Error(), m.ExceptionsStacktrace())
+			default:
+				fmt.Printf("panic running expression %s: %v\nMachine State:%s\nStacktrace: %s\n",
+					expr, r, m.String(), m.Stacktrace().String())
+			}
 			panic(r)
 		}
 	}()

diff --git a/gnovm/pkg/gnolang/debugger_test.go b/gnovm/pkg/gnolang/debugger_test.go
@@ -24,7 +24,7 @@ type writeNopCloser struct{ io.Writer }
 func (writeNopCloser) Close() error { return nil }
 
 // TODO (Marc): move evalTest to gnovm/tests package and remove code duplicates
-func evalTest(debugAddr, in, file string) (out, err string) {
+func evalTest(debugAddr, in, file string) (out, err, stacktrace string) {
 	bout := bytes.NewBufferString("")
 	berr := bytes.NewBufferString("")
 	stdin := bytes.NewBufferString(in)
@@ -58,6 +58,18 @@ func evalTest(debugAddr, in, file string) (out, err string) {
 	})
 
 	defer m.Release()
+	defer func() {
+		if r := recover(); r != nil {
+			switch r.(type) {
+			case gnolang.UnhandledPanicError:
+				stacktrace = m.ExceptionsStacktrace()
+			default:
+				stacktrace = m.Stacktrace().String()
+			}
+			stacktrace = strings.TrimSpace(strings.ReplaceAll(stacktrace, "../../tests/files/", "files/"))
+			panic(r)
+		}
+	}()
 
 	if debugAddr != "" {
 		if e := m.Debugger.Serve(debugAddr); e != nil {
@@ -69,7 +81,7 @@ func evalTest(debugAddr, in, file string) (out, err string) {
 	m.RunFiles(f)
 	ex, _ := gnolang.ParseExpr("main()")
 	m.Eval(ex)
-	out, err = bout.String(), berr.String()
+	out, err, stacktrace = bout.String(), berr.String(), m.ExceptionsStacktrace()
 	return
 }
 
@@ -78,7 +90,7 @@ func runDebugTest(t *testing.T, targetPath string, tests []dtest) {
 
 	for _, test := range tests {
 		t.Run("", func(t *testing.T) {
-			out, err := evalTest("", test.in, targetPath)
+			out, err, _ := evalTest("", test.in, targetPath)
 			t.Log("in:", test.in, "out:", out, "err:", err)
 			if !strings.Contains(out, test.out) {
 				t.Errorf("unexpected output\nwant\"%s\"\n  got \"%s\"", test.out, out)
@@ -194,7 +206,7 @@ func TestRemoteDebug(t *testing.T) {
 }
 
 func TestRemoteError(t *testing.T) {
-	_, err := evalTest(":xxx", "", debugTarget)
+	_, err, _ := evalTest(":xxx", "", debugTarget)
 	t.Log("err:", err)
 	if !strings.Contains(err, "tcp/xxx: unknown port") &&
 		!strings.Contains(err, "tcp/xxx: nodename nor servname provided, or not known") {

diff --git a/gnovm/pkg/gnolang/eval_test.go b/gnovm/pkg/gnolang/eval_test.go
@@ -3,6 +3,7 @@ package gnolang_test
 import (
 	"os"
 	"path"
+	"sort"
 	"strings"
 	"testing"
 )
@@ -14,17 +15,21 @@ func TestEvalFiles(t *testing.T) {
 		t.Fatal(err)
 	}
 	for _, f := range files {
-		wantOut, wantErr, ok := testData(dir, f)
+		wantOut, wantErr, wantStacktrace, ok := testData(dir, f)
 		if !ok {
 			continue
 		}
 		t.Run(f.Name(), func(t *testing.T) {
-			out, err := evalTest("", "", path.Join(dir, f.Name()))
+			out, err, stacktrace := evalTest("", "", path.Join(dir, f.Name()))
 
 			if wantErr != "" && !strings.Contains(err, wantErr) ||
 				wantErr == "" && err != "" {
 				t.Fatalf("unexpected error\nWant: %s\n Got: %s", wantErr, err)
 			}
+
+			if wantStacktrace != "" && !strings.Contains(stacktrace, wantStacktrace) {
+				t.Fatalf("unexpected stacktrace\nWant: %s\n Got: %s", wantStacktrace, stacktrace)
+			}
 			if wantOut != "" && out != wantOut {
 				t.Fatalf("unexpected output\nWant: %s\n Got: %s", wantOut, out)
 			}
@@ -33,30 +38,63 @@ func TestEvalFiles(t *testing.T) {
 }
 
 // testData returns the expected output and error string, and true if entry is valid.
-func testData(dir string, f os.DirEntry) (testOut, testErr string, ok bool) {
+func testData(dir string, f os.DirEntry) (testOut, testErr, testStacktrace string, ok bool) {
 	if f.IsDir() {
-		return "", "", false
+		return
 	}
 	name := path.Join(dir, f.Name())
 	if !strings.HasSuffix(name, ".gno") || strings.HasSuffix(name, "_long.gno") {
-		return "", "", false
+		return
 	}
 	buf, err := os.ReadFile(name)
 	if err != nil {
-		return "", "", false
+		return
 	}
 	str := string(buf)
 	if strings.Contains(str, "// PKGPATH:") {
-		return "", "", false
+		return
 	}
-	return commentFrom(str, "\n// Output:"), commentFrom(str, "\n// Error:"), true
+
+	res := commentFrom(str, []string{"\n// Output:", "\n// Error:", "\n// Stacktrace:"})
+
+	return res[0], res[1], res[2], true
 }
 
-// commentFrom returns the content from a trailing comment block in s starting with delim.
-func commentFrom(s, delim string) string {
-	index := strings.Index(s, delim)
-	if index < 0 {
-		return ""
+type directive struct {
+	delim string
+	res   string
+	index int
+}
+
+// commentFrom returns the comments from s that are between the delimiters.
+func commentFrom(s string, delims []string) []string {
+	directives := make([]directive, len(delims))
+	directivesFound := make([]*directive, 0, len(delims))
+
+	for i, delim := range delims {
+		index := strings.Index(s, delim)
+		directives[i] = directive{delim: delim, index: index}
+		if index >= 0 {
+			directivesFound = append(directivesFound, &directives[i])
+		}
 	}
-	return strings.TrimSpace(strings.ReplaceAll(s[index+len(delim):], "\n// ", "\n"))
+	sort.Slice(directivesFound, func(i, j int) bool {
+		return directivesFound[i].index < directivesFound[j].index
+	})
+
+	for i := range directivesFound {
+		next := len(s)
+		if i != len(directivesFound)-1 {
+			next = directivesFound[i+1].index
+		}
+
+		directivesFound[i].res = strings.TrimSpace(strings.ReplaceAll(s[directivesFound[i].index+len(directivesFound[i].delim):next], "\n// ", "\n"))
+	}
+
+	res := make([]string, len(directives))
+	for i, d := range directives {
+		res[i] = d.res
+	}
+
+	return res
 }
diff --git a/gnovm/pkg/gnolang/frame.go b/gnovm/pkg/gnolang/frame.go
@@ -2,8 +2,11 @@ package gnolang
 
 import (
 	"fmt"
+	"strings"
 )
 
+const maxStacktraceSize = 128
+
 //----------------------------------------
 // (runtime) Frame
 
@@ -64,6 +67,10 @@ func (fr Frame) String() string {
 	}
 }
 
+func (fr *Frame) IsCall() bool {
+	return fr.Func != nil || fr.GoFunc != nil
+}
+
 func (fr *Frame) PushDefer(dfr Defer) {
 	fr.Defers = append(fr.Defers, dfr)
 }
@@ -92,3 +99,119 @@ type Defer struct {
 	// a panic occurs and is decremented each time a panic is recovered.
 	PanicScope uint
 }
+
+type StacktraceCall struct {
+	Stmt  Stmt
+	Frame *Frame
+}
+type Stacktrace struct {
+	Calls           []StacktraceCall
+	NumFramesElided int
+}
+
+func (s Stacktrace) String() string {
+	var builder strings.Builder
+
+	for i := 0; i < len(s.Calls); i++ {
+		if s.NumFramesElided > 0 && i == maxStacktraceSize/2 {
+			fmt.Fprintf(&builder, "...%d frame(s) elided...\n", s.NumFramesElided)
+		}
+
+		call := s.Calls[i]
+		cx := call.Frame.Source.(*CallExpr)
+		switch {
+		case call.Frame.Func != nil && call.Frame.Func.IsNative():
+			fmt.Fprintf(&builder, "%s\n", toExprTrace(cx))
+			fmt.Fprintf(&builder, "    gonative:%s.%s\n", call.Frame.Func.NativePkg, call.Frame.Func.NativeName)
+		case call.Frame.Func != nil:
+			fmt.Fprintf(&builder, "%s\n", toExprTrace(cx))
+			fmt.Fprintf(&builder, "    %s/%s:%d\n", call.Frame.Func.PkgPath, call.Frame.Func.FileName, call.Stmt.GetLine())
+		case call.Frame.GoFunc != nil:
+			fmt.Fprintf(&builder, "%s\n", toExprTrace(cx))
+			fmt.Fprintf(&builder, "    gofunction:%s\n", call.Frame.GoFunc.Value.Type())
+		default:
+			panic("StacktraceCall has a non-call Frame")
+		}
+	}
+	return builder.String()
+}
+
+func toExprTrace(ex Expr) string {
+	switch ex := ex.(type) {
+	case *CallExpr:
+		s := make([]string, len(ex.Args))
+		for i, arg := range ex.Args {
+			s[i] = toExprTrace(arg)
+		}
+		return fmt.Sprintf("%s(%s)", toExprTrace(ex.Func), strings.Join(s, ","))
+	case *BinaryExpr:
+		return fmt.Sprintf("%s %s %s", toExprTrace(ex.Left), ex.Op.TokenString(), toExprTrace(ex.Right))
+	case *UnaryExpr:
+		return fmt.Sprintf("%s%s", ex.Op.TokenString(), toExprTrace(ex.X))
+	case *SelectorExpr:
+		return fmt.Sprintf("%s.%s", toExprTrace(ex.X), ex.Sel)
+	case *IndexExpr:
+		return fmt.Sprintf("%s[%s]", toExprTrace(ex.X), toExprTrace(ex.Index))
+	case *StarExpr:
+		return fmt.Sprintf("*%s", toExprTrace(ex.X))
+	case *RefExpr:
+		return fmt.Sprintf("&%s", toExprTrace(ex.X))
+	case *CompositeLitExpr:
+		lenEl := len(ex.Elts)
+		if ex.Type == nil {
+			return fmt.Sprintf("<elided><len=%d>", lenEl)
+		}
+
+		return fmt.Sprintf("%s<len=%d>", toExprTrace(ex.Type), lenEl)
+	case *FuncLitExpr:
+		return fmt.Sprintf("%s{ ... }", toExprTrace(&ex.Type))
+	case *TypeAssertExpr:
+		return fmt.Sprintf("%s.(%s)", toExprTrace(ex.X), toExprTrace(ex.Type))
+	case *ConstExpr:
+		return toConstExpTrace(ex)
+	case *NameExpr, *BasicLitExpr, *SliceExpr:
+		return ex.String()
+	}
+
+	return ex.String()
+}
+
+func toConstExpTrace(cte *ConstExpr) string {
+	tv := cte.TypedValue
+
+	switch bt := baseOf(tv.T).(type) {
+	case PrimitiveType:
+		switch bt {
+		case UntypedBoolType, BoolType:
+			return fmt.Sprintf("%t", tv.GetBool())
+		case UntypedStringType, StringType:
+			return tv.GetString()
+		case IntType:
+			return fmt.Sprintf("%d", tv.GetInt())
+		case Int8Type:
+			return fmt.Sprintf("%d", tv.GetInt8())
+		case Int16Type:
+			return fmt.Sprintf("%d", tv.GetInt16())
+		case UntypedRuneType, Int32Type:
+			return fmt.Sprintf("%d", tv.GetInt32())
+		case Int64Type:
+			return fmt.Sprintf("%d", tv.GetInt64())
+		case UintType:
+			return fmt.Sprintf("%d", tv.GetUint())
+		case Uint8Type:
+			return fmt.Sprintf("%d", tv.GetUint8())
+		case Uint16Type:
+			return fmt.Sprintf("%d", tv.GetUint16())
+		case Uint32Type:
+			return fmt.Sprintf("%d", tv.GetUint32())
+		case Uint64Type:
+			return fmt.Sprintf("%d", tv.GetUint64())
+		case Float32Type:
+			return fmt.Sprintf("%v", tv.GetFloat32())
+		case Float64Type:
+			return fmt.Sprintf("%v", tv.GetFloat64())
+		}
+	}
+
+	return tv.T.String()
+}