Repository: tetratelabs/wazero
Pull request #938 (2022-12-16 08:05:50)

logging: extracts utilities to read parameters and results from memory
This changes the listener signature to accept context and calling
module, so that all possible parameters and results can be logged. This
also changes the logging listener to make parameters visible when
logging results.

This infrastructure supports some helpful use cases, such as logging
WASI result parameters, such as the prestat path, which is only knowable
after the function has been called. The context parameter supposed
reading results of gojs functions, which are stored host-side in a go
context object.

Future pull requests will complete this as well backfill unit tests.
This is raised independently mainly to keep the PR size down of the
upcoming filesystem logger.

codefromthecrypt: closing this for now as completing it displaces a lot of time needed for other things.
codefromthecrypt: next step: flag certain fields as logging.ValueTypeString, so that their natural values print out.
codefromthecrypt: will continue this until we have a logging enum working for "filesystem" ABIs

ex. the below isn't synced to the branch yet:

WASI
```
--> ._start.command_export()
        	==> wasi_snapshot_preview1.environ_sizes_get()
        	<== (environc=0,environv_len=0,errno=ESUCCESS)
        	==> wasi_snapshot_preview1.fd_prestat_get(fd=3)
        	<== (prestat=0000000001000000,errno=ESUCCESS)
        	==> wasi_snapshot_preview1.fd_prestat_dir_name(fd=3)
        	<== (path=/,errno=ESUCCESS)
        	==> wasi_snapshot_preview1.fd_prestat_get(fd=4)
        	<== (prestat=0000000001000000,errno=EBADF)
--snip--
```

GOOS=js (much harder to do as values aren't easy to get to and also involves sampling)
```
 ==> go.syscall/js.valueCall(method=open)
        	> (name=sub/.,flags=0,perm=0)
        	< (fd=4)
        <==
        ==> go.syscall/js.valueCall(method=fstat)
        	> (fd=4)
        	< (isDir=true,mode=2147483648,size=0,mtimeMs=3990038528)
        <==
        ==> go.syscall/js.valueCall(method=readdir)
        	> (name=sub/.)
        	< (dirents=1)
        <==
        ==> go.syscall/js.valueCall(method=cwd)
        	< (cwd=/)
        <==
        ==> go.syscall/js.valueCall(method=lstat)
        	> (name=sub/./test.txt)
        	< (isDir=false,mode=0,size=14,mtimeMs=3990038528)
```

Patch:
diff --git a/experimental/listener.go b/experimental/listener.go
index c7e5c571..df1e1603 100644
--- a/experimental/listener.go
+++ b/experimental/listener.go
@@ -17,6 +17,9 @@ type FunctionListenerFactory interface {
 	// NewListener returns a FunctionListener for a defined function. If nil is
 	// returned, no listener will be notified.
 	NewListener(api.FunctionDefinition) FunctionListener
+	// ^^ A single instance can be returned to avoid instantiating a listener
+	// per function, especially as they may be thousands of functions. Shared
+	// listeners use their FunctionDefinition parameter to clarify.
 }
 
 // FunctionListener can be registered for any function via
@@ -29,19 +32,25 @@ type FunctionListener interface {
 	//
 	//   - ctx: the context of the caller function which must be the same
 	//	   instance or parent of the result.
+	//   - mod: the calling module.
 	//   - def: the function definition.
 	//   - paramValues:  api.ValueType encoded parameters.
-	Before(ctx context.Context, def api.FunctionDefinition, paramValues []uint64) context.Context
+	//
+	// Note: api.Memory is meant for inspection, not modification.
+	Before(ctx context.Context, mod api.Module, def api.FunctionDefinition, paramValues []uint64) context.Context
 
 	// After is invoked after a function is called.
 	//
 	// # Params
 	//
 	//   - ctx: the context returned by Before.
+	//   - mod: the calling module.
 	//   - def: the function definition.
 	//   - err: nil if the function didn't err
 	//   - resultValues: api.ValueType encoded results.
-	After(ctx context.Context, def api.FunctionDefinition, err error, resultValues []uint64)
+	//
+	// Note: api.Memory is meant for inspection, not modification.
+	After(ctx context.Context, mod api.Module, def api.FunctionDefinition, err error, resultValues []uint64)
 }
 
 // TODO: We need to add tests to enginetest to ensure contexts nest. A good test can use a combination of call and call
diff --git a/experimental/logging/log_listener.go b/experimental/logging/log_listener.go
index 9b707b55..08d7a37d 100644
--- a/experimental/logging/log_listener.go
+++ b/experimental/logging/log_listener.go
@@ -1,23 +1,27 @@
 package logging
 
 import (
+	"bufio"
 	"context"
-	"fmt"
 	"io"
-	"strconv"
-	"strings"
 
 	"github.com/tetratelabs/wazero/api"
 	"github.com/tetratelabs/wazero/experimental"
+	"github.com/tetratelabs/wazero/internal/logging"
 	"github.com/tetratelabs/wazero/internal/wasi_snapshot_preview1"
 )
 
+type Writer interface {
+	io.Writer
+	io.StringWriter
+}
+
 // NewLoggingListenerFactory is an experimental.FunctionListenerFactory that
 // logs all functions that have a name to the writer.
 //
 // Use NewHostLoggingListenerFactory if only interested in host interactions.
-func NewLoggingListenerFactory(writer io.Writer) experimental.FunctionListenerFactory {
-	return &loggingListenerFactory{writer: writer}
+func NewLoggingListenerFactory(w Writer) experimental.FunctionListenerFactory {
+	return &loggingListenerFactory{w: toInternalWriter(w)}
 }
 
 // NewHostLoggingListenerFactory is an experimental.FunctionListenerFactory
@@ -27,17 +31,28 @@ func NewLoggingListenerFactory(writer io.Writer) experimental.FunctionListenerFa
 // guest defined functions such as those implementing garbage collection.
 //
 // For example, "_start" is defined by the guest, but exported, so would be
-// written to the writer in order to provide minimal context needed to
-// understand host calls such as "fd_open".
-func NewHostLoggingListenerFactory(writer io.Writer) experimental.FunctionListenerFactory {
-	return &loggingListenerFactory{writer: writer, hostOnly: true}
+// written to the w in order to provide minimal context needed to
+// understand host calls such as "args_get".
+func NewHostLoggingListenerFactory(w Writer) experimental.FunctionListenerFactory {
+	return &loggingListenerFactory{w: toInternalWriter(w), hostOnly: true}
+}
+
+func toInternalWriter(w Writer) logging.Writer {
+	if w, ok := w.(logging.Writer); ok {
+		return w
+	}
+	return bufio.NewWriter(w)
 }
 
 type loggingListenerFactory struct {
-	writer   io.Writer
+	w        logging.Writer
 	hostOnly bool
 }
 
+type flusher interface {
+	Flush() error
+}
+
 // NewListener implements the same method as documented on
 // experimental.FunctionListener.
 func (f *loggingListenerFactory) NewListener(fnd api.FunctionDefinition) experimental.FunctionListener {
@@ -48,162 +63,135 @@ func (f *loggingListenerFactory) NewListener(fnd api.FunctionDefinition) experim
 		return nil
 	}
 
-	// special-case formatting of WASI error number until there's a generic way
-	// to stringify parameters or results.
-	wasiErrnoPos := -1
-	if fnd.ModuleName() == "wasi_snapshot_preview1" {
-		for i, n := range fnd.ResultNames() {
-			if n == "errno" {
-				wasiErrnoPos = i
-			}
-		}
+	var pLoggers []logging.ParamLogger
+	var rLoggers []logging.ResultLogger
+	switch fnd.ModuleName() {
+	case wasi_snapshot_preview1.ModuleName:
+		pLoggers, rLoggers = wasi_snapshot_preview1.ValueLoggers(fnd)
+	default:
+		pLoggers, rLoggers = logging.ValueLoggers(fnd)
+	}
+
+	var before, after string
+	if fnd.GoFunction() != nil {
+		before = "==> " + fnd.DebugName()
+		after = "<=="
+	} else {
+		before = "--> " + fnd.DebugName()
+		after = "<--"
+	}
+	return &loggingListener{
+		w:            f.w,
+		beforePrefix: before,
+		afterPrefix:  after,
+		pLoggers:     pLoggers,
+		rLoggers:     rLoggers,
 	}
-	return &loggingListener{writer: f.writer, fnd: fnd, wasiErrnoPos: wasiErrnoPos}
 }
 
-// nestLevelKey holds state between logger.Before and loggingListener.After to ensure
-// call depth is reflected.
-type nestLevelKey struct{}
+// logState saves a copy of params between calls as the slice underlying them
+// is a stack reused for results.
+type logState struct {
+	w         logging.Writer
+	nestLevel int
+	params    []uint64
+}
 
-// loggingListener implements experimental.FunctionListener to log entrance and exit
+// loggingListener implements experimental.FunctionListener to log entrance and after
 // of each function call.
 type loggingListener struct {
-	writer io.Writer
-	fnd    api.FunctionDefinition
-
-	// wasiErrnoPos is the result index of wasi_snapshot_preview1.Errno or -1.
-	wasiErrnoPos int
+	w                         logging.Writer
+	beforePrefix, afterPrefix string
+	pLoggers                  []logging.ParamLogger
+	rLoggers                  []logging.ResultLogger
 }
 
 // Before logs to stdout the module and function name, prefixed with '-->' and
 // indented based on the call nesting level.
-func (l *loggingListener) Before(ctx context.Context, _ api.FunctionDefinition, vals []uint64) context.Context {
-	nestLevel, _ := ctx.Value(nestLevelKey{}).(int)
+func (l *loggingListener) Before(ctx context.Context, mod api.Module, _ api.FunctionDefinition, params []uint64) context.Context {
+	var nestLevel int
+	if ls := ctx.Value(logging.LoggerKey{}); ls != nil {
+		nestLevel = ls.(*logState).nestLevel
+	}
+	nestLevel++
+
+	l.logIndented(ctx, mod, nestLevel, true, params, nil, nil)
 
-	l.writeIndented(true, nil, vals, nestLevel+1)
+	ls := &logState{w: l.w, nestLevel: nestLevel}
+	if pLen := len(params); pLen > 0 {
+		ls.params = make([]uint64, pLen)
+		copy(ls.params, params) // safe copy
+	} else { // empty
+		ls.params = params
+	}
 
 	// Increase the next nesting level.
-	return context.WithValue(ctx, nestLevelKey{}, nestLevel+1)
+	return context.WithValue(ctx, logging.LoggerKey{}, ls)
 }
 
 // After logs to stdout the module and function name, prefixed with '<--' and
 // indented based on the call nesting level.
-func (l *loggingListener) After(ctx context.Context, _ api.FunctionDefinition, err error, vals []uint64) {
+func (l *loggingListener) After(ctx context.Context, mod api.Module, _ api.FunctionDefinition, err error, results []uint64) {
 	// Note: We use the nest level directly even though it is the "next" nesting level.
 	// This works because our indent of zero nesting is one tab.
-	l.writeIndented(false, err, vals, ctx.Value(nestLevelKey{}).(int))
+	if state, ok := ctx.Value(logging.LoggerKey{}).(*logState); ok {
+		l.logIndented(ctx, mod, state.nestLevel, false, state.params, err, results)
+	}
 }
 
-// writeIndented writes an indented message like this: "-->\t\t\t$indentLevel$funcName\n"
-func (l *loggingListener) writeIndented(before bool, err error, vals []uint64, indentLevel int) {
-	var message strings.Builder
-	for i := 1; i < indentLevel; i++ {
-		message.WriteByte('\t')
+// logIndented logs an indented l.w like this: "-->\t\t\t$nestLevel$funcName\n"
+func (l *loggingListener) logIndented(ctx context.Context, mod api.Module, nestLevel int, isBefore bool, params []uint64, err error, results []uint64) {
+	for i := 1; i < nestLevel; i++ {
+		l.w.WriteByte('\t') // nolint
 	}
-	if before {
-		if l.fnd.GoFunction() != nil {
-			message.WriteString("==> ")
-		} else {
-			message.WriteString("--> ")
-		}
-		l.writeFuncEnter(&message, vals)
+	if isBefore { // before
+		l.w.WriteString(l.beforePrefix) // nolint
+		l.logParams(ctx, mod, params)
 	} else { // after
-		if l.fnd.GoFunction() != nil {
-			message.WriteString("<==")
+		l.w.WriteString(l.afterPrefix) // nolint
+		if err != nil {
+			l.w.WriteString(" error: ")  // nolint
+			l.w.WriteString(err.Error()) // nolint
 		} else {
-			message.WriteString("<--")
+			l.logResults(ctx, mod, params, results)
 		}
-		l.writeFuncExit(&message, err, vals)
 	}
-	message.WriteByte('\n')
+	l.w.WriteByte('\n') // nolint
 
-	_, _ = l.writer.Write([]byte(message.String()))
+	if f, ok := l.w.(flusher); ok {
+		f.Flush() // nolint
+	}
 }
 
-func (l *loggingListener) writeFuncEnter(message *strings.Builder, vals []uint64) {
-	valLen := len(vals)
-	message.WriteString(l.fnd.DebugName())
-	message.WriteByte('(')
-	switch valLen {
-	case 0:
-	default:
-		i := l.writeParam(message, 0, vals)
-		for i < valLen {
-			message.WriteByte(',')
-			i = l.writeParam(message, i, vals)
+func (l *loggingListener) logParams(ctx context.Context, mod api.Module, params []uint64) {
+	paramLen := len(l.pLoggers)
+	l.w.WriteByte('(') // nolint
+	if paramLen > 0 {
+		l.pLoggers[0](ctx, mod, l.w, params)
+		for i := 1; i < paramLen; i++ {
+			l.w.WriteByte(',') // nolint
+			l.pLoggers[i](ctx, mod, l.w, params)
 		}
 	}
-	message.WriteByte(')')
+	l.w.WriteByte(')') // nolint
 }
 
-func (l *loggingListener) writeFuncExit(message *strings.Builder, err error, vals []uint64) {
-	if err != nil {
-		message.WriteString(" error: ")
-		message.WriteString(err.Error())
+func (l *loggingListener) logResults(ctx context.Context, mod api.Module, params, results []uint64) {
+	resultLen := len(l.rLoggers)
+	if resultLen == 0 {
 		return
 	}
-	valLen := len(vals)
-	if valLen == 0 {
-		return
-	}
-	message.WriteByte(' ')
-	switch valLen {
+	l.w.WriteByte(' ') // nolint
+	switch resultLen {
 	case 1:
-		l.writeResult(message, 0, vals)
+		l.rLoggers[0](ctx, mod, l.w, params, results)
 	default:
-		message.WriteByte('(')
-		i := l.writeResult(message, 0, vals)
-		for i < valLen {
-			message.WriteByte(',')
-			i = l.writeResult(message, i, vals)
+		l.w.WriteByte('(') // nolint
+		l.rLoggers[0](ctx, mod, l.w, params, results)
+		for i := 1; i < resultLen; i++ {
+			l.w.WriteByte(',') // nolint
+			l.rLoggers[i](ctx, mod, l.w, params, results)
 		}
-		message.WriteByte(')')
-	}
-}
-
-func (l *loggingListener) writeResult(message *strings.Builder, i int, vals []uint64) int {
-	if i == l.wasiErrnoPos {
-		message.WriteString(wasi_snapshot_preview1.ErrnoName(uint32(vals[i])))
-		return i + 1
-	}
-
-	if len(l.fnd.ResultNames()) > 0 {
-		message.WriteString(l.fnd.ResultNames()[i])
-		message.WriteByte('=')
-	}
-
-	return l.writeVal(message, l.fnd.ResultTypes()[i], i, vals)
-}
-
-func (l *loggingListener) writeParam(message *strings.Builder, i int, vals []uint64) int {
-	if len(l.fnd.ParamNames()) > 0 {
-		message.WriteString(l.fnd.ParamNames()[i])
-		message.WriteByte('=')
-	}
-	return l.writeVal(message, l.fnd.ParamTypes()[i], i, vals)
-}
-
-// writeVal formats integers as signed even though the call site determines
-// if it is signed or not. This presents a better experience for values that
-// are often signed, such as seek offset. This concedes the rare intentional
-// unsigned value at the end of its range will show up as negative.
-func (l *loggingListener) writeVal(message *strings.Builder, t api.ValueType, i int, vals []uint64) int {
-	v := vals[i]
-	i++
-	switch t {
-	case api.ValueTypeI32:
-		message.WriteString(strconv.FormatInt(int64(int32(v)), 10))
-	case api.ValueTypeI64:
-		message.WriteString(strconv.FormatInt(int64(v), 10))
-	case api.ValueTypeF32:
-		message.WriteString(strconv.FormatFloat(float64(api.DecodeF32(v)), 'g', -1, 32))
-	case api.ValueTypeF64:
-		message.WriteString(strconv.FormatFloat(api.DecodeF64(v), 'g', -1, 64))
-	case 0x7b: // wasm.ValueTypeV128
-		message.WriteString(fmt.Sprintf("%016x%016x", v, vals[i])) // fixed-width hex
-		i++
-	case api.ValueTypeExternref, 0x70: // wasm.ValueTypeFuncref
-		message.WriteString(fmt.Sprintf("%016x", v)) // fixed-width hex
+		l.w.WriteByte(')') // nolint
 	}
-	return i
 }
diff --git a/imports/wasi_snapshot_preview1/fs.go b/imports/wasi_snapshot_preview1/fs.go
index e9d5857b..9a874974 100644
--- a/imports/wasi_snapshot_preview1/fs.go
+++ b/imports/wasi_snapshot_preview1/fs.go
@@ -461,7 +461,7 @@ func fdPrestatGetFn(_ context.Context, mod api.Module, params []uint64) Errno {
 var fdPrestatDirName = newHostFunc(
 	fdPrestatDirNameName, fdPrestatDirNameFn,
 	[]api.ValueType{i32, i32, i32},
-	"fd", "path", "path_len",
+	"fd", "result.path", "result.path_len",
 )
 
 func fdPrestatDirNameFn(_ context.Context, mod api.Module, params []uint64) Errno {
diff --git a/imports/wasi_snapshot_preview1/random.go b/imports/wasi_snapshot_preview1/random.go
index bb082208..b5ea4930 100644
--- a/imports/wasi_snapshot_preview1/random.go
+++ b/imports/wasi_snapshot_preview1/random.go
@@ -36,7 +36,7 @@ const randomGetName = "random_get"
 // See https://github.com/WebAssembly/WASI/blob/snapshot-01/phases/snapshot/docs.md#-random_getbuf-pointeru8-bufLen-size---errno
 var randomGet = newHostFunc(randomGetName, randomGetFn, []api.ValueType{i32, i32}, "buf", "buf_len")
 
-func randomGetFn(ctx context.Context, mod api.Module, params []uint64) Errno {
+func randomGetFn(_ context.Context, mod api.Module, params []uint64) Errno {
 	sysCtx := mod.(*wasm.CallContext).Sys
 	randSource := sysCtx.RandSource()
 	buf, bufLen := uint32(params[0]), uint32(params[1])
diff --git a/imports/wasi_snapshot_preview1/wasi.go b/imports/wasi_snapshot_preview1/wasi.go
index 314068cb..fa21078e 100644
--- a/imports/wasi_snapshot_preview1/wasi.go
+++ b/imports/wasi_snapshot_preview1/wasi.go
@@ -22,6 +22,7 @@ import (
 
 	"github.com/tetratelabs/wazero"
 	"github.com/tetratelabs/wazero/api"
+	"github.com/tetratelabs/wazero/internal/wasi_snapshot_preview1"
 	"github.com/tetratelabs/wazero/internal/wasm"
 )
 
@@ -29,7 +30,7 @@ import (
 //
 // See https://github.com/WebAssembly/WASI/blob/snapshot-01/phases/snapshot/docs.md
 const (
-	ModuleName = "wasi_snapshot_preview1"
+	ModuleName = wasi_snapshot_preview1.ModuleName
 	i32, i64   = wasm.ValueTypeI32, wasm.ValueTypeI64
 )
 
diff --git a/internal/engine/compiler/engine.go b/internal/engine/compiler/engine.go
index 47974f33..025d9c73 100644
--- a/internal/engine/compiler/engine.go
+++ b/internal/engine/compiler/engine.go
@@ -928,9 +928,9 @@ entry:
 			case builtinFunctionIndexTableGrow:
 				ce.builtinFunctionTableGrow(caller.source.Module.Tables)
 			case builtinFunctionIndexFunctionListenerBefore:
-				ce.builtinFunctionFunctionListenerBefore(ce.ctx, caller)
+				ce.builtinFunctionFunctionListenerBefore(ce.ctx, callCtx.WithMemory(ce.memoryInstance), caller)
 			case builtinFunctionIndexFunctionListenerAfter:
-				ce.builtinFunctionFunctionListenerAfter(ce.ctx, caller)
+				ce.builtinFunctionFunctionListenerAfter(ce.ctx, callCtx.WithMemory(ce.memoryInstance), caller)
 			}
 			if false {
 				if ce.exitContext.builtinFunctionCallIndex == builtinFunctionIndexBreakPoint {
@@ -995,17 +995,17 @@ func (ce *callEngine) builtinFunctionTableGrow(tables []*wasm.TableInstance) {
 	ce.pushValue(uint64(res))
 }
 
-func (ce *callEngine) builtinFunctionFunctionListenerBefore(ctx context.Context, fn *function) {
+func (ce *callEngine) builtinFunctionFunctionListenerBefore(ctx context.Context, mod api.Module, fn *function) {
 	base := int(ce.stackBasePointerInBytes >> 3)
-	listerCtx := fn.parent.listener.Before(ctx, fn.source.Definition, ce.stack[base:base+fn.source.Type.ParamNumInUint64])
+	listerCtx := fn.parent.listener.Before(ctx, mod, fn.source.Definition, ce.stack[base:base+fn.source.Type.ParamNumInUint64])
 	prevStackTop := ce.contextStack
 	ce.contextStack = &contextStack{self: ctx, prev: prevStackTop}
 	ce.ctx = listerCtx
 }
 
-func (ce *callEngine) builtinFunctionFunctionListenerAfter(ctx context.Context, fn *function) {
+func (ce *callEngine) builtinFunctionFunctionListenerAfter(ctx context.Context, mod api.Module, fn *function) {
 	base := int(ce.stackBasePointerInBytes >> 3)
-	fn.parent.listener.After(ctx, fn.source.Definition, nil, ce.stack[base:base+fn.source.Type.ResultNumInUint64])
+	fn.parent.listener.After(ctx, mod, fn.source.Definition, nil, ce.stack[base:base+fn.source.Type.ResultNumInUint64])
 	ce.ctx = ce.contextStack.self
 	ce.contextStack = ce.contextStack.prev
 }
diff --git a/internal/engine/interpreter/interpreter.go b/internal/engine/interpreter/interpreter.go
index 641d3062..80b34b31 100644
--- a/internal/engine/interpreter/interpreter.go
+++ b/internal/engine/interpreter/interpreter.go
@@ -865,9 +865,10 @@ func (ce *callEngine) callFunction(ctx context.Context, callCtx *wasm.CallContex
 
 func (ce *callEngine) callGoFunc(ctx context.Context, callCtx *wasm.CallContext, f *function, stack []uint64) {
 	lsn := f.parent.listener
+	callCtx = callCtx.WithMemory(ce.callerMemory())
 	if lsn != nil {
 		params := stack[:f.source.Type.ParamNumInUint64]
-		ctx = lsn.Before(ctx, f.source.Definition, params)
+		ctx = lsn.Before(ctx, callCtx, f.source.Definition, params)
 	}
 	frame := &callFrame{f: f}
 	ce.pushFrame(frame)
@@ -875,7 +876,7 @@ func (ce *callEngine) callGoFunc(ctx context.Context, callCtx *wasm.CallContext,
 	fn := f.source.GoFunc
 	switch fn := fn.(type) {
 	case api.GoModuleFunction:
-		fn.Call(ctx, callCtx.WithMemory(ce.callerMemory()), stack)
+		fn.Call(ctx, callCtx, stack)
 	case api.GoFunction:
 		fn.Call(ctx, stack)
 	}
@@ -884,7 +885,7 @@ func (ce *callEngine) callGoFunc(ctx context.Context, callCtx *wasm.CallContext,
 	if lsn != nil {
 		// TODO: This doesn't get the error due to use of panic to propagate them.
 		results := stack[:f.source.Type.ResultNumInUint64]
-		lsn.After(ctx, f.source.Definition, nil, results)
+		lsn.After(ctx, callCtx, f.source.Definition, nil, results)
 	}
 }
 
@@ -4367,10 +4368,13 @@ func i32Abs(v uint32) uint32 {
 }
 
 func (ce *callEngine) callNativeFuncWithListener(ctx context.Context, callCtx *wasm.CallContext, f *function, fnl experimental.FunctionListener) context.Context {
-	ctx = fnl.Before(ctx, f.source.Definition, ce.peekValues(len(f.source.Type.Params)))
+	if f.source.IsHostFunction {
+		callCtx = callCtx.WithMemory(ce.callerMemory())
+	}
+	ctx = fnl.Before(ctx, callCtx, f.source.Definition, ce.peekValues(len(f.source.Type.Params)))
 	ce.callNativeFunc(ctx, callCtx, f)
 	// TODO: This doesn't get the error due to use of panic to propagate them.
-	fnl.After(ctx, f.source.Definition, nil, ce.peekValues(len(f.source.Type.Results)))
+	fnl.After(ctx, callCtx, f.source.Definition, nil, ce.peekValues(len(f.source.Type.Results)))
 	return ctx
 }
 
diff --git a/internal/logging/logging.go b/internal/logging/logging.go
new file mode 100644
index 00000000..b717daaf
--- /dev/null
+++ b/internal/logging/logging.go
@@ -0,0 +1,228 @@
+// Package logging includes utilities used to log function calls. This is in
+// an independent package to avoid dependency cycles.
+package logging
+
+import (
+	"context"
+	"encoding/hex"
+	"fmt"
+	"io"
+	"strconv"
+
+	"github.com/tetratelabs/wazero/api"
+)
+
+// ValueType is an extended form of api.ValueType, used to control logging in
+// cases such as bitmasks or strings.
+type ValueType = api.ValueType
+
+const (
+	ValueTypeI32                 = api.ValueTypeI32
+	ValueTypeI64                 = api.ValueTypeI64
+	ValueTypeF32                 = api.ValueTypeF32
+	ValueTypeF64                 = api.ValueTypeF64
+	ValueTypeV128      ValueType = 0x7b // same as wasm.ValueTypeV128
+	ValueTypeFuncref   ValueType = 0x70 // same as wasm.ValueTypeFuncref
+	ValueTypeExternref           = api.ValueTypeExternref
+
+	// ValueTypeMemI32 is a non-standard type which writes ValueTypeI32 from the memory offset.
+	ValueTypeMemI32 = 0xfd
+	// ValueTypeMemH64 is a non-standard type which writes 64-bits fixed-width hex from the memory offset.
+	ValueTypeMemH64 = 0xfe
+	// ValueTypeString is a non-standard type describing an offset/len pair of a string.
+	ValueTypeString = 0xff
+)
+
+// LoggerKey is a context.Context Value key with a FunctionLogger value.
+type LoggerKey struct{}
+
+type ParamLogger func(ctx context.Context, mod api.Module, w Writer, params []uint64)
+
+type ResultLogger func(ctx context.Context, mod api.Module, w Writer, params, results []uint64)
+
+type Writer interface {
+	io.Writer
+	io.StringWriter
+	io.ByteWriter
+}
+
+// ValWriter formats an indexed value. For example, if `vals[i]` is a
+// ValueTypeI32, this would format it by default as signed. If a
+// 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) {
+	if paramLen := uint32(len(fnd.ParamTypes())); paramLen > 0 {
+		paramLoggers = make([]ParamLogger, paramLen)
+		hasParamNames := len(fnd.ParamNames()) > 0
+		for i, t := range fnd.ParamTypes() {
+			if hasParamNames {
+				paramLoggers[i] = NewParamLogger(uint32(i), fnd.ParamNames()[i], t)
+			} else {
+				paramLoggers[i] = paramLogger{idx: uint32(i), valWriter: ValWriterForType(t)}.Log
+			}
+		}
+	}
+	if resultLen := uint32(len(fnd.ResultTypes())); resultLen > 0 {
+		resultLoggers = make([]ResultLogger, resultLen)
+		hasResultNames := len(fnd.ResultNames()) > 0
+		for i, t := range fnd.ResultTypes() {
+			if hasResultNames {
+				resultLoggers[i] = NewResultLogger(uint32(i), fnd.ResultNames()[i], t)
+			} else {
+				resultLoggers[i] = resultLogger{idx: uint32(i), valWriter: ValWriterForType(t)}.Log
+			}
+		}
+	}
+	return
+}
+
+type paramLogger struct {
+	idx       uint32
+	valWriter ValWriter
+}
+
+func (n paramLogger) Log(ctx context.Context, mod api.Module, w Writer, params []uint64) {
+	n.valWriter(ctx, mod, w, n.idx, params)
+}
+
+func NewParamLogger(idx uint32, name string, t ValueType) ParamLogger {
+	return namedParamLogger{idx, name, ValWriterForType(t)}.Log
+}
+
+type namedParamLogger struct {
+	idx       uint32
+	name      string
+	valWriter ValWriter
+}
+
+func (n namedParamLogger) Log(ctx context.Context, mod api.Module, w Writer, params []uint64) {
+	w.WriteString(n.name) // nolint
+	w.WriteByte('=')      // nolint
+	n.valWriter(ctx, mod, w, n.idx, params)
+}
+
+type resultLogger struct {
+	idx       uint32
+	valWriter ValWriter
+}
+
+func (n resultLogger) Log(ctx context.Context, mod api.Module, w Writer, _, results []uint64) {
+	n.valWriter(ctx, mod, w, n.idx, results)
+}
+
+func NewResultLogger(idx uint32, name string, t ValueType) ResultLogger {
+	return namedResultLogger{idx, name, ValWriterForType(t)}.Log
+}
+
+type namedResultLogger struct {
+	idx       uint32
+	name      string
+	valWriter ValWriter
+}
+
+func (n namedResultLogger) Log(ctx context.Context, mod api.Module, w Writer, _, results []uint64) {
+	w.WriteString(n.name) // nolint
+	w.WriteByte('=')      // nolint
+	n.valWriter(ctx, mod, w, n.idx, results)
+}
+
+func ValWriterForType(vt ValueType) ValWriter {
+	switch vt {
+	case ValueTypeI32:
+		return writeI32
+	case ValueTypeI64:
+		return writeI64
+	case ValueTypeF32:
+		return writeF32
+	case ValueTypeF64:
+		return writeF64
+	case ValueTypeV128:
+		return writeV128
+	case ValueTypeExternref, ValueTypeFuncref:
+		return writeRef
+	case ValueTypeMemI32:
+		return writeMemI32
+	case ValueTypeMemH64:
+		return writeMemH64
+	case ValueTypeString:
+		return writeString
+	default:
+		panic(fmt.Errorf("BUG: unsupported type %d", vt))
+	}
+}
+
+func writeI32(_ context.Context, _ api.Module, w Writer, i uint32, vals []uint64) {
+	v := vals[i]
+	w.WriteString(strconv.FormatInt(int64(int32(v)), 10)) //nolint
+}
+
+func writeI64(_ context.Context, _ api.Module, w Writer, i uint32, vals []uint64) {
+	v := vals[i]
+	w.WriteString(strconv.FormatInt(int64(v), 10)) //nolint
+}
+
+func writeF32(_ context.Context, _ api.Module, w Writer, i uint32, vals []uint64) {
+	v := vals[i]
+	s := strconv.FormatFloat(float64(api.DecodeF32(v)), 'g', -1, 32)
+	w.WriteString(s) //nolint
+}
+
+func writeF64(_ context.Context, _ api.Module, w Writer, i uint32, vals []uint64) {
+	v := vals[i]
+	s := strconv.FormatFloat(api.DecodeF64(v), 'g', -1, 64)
+	w.WriteString(s) //nolint
+}
+
+// logV128 logs in fixed-width hex
+func writeV128(_ context.Context, _ api.Module, w Writer, i uint32, vals []uint64) {
+	v1, v2 := vals[i], vals[i+1]
+	w.WriteString(fmt.Sprintf("%016x%016x", v1, v2)) //nolint
+}
+
+// logRef logs in fixed-width hex
+func writeRef(_ context.Context, _ api.Module, w Writer, i uint32, vals []uint64) {
+	v := vals[i]
+	w.WriteString(fmt.Sprintf("%016x", v)) //nolint
+}
+
+func writeMemI32(_ context.Context, mod api.Module, w Writer, i uint32, vals []uint64) {
+	offset := uint32(vals[i])
+	byteCount := uint32(4)
+	if v, ok := mod.Memory().ReadUint32Le(offset); ok {
+		w.WriteString(strconv.FormatInt(int64(int32(v)), 10)) //nolint
+	} else { // log the positions that were out of memory
+		WriteOOM(w, offset, byteCount)
+	}
+}
+
+func writeMemH64(_ context.Context, mod api.Module, w Writer, i uint32, vals []uint64) {
+	offset := uint32(vals[i])
+	byteCount := uint32(8)
+	if s, ok := mod.Memory().Read(offset, byteCount); ok {
+		hex.NewEncoder(w).Write(s) //nolint
+	} else { // log the positions that were out of memory
+		WriteOOM(w, offset, byteCount)
+	}
+}
+
+func writeString(_ context.Context, mod api.Module, w Writer, i uint32, vals []uint64) {
+	offset, byteCount := uint32(vals[i]), uint32(vals[i+1])
+	WriteStringOrOOM(mod.Memory(), w, offset, byteCount)
+}
+
+func WriteStringOrOOM(mem api.Memory, w Writer, offset, byteCount uint32) {
+	if s, ok := mem.Read(offset, byteCount); ok {
+		w.Write(s) //nolint
+	} else { // log the positions that were out of memory
+		WriteOOM(w, offset, byteCount)
+	}
+}
+
+func WriteOOM(w Writer, offset uint32, byteCount uint32) {
+	w.WriteString("OOM(")                       //nolint
+	w.WriteString(strconv.Itoa(int(offset)))    //nolint
+	w.WriteByte(',')                            //nolint
+	w.WriteString(strconv.Itoa(int(byteCount))) //nolint
+	w.WriteByte(')')                            //nolint
+}
diff --git a/internal/wasi_snapshot_preview1/errno.go b/internal/wasi_snapshot_preview1/wasi.go
similarity index 68%
rename from internal/wasi_snapshot_preview1/errno.go
rename to internal/wasi_snapshot_preview1/wasi.go
index caad06a3..2f0de82e 100644
--- a/internal/wasi_snapshot_preview1/errno.go
+++ b/internal/wasi_snapshot_preview1/wasi.go
@@ -3,9 +3,15 @@
 package wasi_snapshot_preview1
 
 import (
+	"context"
 	"fmt"
+
+	"github.com/tetratelabs/wazero/api"
+	"github.com/tetratelabs/wazero/internal/logging"
 )
 
+const ModuleName = "wasi_snapshot_preview1"
+
 // ErrnoName returns the POSIX error code name, except ErrnoSuccess, which is not an error. e.g. Errno2big -> "E2BIG"
 func ErrnoName(errno uint32) string {
 	if int(errno) < len(errnoToString) {
@@ -93,3 +99,19 @@ var errnoToString = [...]string{
 	"EXDEV",
 	"ENOTCAPABLE",
 }
+
+func ValueLoggers(fnd api.FunctionDefinition) (pLoggers []logging.ParamLogger, rLoggers []logging.ResultLogger) {
+	pLoggers, rLoggers = logging.ValueLoggers(fnd)
+
+	// All WASI functions except proc_after return only an errno result.
+	if fnd.Name() == "proc_exit" {
+		return logging.ValueLoggers(fnd)
+	}
+	rLoggers[0] = wasiErrno
+	return
+}
+
+func wasiErrno(_ context.Context, _ api.Module, w logging.Writer, _, results []uint64) {
+	errno := ErrnoName(uint32(results[0]))
+	w.WriteString(errno) // nolint
+}


Test patch:
diff --git a/experimental/listener_example_test.go b/experimental/listener_example_test.go
index ee1fbe0b..d2433d22 100644
--- a/experimental/listener_example_test.go
+++ b/experimental/listener_example_test.go
@@ -43,13 +43,13 @@ func (u uniqGoFuncs) NewListener(def api.FunctionDefinition) FunctionListener {
 }
 
 // Before implements FunctionListener.Before
-func (u uniqGoFuncs) Before(ctx context.Context, def api.FunctionDefinition, _ []uint64) context.Context {
+func (u uniqGoFuncs) Before(ctx context.Context, _ api.Module, def api.FunctionDefinition, _ []uint64) context.Context {
 	u[def.DebugName()] = struct{}{}
 	return ctx
 }
 
 // After implements FunctionListener.After
-func (u uniqGoFuncs) After(context.Context, api.FunctionDefinition, error, []uint64) {}
+func (u uniqGoFuncs) After(context.Context, api.Module, api.FunctionDefinition, error, []uint64) {}
 
 // This shows how to make a listener that counts go function calls.
 func Example_customListenerFactory() {
diff --git a/experimental/listener_test.go b/experimental/listener_test.go
index 1d557929..92991c7c 100644
--- a/experimental/listener_test.go
+++ b/experimental/listener_test.go
@@ -21,12 +21,12 @@ type recorder struct {
 	beforeNames, afterNames []string
 }
 
-func (r *recorder) Before(ctx context.Context, def api.FunctionDefinition, _ []uint64) context.Context {
+func (r *recorder) Before(ctx context.Context, _ api.Module, def api.FunctionDefinition, _ []uint64) context.Context {
 	r.beforeNames = append(r.beforeNames, def.DebugName())
 	return ctx
 }
 
-func (r *recorder) After(_ context.Context, def api.FunctionDefinition, _ error, _ []uint64) {
+func (r *recorder) After(_ context.Context, _ api.Module, def api.FunctionDefinition, _ error, _ []uint64) {
 	r.afterNames = append(r.afterNames, def.DebugName())
 }
 
diff --git a/experimental/logging/log_listener_test.go b/experimental/logging/log_listener_test.go
index 751c2af8..665c1096 100644
--- a/experimental/logging/log_listener_test.go
+++ b/experimental/logging/log_listener_test.go
@@ -298,11 +298,11 @@ func Test_loggingListener(t *testing.T) {
 			}
 			m.BuildFunctionDefinitions()
 			def := m.FunctionDefinitionSection[0]
-			l := lf.NewListener(m.FunctionDefinitionSection[0])
+			l := lf.NewListener(def)
 
 			out.Reset()
-			ctx := l.Before(testCtx, def, tc.params)
-			l.After(ctx, def, tc.err, tc.results)
+			ctx := l.Before(testCtx, nil, def, tc.params)
+			l.After(ctx, nil, def, tc.err, tc.results)
 			require.Equal(t, tc.expected, out.String())
 		})
 	}
@@ -337,10 +337,10 @@ func Test_loggingListener_indentation(t *testing.T) {
 	def2 := m.FunctionDefinitionSection[1]
 	l2 := lf.NewListener(def2)
 
-	ctx := l1.Before(testCtx, def1, []uint64{})
-	ctx1 := l2.Before(ctx, def2, []uint64{})
-	l2.After(ctx1, def2, nil, []uint64{})
-	l1.After(ctx, def1, nil, []uint64{})
+	ctx := l1.Before(testCtx, nil, def1, []uint64{})
+	ctx1 := l2.Before(ctx, nil, def2, []uint64{})
+	l2.After(ctx1, nil, def2, nil, []uint64{})
+	l1.After(ctx, nil, def1, nil, []uint64{})
 	require.Equal(t, `--> test.fn1()
 	--> test.fn2()
 	<--
diff --git a/imports/wasi_snapshot_preview1/fs_test.go b/imports/wasi_snapshot_preview1/fs_test.go
index f672ed4b..a55f4514 100644
--- a/imports/wasi_snapshot_preview1/fs_test.go
+++ b/imports/wasi_snapshot_preview1/fs_test.go
@@ -742,7 +742,7 @@ func Test_fdPrestatDirName(t *testing.T) {
 
 	requireErrno(t, ErrnoSuccess, mod, fdPrestatDirNameName, uint64(fd), uint64(path), uint64(pathLen))
 	require.Equal(t, `
-==> wasi_snapshot_preview1.fd_prestat_dir_name(fd=3,path=1,path_len=0)
+==> wasi_snapshot_preview1.fd_prestat_dir_name(fd=3,result.path=1,result.path_len=0)
 <== ESUCCESS
 `, "\n"+log.String())
 
@@ -775,7 +775,7 @@ func Test_fdPrestatDirName_Errors(t *testing.T) {
 			pathLen:       pathLen,
 			expectedErrno: ErrnoFault,
 			expectedLog: `
-==> wasi_snapshot_preview1.fd_prestat_dir_name(fd=3,path=65536,path_len=1)
+==> wasi_snapshot_preview1.fd_prestat_dir_name(fd=3,result.path=65536,result.path_len=1)
 <== EFAULT
 `,
 		},
@@ -786,7 +786,7 @@ func Test_fdPrestatDirName_Errors(t *testing.T) {
 			pathLen:       pathLen,
 			expectedErrno: ErrnoFault,
 			expectedLog: `
-==> wasi_snapshot_preview1.fd_prestat_dir_name(fd=3,path=65536,path_len=1)
+==> wasi_snapshot_preview1.fd_prestat_dir_name(fd=3,result.path=65536,result.path_len=1)
 <== EFAULT
 `,
 		},
@@ -797,7 +797,7 @@ func Test_fdPrestatDirName_Errors(t *testing.T) {
 			pathLen:       pathLen + 1,
 			expectedErrno: ErrnoNametoolong,
 			expectedLog: `
-==> wasi_snapshot_preview1.fd_prestat_dir_name(fd=3,path=0,path_len=2)
+==> wasi_snapshot_preview1.fd_prestat_dir_name(fd=3,result.path=0,result.path_len=2)
 <== ENAMETOOLONG
 `,
 		},
@@ -808,7 +808,7 @@ func Test_fdPrestatDirName_Errors(t *testing.T) {
 			pathLen:       pathLen,
 			expectedErrno: ErrnoBadf,
 			expectedLog: `
-==> wasi_snapshot_preview1.fd_prestat_dir_name(fd=42,path=0,path_len=1)
+==> wasi_snapshot_preview1.fd_prestat_dir_name(fd=42,result.path=0,result.path_len=1)
 <== EBADF
 `,
 		},
diff --git a/internal/engine/compiler/engine_test.go b/internal/engine/compiler/engine_test.go
index 09f61650..6001d794 100644
--- a/internal/engine/compiler/engine_test.go
+++ b/internal/engine/compiler/engine_test.go
@@ -577,7 +577,7 @@ func TestCallEngine_builtinFunctionFunctionListenerBefore(t *testing.T) {
 		},
 		parent: &code{
 			listener: mockListener{
-				before: func(ctx context.Context, def api.FunctionDefinition, paramValues []uint64) context.Context {
+				before: func(ctx context.Context, _ api.Module, def api.FunctionDefinition, paramValues []uint64) context.Context {
 					require.Equal(t, currentContext, ctx)
 					require.Equal(t, []uint64{2, 3, 4}, paramValues)
 					return nextContext
@@ -590,7 +590,7 @@ func TestCallEngine_builtinFunctionFunctionListenerBefore(t *testing.T) {
 		stackContext: stackContext{stackBasePointerInBytes: 16},
 		contextStack: &contextStack{self: prevContext},
 	}
-	ce.builtinFunctionFunctionListenerBefore(ce.ctx, f)
+	ce.builtinFunctionFunctionListenerBefore(ce.ctx, &wasm.CallContext{}, f)
 
 	// Contexts must be stacked.
 	require.Equal(t, currentContext, ce.contextStack.self)
@@ -606,7 +606,7 @@ func TestCallEngine_builtinFunctionFunctionListenerAfter(t *testing.T) {
 		},
 		parent: &code{
 			listener: mockListener{
-				after: func(ctx context.Context, def api.FunctionDefinition, err error, resultValues []uint64) {
+				after: func(ctx context.Context, mod api.Module, def api.FunctionDefinition, err error, resultValues []uint64) {
 					require.Equal(t, currentContext, ctx)
 					require.Equal(t, []uint64{5}, resultValues)
 				},
@@ -619,7 +619,7 @@ func TestCallEngine_builtinFunctionFunctionListenerAfter(t *testing.T) {
 		stackContext: stackContext{stackBasePointerInBytes: 40},
 		contextStack: &contextStack{self: prevContext},
 	}
-	ce.builtinFunctionFunctionListenerAfter(ce.ctx, f)
+	ce.builtinFunctionFunctionListenerAfter(ce.ctx, &wasm.CallContext{}, f)
 
 	// Contexts must be popped.
 	require.Nil(t, ce.contextStack)
@@ -627,16 +627,16 @@ func TestCallEngine_builtinFunctionFunctionListenerAfter(t *testing.T) {
 }
 
 type mockListener struct {
-	before func(ctx context.Context, def api.FunctionDefinition, paramValues []uint64) context.Context
-	after  func(ctx context.Context, def api.FunctionDefinition, err error, resultValues []uint64)
+	before func(ctx context.Context, mod api.Module, def api.FunctionDefinition, paramValues []uint64) context.Context
+	after  func(ctx context.Context, mod api.Module, def api.FunctionDefinition, err error, resultValues []uint64)
 }
 
-func (m mockListener) Before(ctx context.Context, def api.FunctionDefinition, paramValues []uint64) context.Context {
-	return m.before(ctx, def, paramValues)
+func (m mockListener) Before(ctx context.Context, mod api.Module, def api.FunctionDefinition, paramValues []uint64) context.Context {
+	return m.before(ctx, mod, def, paramValues)
 }
 
-func (m mockListener) After(ctx context.Context, def api.FunctionDefinition, err error, resultValues []uint64) {
-	m.after(ctx, def, err, resultValues)
+func (m mockListener) After(ctx context.Context, mod api.Module, def api.FunctionDefinition, err error, resultValues []uint64) {
+	m.after(ctx, mod, def, err, resultValues)
 }
 
 func TestFunction_getSourceOffsetInWasmBinary(t *testing.T) {
diff --git a/internal/testing/proxy/proxy.go b/internal/testing/proxy/proxy.go
index b04af5ba..56a5f031 100644
--- a/internal/testing/proxy/proxy.go
+++ b/internal/testing/proxy/proxy.go
@@ -1,8 +1,6 @@
 package proxy
 
 import (
-	"io"
-
 	"github.com/tetratelabs/wazero"
 	"github.com/tetratelabs/wazero/api"
 	"github.com/tetratelabs/wazero/experimental"
@@ -16,7 +14,7 @@ const proxyModuleName = "internal/testing/proxy/proxy.go"
 
 // NewLoggingListenerFactory is like logging.NewHostLoggingListenerFactory,
 // except it skips logging proxying functions from NewModuleBinary.
-func NewLoggingListenerFactory(writer io.Writer) experimental.FunctionListenerFactory {
+func NewLoggingListenerFactory(writer logging.Writer) experimental.FunctionListenerFactory {
 	return &loggingListenerFactory{logging.NewHostLoggingListenerFactory(writer)}
 }
 
diff --git a/internal/wasm/host_test.go b/internal/wasm/host_test.go
index 4d33e3b5..623790a0 100644
--- a/internal/wasm/host_test.go
+++ b/internal/wasm/host_test.go
@@ -6,6 +6,7 @@ import (
 
 	"github.com/tetratelabs/wazero/api"
 	"github.com/tetratelabs/wazero/internal/testing/require"
+	"github.com/tetratelabs/wazero/internal/wasi_snapshot_preview1"
 )
 
 func argsSizesGet(ctx context.Context, mod api.Module, resultArgc, resultArgvBufSize uint32) uint32 {
@@ -42,7 +43,7 @@ func TestNewHostModule(t *testing.T) {
 		},
 		{
 			name:       "funcs",
-			moduleName: "wasi_snapshot_preview1",
+			moduleName: wasi_snapshot_preview1.ModuleName,
 			nameToGoFunc: map[string]interface{}{
 				argsSizesGetName: argsSizesGet,
 				fdWriteName:      fdWrite,
@@ -71,7 +72,7 @@ func TestNewHostModule(t *testing.T) {
 					{Name: "fd_write", Type: ExternTypeFunc, Index: 1},
 				},
 				NameSection: &NameSection{
-					ModuleName: "wasi_snapshot_preview1",
+					ModuleName: wasi_snapshot_preview1.ModuleName,
 					FunctionNames: NameMap{
 						{Index: 0, Name: "args_sizes_get"},
 						{Index: 1, Name: "fd_write"},