Repository: tetratelabs/wazero
Pull request #1401 (2023-04-25 01:32:01)

debug: includes Go stack trace in the face of Go runtime errors
this improves the debuggability of the issues like #1399 

Below is the example output for this change on debugging 1399:

```
2023/04/25 10:35:16 runtime error: invalid memory address or nil pointer dereference (recovered by wazero)
wasm stack trace:
        env.hostTalk(i32,i32,i32,i32) i32
        .hello(i32,i32) i64

Go runtime stack trace:
goroutine 1 [running]:
runtime/debug.Stack()
        /usr/local/go/src/runtime/debug/stack.go:24 +0x64
github.com/tetratelabs/wazero/internal/wasmdebug.(*stackTrace).FromRecovered(0x140001e78d0?, {0x100285760?, 0x100396360?})
        /Users/mathetake/wazero/internal/wasmdebug/debug.go:139 +0xc4
github.com/tetratelabs/wazero/internal/engine/compiler.(*callEngine).deferredOnCall(0x14000178900, {0x100285760, 0x100396360})
        /Users/mathetake/wazero/internal/engine/compiler/engine.go:803 +0x25c
github.com/tetratelabs/wazero/internal/engine/compiler.(*callEngine).Call.func1()
        /Users/mathetake/wazero/internal/engine/compiler/engine.go:691 +0x4c
panic({0x100285760, 0x100396360})
        /usr/local/go/src/runtime/panic.go:884 +0x1f4
main.glob..func2({0x1002a8e80, 0x14000112000}, {0x1002aa528, 0x140001786c0}, {0x14000249048, 0x4, 0x140001e7c01?})
        /Users/mathetake/wazero-step-by-step/chapter-04/host/main.go:50 +0x170
github.com/tetratelabs/wazero/api.GoModuleFunc.Call(0x1078d8038?, {0x1002a8e80?, 0x14000112000?}, {0x1002aa528?, 0x140001786c0?}, {0x14000249048?, 0x140001e7c88?, 0x1000fb1e4?})
        /Users/mathetake/wazero/api/wasm.go:411 +0x54
github.com/tetratelabs/wazero/internal/engine/compiler.(*callEngine).execWasmFunction(0x14000178900, {0x1002a8e80?, 0x14000112000?}, 0x1003a4300?)
        /Users/mathetake/wazero/internal/engine/compiler/engine.go:953 +0x158
github.com/tetratelabs/wazero/internal/engine/compiler.(*callEngine).Call(0x14000178900, {0x1002a8e80, 0x14000112000}, {0x14000112af0?, 0x2, 0x1b68?})
        /Users/mathetake/wazero/internal/engine/compiler/engine.go:705 +0x2b4
main.main()
        /Users/mathetake/wazero-step-by-step/chapter-04/host/main.go:165 +0x534

```


Patch:
diff --git a/internal/wasmdebug/debug.go b/internal/wasmdebug/debug.go
index 285a7717..0aa61369 100644
--- a/internal/wasmdebug/debug.go
+++ b/internal/wasmdebug/debug.go
@@ -112,6 +112,10 @@ type stackTrace struct {
 	frames []string
 }
 
+// GoRuntimeErrorTracePrefix is the prefix coming before the Go runtime stack trace included in the face of runtime.Error.
+// This is exported for testing purpose.
+const GoRuntimeErrorTracePrefix = "Go runtime stack trace:"
+
 func (s *stackTrace) FromRecovered(recovered interface{}) error {
 	if false {
 		debug.PrintStack()
@@ -131,8 +135,8 @@ func (s *stackTrace) FromRecovered(recovered interface{}) error {
 	// If we have a runtime.Error, something severe happened which should include the stack trace. This could be
 	// a nil pointer from wazero or a user-defined function from HostModuleBuilder.
 	if runtimeErr, ok := recovered.(runtime.Error); ok {
-		// TODO: consider adding debug.Stack(), but last time we attempted, some tests became unstable.
-		return fmt.Errorf("%w (recovered by wazero)\nwasm stack trace:\n\t%s", runtimeErr, stack)
+		return fmt.Errorf("%w (recovered by wazero)\nwasm stack trace:\n\t%s\n\n%s\n%s",
+			runtimeErr, stack, GoRuntimeErrorTracePrefix, debug.Stack())
 	}
 
 	// At this point we expect the error was from a function defined by HostModuleBuilder that intentionally called panic.


Test patch:
diff --git a/internal/engine/compiler/engine_test.go b/internal/engine/compiler/engine_test.go
index 0d2a0ed5..fbf56af2 100644
--- a/internal/engine/compiler/engine_test.go
+++ b/internal/engine/compiler/engine_test.go
@@ -44,23 +44,23 @@ func (e engineTester) NewEngine(enabledFeatures api.CoreFeatures) wasm.Engine {
 func TestCompiler_Engine_NewModuleEngine(t *testing.T) {
 	defer functionLog.Reset()
 	requireSupportedOSArch(t)
-	enginetest.RunTestEngine_NewModuleEngine(t, et)
+	enginetest.RunTestEngineNewModuleEngine(t, et)
 }
 
 func TestCompiler_MemoryGrowInRecursiveCall(t *testing.T) {
 	defer functionLog.Reset()
-	enginetest.RunTestEngine_MemoryGrowInRecursiveCall(t, et)
+	enginetest.RunTestEngineMemoryGrowInRecursiveCall(t, et)
 }
 
 func TestCompiler_ModuleEngine_LookupFunction(t *testing.T) {
 	defer functionLog.Reset()
-	enginetest.RunTestModuleEngine_LookupFunction(t, et)
+	enginetest.RunTestModuleEngineLookupFunction(t, et)
 }
 
 func TestCompiler_ModuleEngine_Call(t *testing.T) {
 	defer functionLog.Reset()
 	requireSupportedOSArch(t)
-	enginetest.RunTestModuleEngine_Call(t, et)
+	enginetest.RunTestModuleEngineCall(t, et)
 	require.Equal(t, `
 --> .$0(1,2)
 <-- (1,2)
@@ -70,7 +70,7 @@ func TestCompiler_ModuleEngine_Call(t *testing.T) {
 func TestCompiler_ModuleEngine_Call_HostFn(t *testing.T) {
 	defer functionLog.Reset()
 	requireSupportedOSArch(t)
-	enginetest.RunTestModuleEngine_Call_HostFn(t, et)
+	enginetest.RunTestModuleEngineCallHostFn(t, et)
 }
 
 func TestCompiler_ModuleEngine_Call_Errors(t *testing.T) {
@@ -131,11 +131,11 @@ func TestCompiler_ModuleEngine_Call_Errors(t *testing.T) {
 func TestCompiler_ModuleEngine_Memory(t *testing.T) {
 	defer functionLog.Reset()
 	requireSupportedOSArch(t)
-	enginetest.RunTestModuleEngine_Memory(t, et)
+	enginetest.RunTestModuleEngineMemory(t, et)
 }
 
 func TestCompiler_BeforeListenerStackIterator(t *testing.T) {
-	enginetest.RunTestModuleEngine_BeforeListenerStackIterator(t, et)
+	enginetest.RunTestModuleEngineBeforeListenerStackIterator(t, et)
 }
 
 // requireSupportedOSArch is duplicated also in the platform package to ensure no cyclic dependency.
diff --git a/internal/engine/interpreter/interpreter_test.go b/internal/engine/interpreter/interpreter_test.go
index 99b68352..ff7de9f3 100644
--- a/internal/engine/interpreter/interpreter_test.go
+++ b/internal/engine/interpreter/interpreter_test.go
@@ -85,20 +85,20 @@ func (e engineTester) NewEngine(enabledFeatures api.CoreFeatures) wasm.Engine {
 
 func TestInterpreter_MemoryGrowInRecursiveCall(t *testing.T) {
 	defer functionLog.Reset()
-	enginetest.RunTestEngine_MemoryGrowInRecursiveCall(t, et)
+	enginetest.RunTestEngineMemoryGrowInRecursiveCall(t, et)
 }
 
 func TestInterpreter_Engine_NewModuleEngine(t *testing.T) {
-	enginetest.RunTestEngine_NewModuleEngine(t, et)
+	enginetest.RunTestEngineNewModuleEngine(t, et)
 }
 
 func TestInterpreter_ModuleEngine_LookupFunction(t *testing.T) {
-	enginetest.RunTestModuleEngine_LookupFunction(t, et)
+	enginetest.RunTestModuleEngineLookupFunction(t, et)
 }
 
 func TestInterpreter_ModuleEngine_Call(t *testing.T) {
 	defer functionLog.Reset()
-	enginetest.RunTestModuleEngine_Call(t, et)
+	enginetest.RunTestModuleEngineCall(t, et)
 	require.Equal(t, `
 --> .$0(1,2)
 <-- (1,2)
@@ -107,7 +107,7 @@ func TestInterpreter_ModuleEngine_Call(t *testing.T) {
 
 func TestInterpreter_ModuleEngine_Call_HostFn(t *testing.T) {
 	defer functionLog.Reset()
-	enginetest.RunTestModuleEngine_Call_HostFn(t, et)
+	enginetest.RunTestModuleEngineCallHostFn(t, et)
 }
 
 func TestInterpreter_ModuleEngine_Call_Errors(t *testing.T) {
@@ -165,7 +165,7 @@ func TestInterpreter_ModuleEngine_Call_Errors(t *testing.T) {
 }
 
 func TestInterpreter_ModuleEngine_Memory(t *testing.T) {
-	enginetest.RunTestModuleEngine_Memory(t, et)
+	enginetest.RunTestModuleEngineMemory(t, et)
 }
 
 func TestInterpreter_NonTrappingFloatToIntConversion(t *testing.T) {
@@ -563,5 +563,5 @@ func TestEngine_CachedcodesPerModule(t *testing.T) {
 }
 
 func TestCompiler_BeforeListenerStackIterator(t *testing.T) {
-	enginetest.RunTestModuleEngine_BeforeListenerStackIterator(t, et)
+	enginetest.RunTestModuleEngineBeforeListenerStackIterator(t, et)
 }
diff --git a/internal/testing/enginetest/enginetest.go b/internal/testing/enginetest/enginetest.go
index 181a4601..308ef8de 100644
--- a/internal/testing/enginetest/enginetest.go
+++ b/internal/testing/enginetest/enginetest.go
@@ -4,14 +4,14 @@
 // In simplest case, dispatch:
 //
 //	func TestModuleEngine_Call(t *testing.T) {
-//		enginetest.RunTestModuleEngine_Call(t, NewEngine)
+//		enginetest.RunTestModuleEngineCall(t, NewEngine)
 //	}
 //
 // Some tests using the Compiler Engine may need to guard as they use compiled features:
 //
 //	func TestModuleEngine_Call(t *testing.T) {
 //		requireSupportedOSArch(t)
-//		enginetest.RunTestModuleEngine_Call(t, NewEngine)
+//		enginetest.RunTestModuleEngineCall(t, NewEngine)
 //	}
 //
 // Note: These tests intentionally avoid using wasm.Store as it is important to know both the dependencies and
@@ -22,6 +22,7 @@ import (
 	"context"
 	"errors"
 	"math"
+	"strings"
 	"testing"
 
 	"github.com/tetratelabs/wazero/api"
@@ -29,6 +30,7 @@ import (
 	"github.com/tetratelabs/wazero/internal/testing/require"
 	"github.com/tetratelabs/wazero/internal/u64"
 	"github.com/tetratelabs/wazero/internal/wasm"
+	"github.com/tetratelabs/wazero/internal/wasmdebug"
 	"github.com/tetratelabs/wazero/internal/wasmruntime"
 )
 
@@ -36,12 +38,8 @@ const (
 	i32, i64 = wasm.ValueTypeI32, wasm.ValueTypeI64
 )
 
-var (
-	// testCtx is an arbitrary, non-default context. Non-nil also prevents linter errors.
-	testCtx = context.WithValue(context.Background(), struct{}{}, "arbitrary")
-	// v_v is a nullary function type (void -> void)
-	v_v = wasm.FunctionType{}
-)
+// testCtx is an arbitrary, non-default context. Non-nil also prevents linter errors.
+var testCtx = context.WithValue(context.Background(), struct{}{}, "arbitrary")
 
 type EngineTester interface {
 	NewEngine(enabledFeatures api.CoreFeatures) wasm.Engine
@@ -49,8 +47,8 @@ type EngineTester interface {
 	ListenerFactory() experimental.FunctionListenerFactory
 }
 
-// RunTestEngine_MemoryGrowInRecursiveCall ensures that it's safe to grow memory in the recursive Wasm calls.
-func RunTestEngine_MemoryGrowInRecursiveCall(t *testing.T, et EngineTester) {
+// RunTestEngineMemoryGrowInRecursiveCall ensures that it's safe to grow memory in the recursive Wasm calls.
+func RunTestEngineMemoryGrowInRecursiveCall(t *testing.T, et EngineTester) {
 	enabledFeatures := api.CoreFeaturesV1
 	e := et.NewEngine(enabledFeatures)
 	s := wasm.NewStore(enabledFeatures, e)
@@ -126,7 +124,7 @@ func RunTestEngine_MemoryGrowInRecursiveCall(t *testing.T, et EngineTester) {
 	require.NoError(t, err)
 }
 
-func RunTestEngine_NewModuleEngine(t *testing.T, et EngineTester) {
+func RunTestEngineNewModuleEngine(t *testing.T, et EngineTester) {
 	e := et.NewEngine(api.CoreFeaturesV1)
 
 	t.Run("error before instantiation", func(t *testing.T) {
@@ -135,7 +133,7 @@ func RunTestEngine_NewModuleEngine(t *testing.T, et EngineTester) {
 	})
 }
 
-func RunTestModuleEngine_Call(t *testing.T, et EngineTester) {
+func RunTestModuleEngineCall(t *testing.T, et EngineTester) {
 	e := et.NewEngine(api.CoreFeaturesV2)
 
 	// Define a basic function which defines two parameters and two results.
@@ -192,7 +190,7 @@ func RunTestModuleEngine_Call(t *testing.T, et EngineTester) {
 	})
 }
 
-func RunTestModuleEngine_LookupFunction(t *testing.T, et EngineTester) {
+func RunTestModuleEngineLookupFunction(t *testing.T, et EngineTester) {
 	e := et.NewEngine(api.CoreFeaturesV1)
 
 	mod := &wasm.Module{
@@ -269,10 +267,10 @@ func RunTestModuleEngine_LookupFunction(t *testing.T, et EngineTester) {
 	})
 }
 
-func runTestModuleEngine_Call_HostFn_Mem(t *testing.T, et EngineTester, readMem *wasm.Code) {
+func runTestModuleEngineCallHostFnMem(t *testing.T, et EngineTester, readMem *wasm.Code) {
 	e := et.NewEngine(api.CoreFeaturesV1)
 	defer e.Close()
-	importing := setupCallMemTests(t, e, readMem, et.ListenerFactory())
+	importing := setupCallMemTests(t, e, readMem)
 
 	importingMemoryVal := uint64(6)
 	importing.MemoryInstance = &wasm.MemoryInstance{Buffer: u64.LeBytes(importingMemoryVal), Min: 1, Cap: 1, Max: 1}
@@ -301,17 +299,17 @@ func runTestModuleEngine_Call_HostFn_Mem(t *testing.T, et EngineTester, readMem
 	}
 }
 
-func RunTestModuleEngine_Call_HostFn(t *testing.T, et EngineTester) {
+func RunTestModuleEngineCallHostFn(t *testing.T, et EngineTester) {
 	t.Run("wasm", func(t *testing.T) {
-		runTestModuleEngine_Call_HostFn(t, et, hostDivByWasm)
+		runTestModuleEngineCallHostFn(t, et, hostDivByWasm)
 	})
 	t.Run("go", func(t *testing.T) {
-		runTestModuleEngine_Call_HostFn(t, et, &hostDivByGo)
-		runTestModuleEngine_Call_HostFn_Mem(t, et, &hostReadMemGo)
+		runTestModuleEngineCallHostFn(t, et, &hostDivByGo)
+		runTestModuleEngineCallHostFnMem(t, et, &hostReadMemGo)
 	})
 }
 
-func runTestModuleEngine_Call_HostFn(t *testing.T, et EngineTester, hostDivBy *wasm.Code) {
+func runTestModuleEngineCallHostFn(t *testing.T, et EngineTester, hostDivBy *wasm.Code) {
 	e := et.NewEngine(api.CoreFeaturesV1)
 	defer e.Close()
 
@@ -448,7 +446,15 @@ wasm stack trace:
 			ce := tc.module.Engine.NewFunction(tc.fn)
 
 			_, err := ce.Call(testCtx, tc.input...)
-			require.EqualError(t, err, tc.expectedErr)
+			require.NotNil(t, err)
+
+			errStr := err.Error()
+			// If this faces a Go runtime error, the error includes the Go stack trace which makes the test unstable,
+			// so we trim them here.
+			if index := strings.Index(errStr, wasmdebug.GoRuntimeErrorTracePrefix); index > -1 {
+				errStr = strings.TrimSpace(errStr[:index])
+			}
+			require.Equal(t, errStr, tc.expectedErr)
 
 			// Ensure the module still works
 			results, err := ce.Call(testCtx, 1)
@@ -458,7 +464,7 @@ wasm stack trace:
 	}
 }
 
-// This tests that the StackIterator provided by the Engine to the Before hook
+// RunTestModuleEngineBeforeListenerStackIterator tests that the StackIterator provided by the Engine to the Before hook
 // of the listener is properly able to walk the stack.  As an example, it
 // validates that the following call stack is properly walked:
 //
@@ -466,7 +472,7 @@ wasm stack trace:
 //  2. calls f2(no arg) [1 return, 1 local]
 //  3. calls f3(5) [1 return, no local]
 //  4. calls f4(6) [1 return, HOST]
-func RunTestModuleEngine_BeforeListenerStackIterator(t *testing.T, et EngineTester) {
+func RunTestModuleEngineBeforeListenerStackIterator(t *testing.T, et EngineTester) {
 	e := et.NewEngine(api.CoreFeaturesV2)
 
 	type stackEntry struct {
@@ -622,31 +628,31 @@ type fnListener struct {
 	afterFn  func(ctx context.Context, mod api.Module, def api.FunctionDefinition, err error, resultValues []uint64)
 }
 
-func (f *fnListener) NewListener(fnd api.FunctionDefinition) experimental.FunctionListener {
+func (f *fnListener) NewListener(api.FunctionDefinition) experimental.FunctionListener {
 	return f
 }
 
-func (f fnListener) Before(ctx context.Context, mod api.Module, def api.FunctionDefinition, paramValues []uint64, stackIterator experimental.StackIterator) context.Context {
+func (f *fnListener) Before(ctx context.Context, mod api.Module, def api.FunctionDefinition, paramValues []uint64, stackIterator experimental.StackIterator) context.Context {
 	if f.beforeFn != nil {
 		return f.beforeFn(ctx, mod, def, paramValues, stackIterator)
 	}
 	return ctx
 }
 
-func (f fnListener) After(ctx context.Context, mod api.Module, def api.FunctionDefinition, err error, resultValues []uint64) {
+func (f *fnListener) After(ctx context.Context, mod api.Module, def api.FunctionDefinition, err error, resultValues []uint64) {
 	if f.afterFn != nil {
 		f.afterFn(ctx, mod, def, err, resultValues)
 	}
 }
 
-// RunTestModuleEngine_Memory shows that the byte slice returned from api.Memory Read is not a copy, rather a re-slice
+// RunTestModuleEngineMemory shows that the byte slice returned from api.Memory Read is not a copy, rather a re-slice
 // of the underlying memory. This allows both host and Wasm to see each other's writes, unless one side changes the
 // capacity of the slice.
 //
 // Known cases that change the slice capacity:
 // * Host code calls append on a byte slice returned by api.Memory Read
 // * Wasm code calls wasm.OpcodeMemoryGrowName and this changes the capacity (by default, it will).
-func RunTestModuleEngine_Memory(t *testing.T, et EngineTester) {
+func RunTestModuleEngineMemory(t *testing.T, et EngineTester) {
 	e := et.NewEngine(api.CoreFeaturesV2)
 
 	wasmPhrase := "Well, that'll be the day when you say goodbye."
@@ -655,7 +661,7 @@ func RunTestModuleEngine_Memory(t *testing.T, et EngineTester) {
 	// Define a basic function which defines one parameter. This is used to test results when incorrect arity is used.
 	one := uint32(1)
 	m := &wasm.Module{
-		TypeSection:     []wasm.FunctionType{{Params: []api.ValueType{api.ValueTypeI32}, ParamNumInUint64: 1}, v_v},
+		TypeSection:     []wasm.FunctionType{{Params: []api.ValueType{api.ValueTypeI32}, ParamNumInUint64: 1}, {}},
 		FunctionSection: []wasm.Index{0, 1},
 		MemorySection:   &wasm.Memory{Min: 1, Cap: 1, Max: 2},
 		DataSection: []wasm.DataSegment{
@@ -909,7 +915,7 @@ func setupCallTests(t *testing.T, e wasm.Engine, divBy *wasm.Code, fnlf experime
 	return imported, importing
 }
 
-func setupCallMemTests(t *testing.T, e wasm.Engine, readMem *wasm.Code, fnlf experimental.FunctionListenerFactory) *wasm.ModuleInstance {
+func setupCallMemTests(t *testing.T, e wasm.Engine, readMem *wasm.Code) *wasm.ModuleInstance {
 	ft := wasm.FunctionType{Results: []wasm.ValueType{i64}, ResultNumInUint64: 1}
 
 	hostModule := &wasm.Module{
diff --git a/internal/wasmdebug/debug_test.go b/internal/wasmdebug/debug_test.go
index 037d0940..1747423f 100644
--- a/internal/wasmdebug/debug_test.go
+++ b/internal/wasmdebug/debug_test.go
@@ -64,12 +64,14 @@ func TestAddSignature(t *testing.T) {
 	}
 }
 
-func TestErrorBuilder(t *testing.T) {
-	argErr := errors.New("invalid argument")
-	rteErr := testRuntimeErr("index out of bounds")
-	i32 := api.ValueTypeI32
-	i32i32i32i32 := []api.ValueType{i32, i32, i32, i32}
+var (
+	argErr       = errors.New("invalid argument")
+	rteErr       = testRuntimeErr("index out of bounds")
+	i32          = api.ValueTypeI32
+	i32i32i32i32 = []api.ValueType{i32, i32, i32, i32}
+)
 
+func TestErrorBuilder(t *testing.T) {
 	tests := []struct {
 		name         string
 		build        func(ErrorBuilder) error
@@ -100,19 +102,6 @@ wasm stack trace:
 	x.y()`,
 			expectUnwrap: argErr,
 		},
-		{
-			name: "runtime.Error",
-			build: func(builder ErrorBuilder) error {
-				builder.AddFrame("wasi_snapshot_preview1.fd_write", i32i32i32i32, []api.ValueType{i32}, nil)
-				builder.AddFrame("x.y", nil, nil, nil)
-				return builder.FromRecovered(rteErr)
-			},
-			expectedErr: `index out of bounds (recovered by wazero)
-wasm stack trace:
-	wasi_snapshot_preview1.fd_write(i32,i32,i32,i32) i32
-	x.y()`,
-			expectUnwrap: rteErr,
-		},
 		{
 			name: "wasmruntime.Error",
 			build: func(builder ErrorBuilder) error {
@@ -140,6 +129,24 @@ wasm stack trace:
 	}
 }
 
+func TestErrorBuilderGoRuntimeError(t *testing.T) {
+	builder := NewErrorBuilder()
+	builder.AddFrame("wasi_snapshot_preview1.fd_write", i32i32i32i32, []api.ValueType{i32}, nil)
+	builder.AddFrame("x.y", nil, nil, nil)
+	withStackTrace := builder.FromRecovered(rteErr)
+
+	require.Equal(t, rteErr, errors.Unwrap(withStackTrace))
+
+	errStr := withStackTrace.Error()
+	require.Contains(t, errStr, `index out of bounds (recovered by wazero)
+wasm stack trace:
+	wasi_snapshot_preview1.fd_write(i32,i32,i32,i32) i32
+	x.y()`)
+	require.Contains(t, errStr, "Go runtime stack trace:")
+	require.Contains(t, errStr, "goroutine ")
+	require.Contains(t, errStr, "wazero/internal/wasmdebug/debug_test.go")
+}
+
 // compile-time check to ensure testRuntimeErr implements runtime.Error.
 var _ runtime.Error = testRuntimeErr("")