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/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.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.writeIndented(true, nil, vals, nestLevel+1) + l.logIndented(ctx, mod, nestLevel, true, params, nil, nil) + + 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.writeFuncExit(&message, err, vals) - } - message.WriteByte('\n') - - _, _ = l.writer.Write([]byte(message.String())) -} - -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) + l.logResults(ctx, mod, params, results) } } - message.WriteByte(')') + l.w.WriteByte('\n') // nolint + + if f, ok := l.w.(flusher); ok { + f.Flush() // 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) 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) + } + } + l.w.WriteByte(')') // nolint +} + +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(')') + l.w.WriteByte(')') // nolint } } - -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 - } - return i -} 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.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/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/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/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/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/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/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 +} 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"},