diff --git a/experimental/listener_example_test.go b/experimental/listener_example_test.go index 2aa7de24..b14c551b 100644 --- a/experimental/listener_example_test.go +++ b/experimental/listener_example_test.go @@ -80,5 +80,6 @@ func Example_customListenerFactory() { } // Output: + // wasi_snapshot_preview1.fd_write // wasi_snapshot_preview1.random_get } diff --git a/experimental/logging/log_listener.go b/experimental/logging/log_listener.go index 0c4916d8..eda1ead6 100644 --- a/experimental/logging/log_listener.go +++ b/experimental/logging/log_listener.go @@ -162,9 +162,12 @@ func (f *loggingListenerFactory) NewListener(fnd api.FunctionDefinition) experim type logState struct { w logging.Writer nestLevel int + unsampled bool params []uint64 } +var unsampledLogState = &logState{unsampled: true} + // loggingListener implements experimental.FunctionListener to log entrance and after // of each function call. type loggingListener struct { @@ -178,28 +181,41 @@ type loggingListener struct { // 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, mod api.Module, _ api.FunctionDefinition, params []uint64) context.Context { - if s := l.pSampler; s != nil && !s(ctx, mod, params) { - return ctx + // First, see if this invocation is sampled. + sampled := true + if s := l.pSampler; s != nil { + sampled = s(ctx, mod, params) } + // Check to see if the calling function was logging. + var state *logState var nestLevel int - if ls := ctx.Value(logging.LoggerKey{}); ls != nil { - nestLevel = ls.(*logState).nestLevel + if v := ctx.Value(logging.LoggerKey{}); v != nil { + if !sampled { // override to mute this invocation. + return context.WithValue(ctx, logging.LoggerKey{}, unsampledLogState) + } + state = v.(*logState) + nestLevel = state.nestLevel + } else if !sampled { + return ctx // lack of LoggerKey == not sampled. } + + // We're starting to log: increase the indentation level. nestLevel++ l.logIndented(ctx, mod, nestLevel, true, params, nil, nil) - ls := &logState{w: l.w, nestLevel: nestLevel} + // We need to propagate this invocation's parameters to the after callback. + state = &logState{w: l.w, nestLevel: nestLevel} if pLen := len(params); pLen > 0 { - ls.params = make([]uint64, pLen) - copy(ls.params, params) // safe copy + state.params = make([]uint64, pLen) + copy(state.params, params) // safe copy } else { // empty - ls.params = params + state.params = params } - // Increase the next nesting level. - return context.WithValue(ctx, logging.LoggerKey{}, ls) + // Overwrite the logging key with this invocation's state. + return context.WithValue(ctx, logging.LoggerKey{}, state) } // After logs to stdout the module and function name, prefixed with '<--' and @@ -208,6 +224,9 @@ func (l *loggingListener) After(ctx context.Context, mod api.Module, _ api.Funct // 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. if state, ok := ctx.Value(logging.LoggerKey{}).(*logState); ok { + if state == unsampledLogState { + return + } l.logIndented(ctx, mod, state.nestLevel, false, state.params, err, results) } } diff --git a/experimental/logging/testdata/listener.wasm b/experimental/logging/testdata/listener.wasm index c9cf1def..c514d5f5 100644 Binary files a/experimental/logging/testdata/listener.wasm and b/experimental/logging/testdata/listener.wasm differ diff --git a/experimental/logging/testdata/listener.wat b/experimental/logging/testdata/listener.wat index 0ee77427..f8c84358 100644 --- a/experimental/logging/testdata/listener.wat +++ b/experimental/logging/testdata/listener.wat @@ -2,12 +2,21 @@ (import "wasi_snapshot_preview1" "random_get" (func $wasi.random_get (param $buf i32) (param $buf_len i32) (result (;errno;) i32))) + (import "wasi_snapshot_preview1" "fd_write" + (func $wasi.fd_write (param $fd i32) (param $iovs i32) (param $iovs_len i32) (param $result.size i32) (result (;errno;) i32))) + (table 8 funcref) ;; Define a function table with a single element at index 3. (elem (i32.const 3) $wasi.random_get) (memory 1 1) ;; Memory is needed for WASI (func $wasi_rand (param $len i32) + ;; call fd_write with an unsampled FD, inside a sampled function. + i32.const 1 ;; $fd = stdout + i32.const 0 i32.const 0 i32.const 0 ;; $iovs, $iovs_len $result.size = 0. + call $wasi.fd_write + drop ;; errno + i32.const 4 local.get 0 ;; buf, buf_len call $wasi.random_get drop ;; errno diff --git a/internal/engine/compiler/engine.go b/internal/engine/compiler/engine.go index 50f4e350..6cf389ff 100644 --- a/internal/engine/compiler/engine.go +++ b/internal/engine/compiler/engine.go @@ -269,7 +269,7 @@ type ( funcType *wasm.FunctionType // def is the api.Function for this function. Created during compilation. def api.FunctionDefinition - // parent holds code from which this is crated. + // parent holds code from which this is created. parent *code }