Repository: tetratelabs/wazero
Pull request #1072 (2023-01-28 18:16:32)

logging: adds poll scope
This allows you to specify the poll scope amongst existing logging scopes, both in API and the CLI.

e.g for the CLI.
```bash
$ wazero run --hostlogging=poll --hostlogging=filesystem --mount=.:/:ro cat.wasm
```

e.g. for Go
```go
loggingCtx := context.WithValue(testCtx, experimental.FunctionListenerFactoryKey{},
	logging.NewHostLoggingListenerFactory(&log, logging.LogScopePoll|logging.LogScopeFilesystem))
```

This is particularly helpful to understand side-effects of GC. For example, in `GOOS=js` GC will trigger events and these have been tricky to troubleshoot in the past.


Patch:
diff --git a/cmd/wazero/wazero.go b/cmd/wazero/wazero.go
index bdbd7c01..eaffdd75 100644
--- a/cmd/wazero/wazero.go
+++ b/cmd/wazero/wazero.go
@@ -127,7 +127,7 @@ func doRun(args []string, stdOut io.Writer, stdErr logging.Writer, exit func(cod
 	var hostlogging logScopesFlag
 	flags.Var(&hostlogging, "hostlogging",
 		"A scope of host functions to log to stderr. "+
-			"This may be specified multiple times. Supported values: clock,filesystem,random")
+			"This may be specified multiple times. Supported values: clock,filesystem,poll,random")
 
 	cacheDir := cacheDirFlag(flags)
 
@@ -374,6 +374,8 @@ func (f *logScopesFlag) Set(s string) error {
 		*f |= logScopesFlag(logging.LogScopeClock)
 	case "filesystem":
 		*f |= logScopesFlag(logging.LogScopeFilesystem)
+	case "poll":
+		*f |= logScopesFlag(logging.LogScopePoll)
 	case "random":
 		*f |= logScopesFlag(logging.LogScopeRandom)
 	default:
diff --git a/experimental/logging/log_listener.go b/experimental/logging/log_listener.go
index 0e977779..5b99ee3e 100644
--- a/experimental/logging/log_listener.go
+++ b/experimental/logging/log_listener.go
@@ -36,6 +36,8 @@ const (
 	// LogScopeFilesystem enables logging for functions such as `path_open`.
 	// Note: This doesn't log writes to the console.
 	LogScopeFilesystem = logging.LogScopeFilesystem
+	// LogScopePoll enables logging for functions such as `poll_oneoff`.
+	LogScopePoll = logging.LogScopePoll
 	// LogScopeRandom enables logging for functions such as `random_get`.
 	LogScopeRandom = logging.LogScopeRandom
 	// LogScopeAll means all functions should be logged.
diff --git a/imports/wasi_snapshot_preview1/poll.go b/imports/wasi_snapshot_preview1/poll.go
index e3abb924..ed2cdd6e 100644
--- a/imports/wasi_snapshot_preview1/poll.go
+++ b/imports/wasi_snapshot_preview1/poll.go
@@ -30,7 +30,6 @@ import (
 // # Notes
 //
 //   - Since the `out` pointer nests Errno, the result is always ErrnoSuccess.
-//   - importPollOneoff shows this signature in the WebAssembly 1.0 Text Format.
 //   - This is similar to `poll` in POSIX.
 //
 // See https://github.com/WebAssembly/WASI/blob/snapshot-01/phases/snapshot/docs.md#poll_oneoff
diff --git a/internal/gojs/logging/logging.go b/internal/gojs/logging/logging.go
index 4bb566a2..6509a2c4 100644
--- a/internal/gojs/logging/logging.go
+++ b/internal/gojs/logging/logging.go
@@ -33,6 +33,13 @@ func IsInLogScope(fnd api.FunctionDefinition, scopes logging.LogScopes) bool {
 		}
 	}
 
+	if scopes.IsEnabled(logging.LogScopePoll) {
+		switch fnd.Name() {
+		case custom.NameRuntimeScheduleTimeoutEvent, custom.NameRuntimeClearTimeoutEvent:
+			return true
+		}
+	}
+
 	if scopes.IsEnabled(logging.LogScopeRandom) {
 		switch fnd.Name() {
 		case custom.NameRuntimeGetRandomData:
@@ -61,15 +68,32 @@ func Config(fnd api.FunctionDefinition, scopes logging.LogScopes) (pSampler logg
 	case custom.NameRuntimeWalltime:
 		// no params
 		rLoggers = []logging.ResultLogger{runtimeWalltimeResultLogger}
+	case custom.NameRuntimeScheduleTimeoutEvent:
+		pLoggers = []logging.ParamLogger{runtimeScheduleTimeoutEventParamLogger}
+		rLoggers = []logging.ResultLogger{runtimeScheduleTimeoutEventResultLogger}
+	case custom.NameRuntimeClearTimeoutEvent:
+		pLoggers = []logging.ParamLogger{runtimeClearTimeoutEventParamLogger}
+		// no results
 	default: // TODO: make generic logger for gojs
 	}
 	return
 }
 
 func runtimeGetRandomDataParamLogger(_ context.Context, mod api.Module, w logging.Writer, params []uint64) {
-	funcName := custom.NameRuntimeGetRandomData
-	paramNames := custom.NameSection[funcName].ParamNames
 	paramIdx := 1 /* there are two params, only write the length */
+	writeParameter(w, custom.NameRuntimeGetRandomData, mod, params, paramIdx)
+}
+
+func runtimeScheduleTimeoutEventParamLogger(_ context.Context, mod api.Module, w logging.Writer, params []uint64) {
+	writeParameter(w, custom.NameRuntimeScheduleTimeoutEvent, mod, params, 0)
+}
+
+func runtimeClearTimeoutEventParamLogger(_ context.Context, mod api.Module, w logging.Writer, params []uint64) {
+	writeParameter(w, custom.NameRuntimeClearTimeoutEvent, mod, params, 0)
+}
+
+func writeParameter(w logging.Writer, funcName string, mod api.Module, params []uint64, paramIdx int) {
+	paramNames := custom.NameSection[funcName].ParamNames
 
 	stack := goos.NewStack(funcName, mod.Memory(), uint32(params[0]))
 	w.WriteString(paramNames[paramIdx]) //nolint
@@ -85,6 +109,10 @@ func runtimeWalltimeResultLogger(_ context.Context, mod api.Module, w logging.Wr
 	writeResults(w, custom.NameRuntimeWalltime, mod, params, 0)
 }
 
+func runtimeScheduleTimeoutEventResultLogger(_ context.Context, mod api.Module, w logging.Writer, params, _ []uint64) {
+	writeResults(w, custom.NameRuntimeScheduleTimeoutEvent, mod, params, 1)
+}
+
 func writeResults(w logging.Writer, funcName string, mod api.Module, params []uint64, resultOffset int) {
 	stack := goos.NewStack(funcName, mod.Memory(), uint32(params[0]))
 
diff --git a/internal/gojs/runtime.go b/internal/gojs/runtime.go
index 213de99c..997f514f 100644
--- a/internal/gojs/runtime.go
+++ b/internal/gojs/runtime.go
@@ -53,7 +53,7 @@ func wasmWrite(_ context.Context, mod api.Module, stack goarch.Stack) {
 // See https://github.com/golang/go/blob/go1.19/src/runtime/mem_js.go#L82
 var ResetMemoryDataView = goarch.NewFunc(custom.NameRuntimeResetMemoryDataView, resetMemoryDataView)
 
-func resetMemoryDataView(ctx context.Context, _ api.Module, _ goarch.Stack) {
+func resetMemoryDataView(context.Context, api.Module, goarch.Stack) {
 	// context state does not cache a memory view, and all byte slices used
 	// are safely copied. Also, user-defined functions are not supported.
 	// Hence, there's currently no known reason to reset anything.
diff --git a/internal/logging/logging.go b/internal/logging/logging.go
index ed3e661c..e0145544 100644
--- a/internal/logging/logging.go
+++ b/internal/logging/logging.go
@@ -40,6 +40,7 @@ const (
 	LogScopeNone            = LogScopes(0)
 	LogScopeClock LogScopes = 1 << iota
 	LogScopeFilesystem
+	LogScopePoll
 	LogScopeRandom
 	LogScopeAll = LogScopes(0xffffffffffffffff)
 )
@@ -50,6 +51,8 @@ func scopeName(s LogScopes) string {
 		return "clock"
 	case LogScopeFilesystem:
 		return "filesystem"
+	case LogScopePoll:
+		return "poll"
 	case LogScopeRandom:
 		return "random"
 	default:
diff --git a/internal/wasi_snapshot_preview1/logging/logging.go b/internal/wasi_snapshot_preview1/logging/logging.go
index c0494f96..debfe2a2 100644
--- a/internal/wasi_snapshot_preview1/logging/logging.go
+++ b/internal/wasi_snapshot_preview1/logging/logging.go
@@ -28,6 +28,10 @@ func isFilesystemFunction(fnd api.FunctionDefinition) bool {
 	return false
 }
 
+func isPollFunction(fnd api.FunctionDefinition) bool {
+	return fnd.Name() == PollOneoffName
+}
+
 func isRandomFunction(fnd api.FunctionDefinition) bool {
 	return fnd.Name() == RandomGetName
 }
@@ -46,6 +50,12 @@ func IsInLogScope(fnd api.FunctionDefinition, scopes logging.LogScopes) bool {
 		}
 	}
 
+	if scopes.IsEnabled(logging.LogScopePoll) {
+		if isPollFunction(fnd) {
+			return true
+		}
+	}
+
 	if scopes.IsEnabled(logging.LogScopeRandom) {
 		if isRandomFunction(fnd) {
 			return true
@@ -122,7 +132,7 @@ func Config(fnd api.FunctionDefinition) (pSampler logging.ParamSampler, pLoggers
 			logger = logFsRightsBase(idx).Log
 		case "fs_rights_inheriting":
 			logger = logFsRightsInheriting(idx).Log
-		case "result.nread", "result.nwritten", "result.opened_fd":
+		case "result.nread", "result.nwritten", "result.opened_fd", "result.nevents":
 			name = resultParamName(name)
 			logger = logMemI32(idx).Log
 			rLoggers = append(rLoggers, resultParamLogger(name, logger))


Test patch:
diff --git a/cmd/wazero/wazero_test.go b/cmd/wazero/wazero_test.go
index 7c83bcad..18ff969b 100644
--- a/cmd/wazero/wazero_test.go
+++ b/cmd/wazero/wazero_test.go
@@ -552,15 +552,20 @@ func Test_logScopesFlag(t *testing.T) {
 			values:   []string{"filesystem"},
 			expected: logging.LogScopeFilesystem,
 		},
+		{
+			name:     "poll",
+			values:   []string{"poll"},
+			expected: logging.LogScopePoll,
+		},
 		{
 			name:     "random",
 			values:   []string{"random"},
 			expected: logging.LogScopeRandom,
 		},
 		{
-			name:     "clock filesystem random",
-			values:   []string{"clock", "filesystem", "random"},
-			expected: logging.LogScopeClock | logging.LogScopeFilesystem | logging.LogScopeRandom,
+			name:     "clock filesystem poll random",
+			values:   []string{"clock", "filesystem", "poll", "random"},
+			expected: logging.LogScopeClock | logging.LogScopeFilesystem | logging.LogScopePoll | logging.LogScopeRandom,
 		},
 	}
 
diff --git a/imports/wasi_snapshot_preview1/poll_test.go b/imports/wasi_snapshot_preview1/poll_test.go
index bf183574..00801336 100644
--- a/imports/wasi_snapshot_preview1/poll_test.go
+++ b/imports/wasi_snapshot_preview1/poll_test.go
@@ -42,8 +42,8 @@ func Test_pollOneoff(t *testing.T) {
 	requireErrno(t, ErrnoSuccess, mod, PollOneoffName, uint64(in), uint64(out), uint64(nsubscriptions),
 		uint64(resultNevents))
 	require.Equal(t, `
-==> wasi_snapshot_preview1.poll_oneoff(in=0,out=128,nsubscriptions=1,result.nevents=512)
-<== errno=ESUCCESS
+==> wasi_snapshot_preview1.poll_oneoff(in=0,out=128,nsubscriptions=1)
+<== (nevents=1,errno=ESUCCESS)
 `, "\n"+log.String())
 
 	outMem, ok := mod.Memory().Read(out, uint32(len(expectedMem)))
@@ -75,8 +75,8 @@ func Test_pollOneoff_Errors(t *testing.T) {
 			resultNevents:  512, // past out
 			expectedErrno:  ErrnoFault,
 			expectedLog: `
-==> wasi_snapshot_preview1.poll_oneoff(in=65536,out=128,nsubscriptions=1,result.nevents=512)
-<== errno=EFAULT
+==> wasi_snapshot_preview1.poll_oneoff(in=65536,out=128,nsubscriptions=1)
+<== (nevents=,errno=EFAULT)
 `,
 		},
 		{
@@ -86,8 +86,8 @@ func Test_pollOneoff_Errors(t *testing.T) {
 			nsubscriptions: 1,
 			expectedErrno:  ErrnoFault,
 			expectedLog: `
-==> wasi_snapshot_preview1.poll_oneoff(in=0,out=65536,nsubscriptions=1,result.nevents=512)
-<== errno=EFAULT
+==> wasi_snapshot_preview1.poll_oneoff(in=0,out=65536,nsubscriptions=1)
+<== (nevents=,errno=EFAULT)
 `,
 		},
 		{
@@ -96,8 +96,8 @@ func Test_pollOneoff_Errors(t *testing.T) {
 			nsubscriptions: 1,
 			expectedErrno:  ErrnoFault,
 			expectedLog: `
-==> wasi_snapshot_preview1.poll_oneoff(in=0,out=0,nsubscriptions=1,result.nevents=65536)
-<== errno=EFAULT
+==> wasi_snapshot_preview1.poll_oneoff(in=0,out=0,nsubscriptions=1)
+<== (nevents=,errno=EFAULT)
 `,
 		},
 		{
@@ -106,8 +106,8 @@ func Test_pollOneoff_Errors(t *testing.T) {
 			resultNevents: 512, // past out
 			expectedErrno: ErrnoInval,
 			expectedLog: `
-==> wasi_snapshot_preview1.poll_oneoff(in=0,out=128,nsubscriptions=0,result.nevents=512)
-<== errno=EINVAL
+==> wasi_snapshot_preview1.poll_oneoff(in=0,out=128,nsubscriptions=0)
+<== (nevents=,errno=EINVAL)
 `,
 		},
 		{
@@ -129,8 +129,8 @@ func Test_pollOneoff_Errors(t *testing.T) {
 				'?', // stopped after encoding
 			},
 			expectedLog: `
-==> wasi_snapshot_preview1.poll_oneoff(in=0,out=128,nsubscriptions=1,result.nevents=512)
-<== errno=ESUCCESS
+==> wasi_snapshot_preview1.poll_oneoff(in=0,out=128,nsubscriptions=1)
+<== (nevents=1,errno=ESUCCESS)
 `,
 		},
 	}
diff --git a/internal/gojs/misc_test.go b/internal/gojs/misc_test.go
index b48c1113..826b207d 100644
--- a/internal/gojs/misc_test.go
+++ b/internal/gojs/misc_test.go
@@ -2,11 +2,14 @@ package gojs_test
 
 import (
 	"bytes"
+	"context"
 	"fmt"
 	"strings"
 	"testing"
 
 	"github.com/tetratelabs/wazero"
+	"github.com/tetratelabs/wazero/experimental"
+	"github.com/tetratelabs/wazero/experimental/logging"
 	"github.com/tetratelabs/wazero/internal/testing/require"
 )
 
@@ -47,14 +50,27 @@ func Test_stdio(t *testing.T) {
 func Test_stdio_large(t *testing.T) {
 	t.Parallel()
 
+	// Large stdio will trigger GC which will trigger events.
+	var log bytes.Buffer
+	loggingCtx := context.WithValue(testCtx, experimental.FunctionListenerFactoryKey{},
+		logging.NewHostLoggingListenerFactory(&log, logging.LogScopePoll))
+
 	size := 2 * 1024 * 1024 // 2MB
 	input := make([]byte, size)
-	stdout, stderr, err := compileAndRun(testCtx, "stdio", wazero.NewModuleConfig().
+	stdout, stderr, err := compileAndRun(loggingCtx, "stdio", wazero.NewModuleConfig().
 		WithStdin(bytes.NewReader(input)))
 
 	require.EqualError(t, err, `module "" closed with exit_code(0)`)
 	require.Equal(t, fmt.Sprintf("stderr %d\n", size), stderr)
 	require.Equal(t, fmt.Sprintf("stdout %d\n", size), stdout)
+
+	// We can't predict the precise ms the timeout event will be, so we partial match.
+	require.Contains(t, log.String(), `==> go.runtime.scheduleTimeoutEvent(ms=`)
+	require.Contains(t, log.String(), `<== (id=1)`)
+	// There may be another timeout event between the first and its clear.
+	require.Contains(t, log.String(), `==> go.runtime.clearTimeoutEvent(id=1)
+<==
+`)
 }
 
 func Test_gc(t *testing.T) {
diff --git a/internal/logging/logging_test.go b/internal/logging/logging_test.go
index 74dbca64..ad693d99 100644
--- a/internal/logging/logging_test.go
+++ b/internal/logging/logging_test.go
@@ -53,6 +53,7 @@ func TestLogScopes_String(t *testing.T) {
 		{name: "any", scopes: LogScopeAll, expected: "all"},
 		{name: "clock", scopes: LogScopeClock, expected: "clock"},
 		{name: "filesystem", scopes: LogScopeFilesystem, expected: "filesystem"},
+		{name: "poll", scopes: LogScopePoll, expected: "poll"},
 		{name: "random", scopes: LogScopeRandom, expected: "random"},
 		{name: "filesystem|random", scopes: LogScopeFilesystem | LogScopeRandom, expected: "filesystem|random"},
 		{name: "undefined", scopes: 1 << 14, expected: fmt.Sprintf("<unknown=%d>", 1<<14)},
diff --git a/internal/wasi_snapshot_preview1/logging/logging_test.go b/internal/wasi_snapshot_preview1/logging/logging_test.go
index 405c666e..4b97f94e 100644
--- a/internal/wasi_snapshot_preview1/logging/logging_test.go
+++ b/internal/wasi_snapshot_preview1/logging/logging_test.go
@@ -23,6 +23,7 @@ func (f *testFunctionDefinition) Name() string {
 func TestIsInLogScope(t *testing.T) {
 	clockTimeGet := &testFunctionDefinition{name: ClockTimeGetName}
 	fdRead := &testFunctionDefinition{name: FdReadName}
+	pollOneoff := &testFunctionDefinition{name: PollOneoffName}
 	randomGet := &testFunctionDefinition{name: RandomGetName}
 	tests := []struct {
 		name     string
@@ -90,6 +91,36 @@ func TestIsInLogScope(t *testing.T) {
 			scopes:   logging.LogScopeNone,
 			expected: false,
 		},
+		{
+			name:     "pollOneoff in LogScopePoll",
+			fnd:      pollOneoff,
+			scopes:   logging.LogScopePoll,
+			expected: true,
+		},
+		{
+			name:     "pollOneoff not in LogScopeFilesystem",
+			fnd:      pollOneoff,
+			scopes:   logging.LogScopeFilesystem,
+			expected: false,
+		},
+		{
+			name:     "pollOneoff in LogScopePoll|LogScopeFilesystem",
+			fnd:      pollOneoff,
+			scopes:   logging.LogScopePoll | logging.LogScopeFilesystem,
+			expected: true,
+		},
+		{
+			name:     "pollOneoff in LogScopeAll",
+			fnd:      pollOneoff,
+			scopes:   logging.LogScopeAll,
+			expected: true,
+		},
+		{
+			name:     "pollOneoff not in LogScopeNone",
+			fnd:      pollOneoff,
+			scopes:   logging.LogScopeNone,
+			expected: false,
+		},
 		{
 			name:     "randomGet in LogScopeRandom",
 			fnd:      randomGet,