Adds logging.NewHostLoggingListenerFactory (#867)

This formalizes something I hand edit constantly, which is a listener
that only shows logging when it is a host function or called by the
host. This is important as some compilers create a large amount of
overhead functions, which can make thousands of lines around a host call
you are looking for.

Signed-off-by: Adrian Cole <adrian@tetrate.io>

experimental/logging/log_listener.go

@@ -12,17 +12,41 @@ import (
 	"github.com/tetratelabs/wazero/internal/wasi_snapshot_preview1"
 )
 
-// NewLoggingListenerFactory implements FunctionListenerFactory to log all
-// functions that have a name to the writer.
+// 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}
+	return &loggingListenerFactory{writer: writer}
 }
 
-type loggingListenerFactory struct{ writer io.Writer }
+// NewHostLoggingListenerFactory is an experimental.FunctionListenerFactory
+// that logs exported and host functions to the writer.
+//
+// This is an alternative to NewLoggingListenerFactory, and would weed out
+// 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}
+}
+
+type loggingListenerFactory struct {
+	writer   io.Writer
+	hostOnly bool
+}
 
 // NewListener implements the same method as documented on
 // experimental.FunctionListener.
 func (f *loggingListenerFactory) NewListener(fnd api.FunctionDefinition) experimental.FunctionListener {
+	exported := len(fnd.ExportNames()) > 0
+	if f.hostOnly && // choose functions defined or callable by the host
+		fnd.GoFunction() == nil && // not defined by the host
+		!exported { // not callable by the host
+		return nil
+	}
 	return &loggingListener{writer: f.writer, fnd: fnd, isWasi: fnd.ModuleName() == "wasi_snapshot_preview1"}
 }
 

experimental/logging/log_listener_example_test.go

@@ -19,10 +19,11 @@ import (
 //go:embed testdata/listener.wasm
 var listenerWasm []byte
 
-// This is a very basic integration of listener. The main goal is to show how it is configured.
-func Example_newLoggingListenerFactory() {
+// This is a very basic integration of listener. The main goal is to show how
+// it is configured.
+func Example_newHostLoggingListenerFactory() {
 	// Set context to one that has an experimental listener
-	ctx := context.WithValue(context.Background(), experimental.FunctionListenerFactoryKey{}, logging.NewLoggingListenerFactory(os.Stdout))
+	ctx := context.WithValue(context.Background(), experimental.FunctionListenerFactoryKey{}, logging.NewHostLoggingListenerFactory(os.Stdout))
 
 	r := wazero.NewRuntimeWithConfig(ctx, wazero.NewRuntimeConfigInterpreter())
 	defer r.Close(ctx) // This closes everything this Runtime created.
@@ -55,3 +56,43 @@ func Example_newLoggingListenerFactory() {
 	//	<== ESUCCESS
 	//<-- ()
 }
+
+// This example shows how to see all function calls, including between host
+// functions.
+func Example_newLoggingListenerFactory() {
+	// Set context to one that has an experimental listener
+	ctx := context.WithValue(context.Background(), experimental.FunctionListenerFactoryKey{}, logging.NewLoggingListenerFactory(os.Stdout))
+
+	r := wazero.NewRuntimeWithConfig(ctx, wazero.NewRuntimeConfigInterpreter())
+	defer r.Close(ctx) // This closes everything this Runtime created.
+
+	wasi_snapshot_preview1.MustInstantiate(ctx, r)
+
+	// Compile the WebAssembly module using the default configuration.
+	code, err := r.CompileModule(ctx, listenerWasm)
+	if err != nil {
+		log.Panicln(err)
+	}
+
+	mod, err := r.InstantiateModule(ctx, code, wazero.NewModuleConfig().WithStdout(os.Stdout))
+	if err != nil {
+		log.Panicln(err)
+	}
+
+	_, err = mod.ExportedFunction("rand").Call(ctx, 4)
+	if err != nil {
+		log.Panicln(err)
+	}
+
+	// We should see the same function called twice: directly and indirectly.
+
+	// Output:
+	//--> listener.rand(len=4)
+	//	--> listener.wasi_rand(len=4)
+	//		==> wasi_snapshot_preview1.random_get(buf=4,buf_len=4)
+	//		<== ESUCCESS
+	//		==> wasi_snapshot_preview1.random_get(buf=8,buf_len=4)
+	//		<== ESUCCESS
+	//	<-- ()
+	//<-- ()
+}

experimental/logging/testdata/listener.wat

@@ -1,12 +1,3 @@
-;; This file is a listener example, compiled to work with WebAssembly 1.0:
-;;  wat2wasm \
-;;      --disable-saturating-float-to-int \
-;;      --disable-sign-extension \
-;;      --disable-simd \
-;;      --disable-bulk-memory \
-;;      --disable-reference-types \
-;;      --debug-names \
-;;      listener.wat
 (module $listener
   (import "wasi_snapshot_preview1" "random_get"
     (func $wasi.random_get (param $buf i32) (param $buf_len i32) (result (;errno;) i32)))
@@ -16,7 +7,7 @@
 
   (memory 1 1) ;; Memory is needed for WASI
 
-  (func $rand (export "rand") (param $len i32)
+  (func $wasi_rand (param $len i32)
     i32.const 4 local.get 0 ;; buf, buf_len
     call $wasi.random_get
     drop ;; errno
@@ -25,4 +16,9 @@
     i32.const 3 call_indirect (type 0) ;; element 3, func type 0
     drop ;; errno
   )
+
+  (func $rand (export "rand") (param $len i32)
+    local.get 0 ;; buf_len
+    call $wasi_rand
+  )
 )

imports/wasi_snapshot_preview1/wasi_test.go

@@ -113,7 +113,7 @@ func requireErrnoNosys(t *testing.T, funcName string, params ...uint64) string {
 	var log bytes.Buffer
 
 	// Set context to one that has an experimental listener
-	ctx := context.WithValue(testCtx, FunctionListenerFactoryKey{}, logging.NewLoggingListenerFactory(&log))
+	ctx := context.WithValue(testCtx, FunctionListenerFactoryKey{}, logging.NewHostLoggingListenerFactory(&log))
 
 	r := wazero.NewRuntimeWithConfig(ctx, wazero.NewRuntimeConfigInterpreter())
 	defer r.Close(ctx)