From f8a33cef8dd51956a8fd3650c2060efdf083669a Mon Sep 17 00:00:00 2001
From: Crypt Keeper <64215+codefromthecrypt@users.noreply.github.com>
Date: Wed, 4 Jan 2023 16:04:40 +0800
Subject: [PATCH] logging: avoids logging activity to stdio file descriptors
 (#1007)

This avoids logging activity on stdio file descriptors, in order to help
make troubleshooting easier. Usually, there isn't an issue in these, yet
wasm panics are harder to read if there is also logging of the ..
logging.

Signed-off-by: Adrian Cole <adrian@tetrate.io>
---
 cmd/wazero/wazero_test.go                     |  4 --
 experimental/logging/log_listener.go          |  4 +-
 imports/wasi_snapshot_preview1/fs_test.go     |  8 ++--
 internal/gojs/builtin.go                      |  4 +-
 internal/gojs/fs.go                           | 44 +++++++++----------
 internal/gojs/goos/goos.go                    | 11 +++++
 internal/gojs/http.go                         |  2 +-
 internal/gojs/logging/logging.go              | 38 ++++++----------
 internal/gojs/state.go                        | 22 +++-------
 internal/logging/logging.go                   |  2 +-
 .../wasi_snapshot_preview1/logging/logging.go | 14 +++++-
 11 files changed, 73 insertions(+), 80 deletions(-)

diff --git a/cmd/wazero/wazero_test.go b/cmd/wazero/wazero_test.go
index 743edf33..db96a847 100644
--- a/cmd/wazero/wazero_test.go
+++ b/cmd/wazero/wazero_test.go
@@ -235,8 +235,6 @@ func TestRun(t *testing.T) {
 <== (opened_fd=4,errno=ESUCCESS)
 ==> wasi_snapshot_preview1.fd_read(fd=4,iovs=1024,iovs_len=1)
 <== (nread=5,errno=ESUCCESS)
-==> wasi_snapshot_preview1.fd_write(fd=1,iovs=1024,iovs_len=1)
-<== (nwritten=5,errno=ESUCCESS)
 `,
 		},
 		{
@@ -264,8 +262,6 @@ func TestRun(t *testing.T) {
 <== (err=<nil>,n=0)
 ==> go.syscall/js.valueCall(fs.close(fd=4))
 <== (err=<nil>,ok=true)
-==> go.syscall/js.valueCall(fs.write(fd=1,offset=0,byteCount=5,fOffset=<nil>))
-<== (err=<nil>,n=5)
 `, bearMode, bearMtime),
 		},
 		{
diff --git a/experimental/logging/log_listener.go b/experimental/logging/log_listener.go
index 304bfc8e..e8cf77ae 100644
--- a/experimental/logging/log_listener.go
+++ b/experimental/logging/log_listener.go
@@ -82,7 +82,7 @@ func (f *loggingListenerFactory) NewListener(fnd api.FunctionDefinition) experim
 		if f.fsOnly && !wasilogging.IsFilesystemFunction(fnd) {
 			return nil
 		}
-		pLoggers, rLoggers = wasilogging.Config(fnd)
+		pSampler, pLoggers, rLoggers = wasilogging.Config(fnd)
 	case "go":
 		// TODO: Now, gojs logging is filesystem only, but will need to be
 		// updated later.
@@ -94,7 +94,7 @@ func (f *loggingListenerFactory) NewListener(fnd api.FunctionDefinition) experim
 		if f.fsOnly {
 			return nil
 		}
-		pLoggers, rLoggers = logging.ValueLoggers(fnd)
+		pLoggers, rLoggers = logging.Config(fnd)
 	}
 
 	var before, after string
diff --git a/imports/wasi_snapshot_preview1/fs_test.go b/imports/wasi_snapshot_preview1/fs_test.go
index 68288c4b..bcdc502f 100644
--- a/imports/wasi_snapshot_preview1/fs_test.go
+++ b/imports/wasi_snapshot_preview1/fs_test.go
@@ -1759,12 +1759,10 @@ func Test_fdWrite_discard(t *testing.T) {
 	ok := mod.Memory().Write(0, initialMemory)
 	require.True(t, ok)
 
-	fd := 1 // stdout
+	fd := sys.FdStdout
 	requireErrno(t, ErrnoSuccess, mod, FdWriteName, uint64(fd), uint64(iovs), uint64(iovsCount), uint64(resultNwritten))
-	require.Equal(t, `
-==> wasi_snapshot_preview1.fd_write(fd=1,iovs=1,iovs_len=2)
-<== (nwritten=6,errno=ESUCCESS)
-`, "\n"+log.String())
+	// Should not amplify logging
+	require.Zero(t, len(log.Bytes()))
 
 	actual, ok := mod.Memory().Read(0, uint32(len(expectedMemory)))
 	require.True(t, ok)
diff --git a/internal/gojs/builtin.go b/internal/gojs/builtin.go
index ae683fd5..a19e3845 100644
--- a/internal/gojs/builtin.go
+++ b/internal/gojs/builtin.go
@@ -8,7 +8,7 @@ import (
 
 // newJsGlobal = js.Global() // js.go init
 func newJsGlobal(rt http.RoundTripper) *jsVal {
-	var fetchProperty interface{} = undefined
+	var fetchProperty interface{} = goos.Undefined
 	if rt != nil {
 		fetchProperty = goos.RefHttpFetch
 	}
@@ -19,7 +19,7 @@ func newJsGlobal(rt http.RoundTripper) *jsVal {
 			"crypto":          jsCrypto,
 			"Uint8Array":      uint8ArrayConstructor,
 			"fetch":           fetchProperty,
-			"AbortController": undefined,
+			"AbortController": goos.Undefined,
 			"Headers":         headersConstructor,
 			"process":         jsProcess,
 			"fs":              jsfs,
diff --git a/internal/gojs/fs.go b/internal/gojs/fs.go
index 8c9bfb25..ac701e56 100644
--- a/internal/gojs/fs.go
+++ b/internal/gojs/fs.go
@@ -90,7 +90,7 @@ type jsfsOpen struct{}
 func (jsfsOpen) invoke(ctx context.Context, mod api.Module, args ...interface{}) (interface{}, error) {
 	path := args[0].(string)
 	flags := toUint64(args[1]) // flags are derived from constants like oWRONLY
-	perm := toUint32(args[2])
+	perm := goos.ValueToUint32(args[2])
 	callback := args[3].(funcWrapper)
 
 	fsc := mod.(*wasm.CallContext).Sys.FS()
@@ -146,7 +146,7 @@ type jsfsFstat struct{}
 func (jsfsFstat) invoke(ctx context.Context, mod api.Module, args ...interface{}) (interface{}, error) {
 	fsc := mod.(*wasm.CallContext).Sys.FS()
 
-	fd := toUint32(args[0])
+	fd := goos.ValueToUint32(args[0])
 	callback := args[1].(funcWrapper)
 
 	fstat, err := syscallFstat(fsc, fd)
@@ -231,7 +231,7 @@ type jsfsClose struct{}
 func (jsfsClose) invoke(ctx context.Context, mod api.Module, args ...interface{}) (interface{}, error) {
 	fsc := mod.(*wasm.CallContext).Sys.FS()
 
-	fd := toUint32(args[0])
+	fd := goos.ValueToUint32(args[0])
 	callback := args[1].(funcWrapper)
 
 	err := fsc.CloseFile(fd)
@@ -246,13 +246,13 @@ func (jsfsClose) invoke(ctx context.Context, mod api.Module, args ...interface{}
 type jsfsRead struct{}
 
 func (jsfsRead) invoke(ctx context.Context, mod api.Module, args ...interface{}) (interface{}, error) {
-	fd := toUint32(args[0])
+	fd := goos.ValueToUint32(args[0])
 	buf, ok := args[1].(*byteArray)
 	if !ok {
 		return nil, fmt.Errorf("arg[1] is %v not a []byte", args[1])
 	}
-	offset := toUint32(args[2])
-	byteCount := toUint32(args[3])
+	offset := goos.ValueToUint32(args[2])
+	byteCount := goos.ValueToUint32(args[3])
 	fOffset := args[4] // nil unless Pread
 	callback := args[5].(funcWrapper)
 
@@ -297,13 +297,13 @@ func syscallRead(mod api.Module, fd uint32, offset interface{}, p []byte) (n uin
 type jsfsWrite struct{}
 
 func (jsfsWrite) invoke(ctx context.Context, mod api.Module, args ...interface{}) (interface{}, error) {
-	fd := toUint32(args[0])
+	fd := goos.ValueToUint32(args[0])
 	buf, ok := args[1].(*byteArray)
 	if !ok {
 		return nil, fmt.Errorf("arg[1] is %v not a []byte", args[1])
 	}
-	offset := toUint32(args[2])
-	byteCount := toUint32(args[3])
+	offset := goos.ValueToUint32(args[2])
+	byteCount := goos.ValueToUint32(args[3])
 	fOffset := args[4] // nil unless Pread
 	callback := args[5].(funcWrapper)
 
@@ -418,7 +418,7 @@ type jsfsMkdir struct{}
 
 func (jsfsMkdir) invoke(ctx context.Context, mod api.Module, args ...interface{}) (interface{}, error) {
 	path := args[0].(string)
-	perm := toUint32(args[1])
+	perm := goos.ValueToUint32(args[1])
 	callback := args[2].(funcWrapper)
 
 	fsc := mod.(*wasm.CallContext).Sys.FS()
@@ -502,7 +502,7 @@ type jsfsChmod struct{}
 
 func (jsfsChmod) invoke(ctx context.Context, mod api.Module, args ...interface{}) (interface{}, error) {
 	path := args[0].(string)
-	mode := toUint32(args[1])
+	mode := goos.ValueToUint32(args[1])
 	callback := args[2].(funcWrapper)
 
 	_, _ = path, mode // TODO
@@ -517,8 +517,8 @@ func (jsfsChmod) invoke(ctx context.Context, mod api.Module, args ...interface{}
 type jsfsFchmod struct{}
 
 func (jsfsFchmod) invoke(ctx context.Context, mod api.Module, args ...interface{}) (interface{}, error) {
-	fd := toUint32(args[0])
-	mode := toUint32(args[1])
+	fd := goos.ValueToUint32(args[0])
+	mode := goos.ValueToUint32(args[1])
 	callback := args[2].(funcWrapper)
 
 	_, _ = fd, mode // TODO
@@ -534,8 +534,8 @@ type jsfsChown struct{}
 
 func (jsfsChown) invoke(ctx context.Context, mod api.Module, args ...interface{}) (interface{}, error) {
 	path := args[0].(string)
-	uid := toUint32(args[1])
-	gid := toUint32(args[2])
+	uid := goos.ValueToUint32(args[1])
+	gid := goos.ValueToUint32(args[2])
 	callback := args[3].(funcWrapper)
 
 	_, _, _ = path, uid, gid // TODO
@@ -550,9 +550,9 @@ func (jsfsChown) invoke(ctx context.Context, mod api.Module, args ...interface{}
 type jsfsFchown struct{}
 
 func (jsfsFchown) invoke(ctx context.Context, mod api.Module, args ...interface{}) (interface{}, error) {
-	fd := toUint32(args[0])
-	uid := toUint32(args[1])
-	gid := toUint32(args[2])
+	fd := goos.ValueToUint32(args[0])
+	uid := goos.ValueToUint32(args[1])
+	gid := goos.ValueToUint32(args[2])
 	callback := args[3].(funcWrapper)
 
 	_, _, _ = fd, uid, gid // TODO
@@ -568,8 +568,8 @@ type jsfsLchown struct{}
 
 func (jsfsLchown) invoke(ctx context.Context, mod api.Module, args ...interface{}) (interface{}, error) {
 	path := args[0].(string)
-	uid := toUint32(args[1])
-	gid := toUint32(args[2])
+	uid := goos.ValueToUint32(args[1])
+	gid := goos.ValueToUint32(args[2])
 	callback := args[3].(funcWrapper)
 
 	_, _, _ = path, uid, gid // TODO
@@ -600,7 +600,7 @@ func (jsfsTruncate) invoke(ctx context.Context, mod api.Module, args ...interfac
 type jsfsFtruncate struct{}
 
 func (jsfsFtruncate) invoke(ctx context.Context, mod api.Module, args ...interface{}) (interface{}, error) {
-	fd := toUint32(args[0])
+	fd := goos.ValueToUint32(args[0])
 	length := toInt64(args[1])
 	callback := args[2].(funcWrapper)
 
@@ -664,7 +664,7 @@ func (jsfsSymlink) invoke(ctx context.Context, mod api.Module, args ...interface
 type jsfsFsync struct{}
 
 func (jsfsFsync) invoke(ctx context.Context, mod api.Module, args ...interface{}) (interface{}, error) {
-	fd := toUint32(args[0])
+	fd := goos.ValueToUint32(args[0])
 	callback := args[1].(funcWrapper)
 
 	_ = fd // TODO
diff --git a/internal/gojs/goos/goos.go b/internal/gojs/goos/goos.go
index 849af5f6..1adc7f11 100644
--- a/internal/gojs/goos/goos.go
+++ b/internal/gojs/goos/goos.go
@@ -251,3 +251,14 @@ func (f *stackFunc) Call(ctx context.Context, mod api.Module, wasmStack []uint64
 func NewStack(name string, mem api.Memory, sp uint32) *stack {
 	return &stack{goarch.NewStack(name, mem, sp)}
 }
+
+var Undefined = struct{ name string }{name: "undefined"}
+
+func ValueToUint32(arg interface{}) uint32 {
+	if arg == RefValueZero || arg == Undefined {
+		return 0
+	} else if u, ok := arg.(uint32); ok {
+		return u
+	}
+	return uint32(arg.(float64))
+}
diff --git a/internal/gojs/http.go b/internal/gojs/http.go
index 3a835651..3c5d65cd 100644
--- a/internal/gojs/http.go
+++ b/internal/gojs/http.go
@@ -89,7 +89,7 @@ func (s *fetchResult) get(_ context.Context, propertyKey string) interface{} {
 		return h
 	case "body":
 		// return undefined as arrayPromise is more complicated than an array.
-		return undefined
+		return goos.Undefined
 	case "status":
 		return uint32(s.res.StatusCode)
 	}
diff --git a/internal/gojs/logging/logging.go b/internal/gojs/logging/logging.go
index 20efd7fd..9ddfa413 100644
--- a/internal/gojs/logging/logging.go
+++ b/internal/gojs/logging/logging.go
@@ -5,7 +5,6 @@ import (
 	"fmt"
 	"io/fs"
 	"os"
-	"strconv"
 
 	"github.com/tetratelabs/wazero/api"
 	"github.com/tetratelabs/wazero/internal/gojs"
@@ -13,12 +12,12 @@ import (
 	"github.com/tetratelabs/wazero/internal/gojs/goarch"
 	"github.com/tetratelabs/wazero/internal/gojs/goos"
 	"github.com/tetratelabs/wazero/internal/logging"
+	"github.com/tetratelabs/wazero/internal/sys"
 )
 
 func Config(fnd api.FunctionDefinition) (pSampler logging.ParamSampler, pLoggers []logging.ParamLogger, rLoggers []logging.ResultLogger) {
 	switch fnd.Name() {
-	case custom.NameRuntimeWasmWrite:
-		pLoggers = []logging.ParamLogger{runtimeWasmWriteParamLogger}
+	// Don't log NameRuntimeWasmWrite as it is used in panics
 	case custom.NameSyscallValueCall:
 		pSampler = syscallValueCallParamSampler
 		pLoggers = []logging.ParamLogger{syscallValueCallParamLogger}
@@ -28,21 +27,6 @@ func Config(fnd api.FunctionDefinition) (pSampler logging.ParamSampler, pLoggers
 	return
 }
 
-func runtimeWasmWriteParamLogger(_ context.Context, mod api.Module, w logging.Writer, params []uint64) {
-	mem := mod.Memory()
-	funcName := custom.NameSyscallValueCall
-	stack := goos.NewStack(funcName, mem, uint32(params[0]))
-	fd := stack.ParamUint32(0)
-	pLen := stack.ParamUint32(2)
-
-	w.WriteString(funcName) //nolint
-	w.WriteString("(fd=")   //nolint
-	writeI32(w, fd)
-	w.WriteString(",p_len=") //nolint
-	writeI32(w, pLen)
-	w.WriteByte(')') //nolint
-}
-
 func syscallValueCallParamLogger(ctx context.Context, mod api.Module, w logging.Writer, params []uint64) {
 	vRef, m, args := syscallValueCallParams(ctx, mod, params)
 
@@ -73,10 +57,20 @@ func syscallValueCallParamLogger(ctx context.Context, mod api.Module, w logging.
 }
 
 func syscallValueCallParamSampler(ctx context.Context, mod api.Module, params []uint64) bool {
-	vRef, _, _ := syscallValueCallParams(ctx, mod, params)
+	vRef, m, args := syscallValueCallParams(ctx, mod, params)
 
 	// TODO: add more than just filesystem
-	return vRef == goos.RefJsfs
+	if vRef != goos.RefJsfs {
+		return false
+	}
+
+	// Don't amplify logs with stdio reads or writes
+	switch m {
+	case custom.NameFsWrite, custom.NameFsRead:
+		fd := goos.ValueToUint32(args[0])
+		return fd > sys.FdStderr
+	}
+	return true
 }
 
 func syscallValueCallParams(ctx context.Context, mod api.Module, params []uint64) (goos.Ref, string, []interface{}) {
@@ -168,7 +162,3 @@ var oflagToString = [...]string{
 	"SYNC",
 	"TRUNC",
 }
-
-func writeI32(w logging.Writer, v uint32) {
-	w.WriteString(strconv.FormatInt(int64(int32(v)), 10)) //nolint
-}
diff --git a/internal/gojs/state.go b/internal/gojs/state.go
index 24b06fa6..cbbcdf87 100644
--- a/internal/gojs/state.go
+++ b/internal/gojs/state.go
@@ -57,10 +57,7 @@ func (e *event) get(_ context.Context, propertyKey string) interface{} {
 	panic(fmt.Sprintf("TODO: event.%s", propertyKey))
 }
 
-var (
-	undefined = struct{ name string }{name: "undefined"}
-	NaN       = math.NaN()
-)
+var NaN = math.NaN()
 
 // LoadValue reads up to 8 bytes at the memory offset `addr` to return the
 // value written by storeValue.
@@ -69,7 +66,7 @@ var (
 func LoadValue(ctx context.Context, ref goos.Ref) interface{} { //nolint
 	switch ref {
 	case 0:
-		return undefined
+		return goos.Undefined
 	case goos.RefValueNaN:
 		return NaN
 	case goos.RefValueZero:
@@ -119,7 +116,7 @@ func LoadValue(ctx context.Context, ref goos.Ref) interface{} { //nolint
 // See https://github.com/golang/go/blob/go1.19/misc/wasm/wasm_exec.js#L135-L183
 func storeRef(ctx context.Context, v interface{}) goos.Ref { //nolint
 	// allow-list because we control all implementations
-	if v == undefined {
+	if v == goos.Undefined {
 		return goos.RefValueUndefined
 	} else if v == nil {
 		return goos.RefValueNull
@@ -271,7 +268,7 @@ func (s *State) close() {
 }
 
 func toInt64(arg interface{}) int64 {
-	if arg == goos.RefValueZero || arg == undefined {
+	if arg == goos.RefValueZero || arg == goos.Undefined {
 		return 0
 	} else if u, ok := arg.(int64); ok {
 		return u
@@ -280,7 +277,7 @@ func toInt64(arg interface{}) int64 {
 }
 
 func toUint64(arg interface{}) uint64 {
-	if arg == goos.RefValueZero || arg == undefined {
+	if arg == goos.RefValueZero || arg == goos.Undefined {
 		return 0
 	} else if u, ok := arg.(uint64); ok {
 		return u
@@ -288,15 +285,6 @@ func toUint64(arg interface{}) uint64 {
 	return uint64(arg.(float64))
 }
 
-func toUint32(arg interface{}) uint32 {
-	if arg == goos.RefValueZero || arg == undefined {
-		return 0
-	} else if u, ok := arg.(uint32); ok {
-		return u
-	}
-	return uint32(arg.(float64))
-}
-
 // valueString returns the string form of JavaScript string, boolean and number types.
 func valueString(v interface{}) string { //nolint
 	if s, ok := v.(string); ok {
diff --git a/internal/logging/logging.go b/internal/logging/logging.go
index 20341055..28aad9ab 100644
--- a/internal/logging/logging.go
+++ b/internal/logging/logging.go
@@ -53,7 +53,7 @@ type Writer interface {
 // ValueTypeString, it would read `vals[i+1]` and write the string from memory.
 type ValWriter func(ctx context.Context, mod api.Module, w Writer, i uint32, vals []uint64)
 
-func ValueLoggers(fnd api.FunctionDefinition) (paramLoggers []ParamLogger, resultLoggers []ResultLogger) {
+func Config(fnd api.FunctionDefinition) (paramLoggers []ParamLogger, resultLoggers []ResultLogger) {
 	if paramLen := uint32(len(fnd.ParamTypes())); paramLen > 0 {
 		paramLoggers = make([]ParamLogger, paramLen)
 		hasParamNames := len(fnd.ParamNames()) > 0
diff --git a/internal/wasi_snapshot_preview1/logging/logging.go b/internal/wasi_snapshot_preview1/logging/logging.go
index c7c49b25..de5d1372 100644
--- a/internal/wasi_snapshot_preview1/logging/logging.go
+++ b/internal/wasi_snapshot_preview1/logging/logging.go
@@ -8,6 +8,7 @@ import (
 
 	"github.com/tetratelabs/wazero/api"
 	"github.com/tetratelabs/wazero/internal/logging"
+	"github.com/tetratelabs/wazero/internal/sys"
 	. "github.com/tetratelabs/wazero/internal/wasi_snapshot_preview1"
 )
 
@@ -23,14 +24,17 @@ func IsFilesystemFunction(fnd api.FunctionDefinition) bool {
 	return false
 }
 
-func Config(fnd api.FunctionDefinition) (pLoggers []logging.ParamLogger, rLoggers []logging.ResultLogger) {
+func Config(fnd api.FunctionDefinition) (pSampler logging.ParamSampler, pLoggers []logging.ParamLogger, rLoggers []logging.ResultLogger) {
 	switch fnd.Name() {
 	case FdPrestatGetName:
 		pLoggers = []logging.ParamLogger{logging.NewParamLogger(0, "fd", logging.ValueTypeI32)}
 		rLoggers = []logging.ResultLogger{resultParamLogger("prestat", logPrestat(1).Log), logErrno}
 		return
 	case ProcExitName:
-		return logging.ValueLoggers(fnd)
+		pLoggers, rLoggers = logging.Config(fnd)
+		return
+	case FdReadName, FdWriteName:
+		pSampler = fdReadWriteSampler
 	}
 
 	for idx := uint32(0); idx < uint32(len(fnd.ParamTypes())); idx++ {
@@ -92,6 +96,12 @@ func Config(fnd api.FunctionDefinition) (pLoggers []logging.ParamLogger, rLogger
 	return
 }
 
+// Ensure we don't clutter log with reads and writes to stdio.
+func fdReadWriteSampler(_ context.Context, _ api.Module, params []uint64) bool {
+	fd := uint32(params[0])
+	return fd > sys.FdStderr
+}
+
 func isLookupFlags(fnd api.FunctionDefinition, name string) bool {
 	switch fnd.Name() {
 	case PathFilestatGetName, PathFilestatSetTimesName: