Adds function names to host functions and improves logging listener (#697)

This improves the experimental logging listener to show parameter name
and values like so:

```
--> ._start.command_export()
        	--> .__wasm_call_ctors()
        		--> .__wasilibc_initialize_environ()
        			==> wasi_snapshot_preview1.environ_sizes_get(result.environc=1048572,result.environBufSize=1048568)
        			<== ESUCCESS
        		<-- ()
        		==> wasi_snapshot_preview1.fd_prestat_get(fd=3,result.prestat=1048568)
        		<== ESUCCESS
        		--> .dlmalloc(2)
        			--> .sbrk(0)
        			<-- (1114112)
        		<-- (1060080)
--snip--
```

The convention `==>` implies it was a host function call
(def.IsHostFunction). This also improves the lifecycle by creating
listeners during compile. Finally, this backfills param names for
assemblyscript and wasi.

Signed-off-by: Adrian Cole <adrian@tetrate.io>
This commit is contained in:
Crypt Keeper
2022-07-14 16:43:25 +08:00
committed by GitHub
parent 0ae4254f21
commit 040736caac
27 changed files with 1221 additions and 499 deletions

View File

@@ -6,12 +6,14 @@ import (
_ "embed"
"errors"
"io"
"strings"
"testing"
"testing/iotest"
"unicode/utf16"
"github.com/tetratelabs/wazero"
"github.com/tetratelabs/wazero/api"
. "github.com/tetratelabs/wazero/experimental"
"github.com/tetratelabs/wazero/internal/testing/require"
"github.com/tetratelabs/wazero/internal/watzero"
"github.com/tetratelabs/wazero/sys"
@@ -60,32 +62,37 @@ func TestAbort(t *testing.T) {
tc := tt
t.Run(tc.name, func(t *testing.T) {
r := wazero.NewRuntime()
defer r.Close(testCtx)
var out, log bytes.Buffer
out := &bytes.Buffer{}
// Set context to one that has an experimental listener
ctx := context.WithValue(testCtx, FunctionListenerFactoryKey{}, NewLoggingListenerFactory(&log))
_, err := r.NewModuleBuilder("env").
ExportFunctions(tc.exporter.ExportFunctions()).
Instantiate(testCtx, r)
r := wazero.NewRuntimeWithConfig(wazero.NewRuntimeConfigInterpreter())
defer r.Close(ctx)
envBuilder := r.NewModuleBuilder("env")
tc.exporter.ExportFunctions(envBuilder)
_, err := envBuilder.Instantiate(ctx, r)
require.NoError(t, err)
abortWasm, err := watzero.Wat2Wasm(abortWat)
require.NoError(t, err)
code, err := r.CompileModule(testCtx, abortWasm, wazero.NewCompileConfig())
code, err := r.CompileModule(ctx, abortWasm, wazero.NewCompileConfig())
require.NoError(t, err)
mod, err := r.InstantiateModule(testCtx, code, wazero.NewModuleConfig().WithStderr(out))
mod, err := r.InstantiateModule(ctx, code, wazero.NewModuleConfig().WithStderr(&out))
require.NoError(t, err)
messageOff, filenameOff := writeAbortMessageAndFileName(t, mod.Memory(), encodeUTF16("message"), encodeUTF16("filename"))
messageOff, filenameOff := writeAbortMessageAndFileName(ctx, t, mod.Memory(), encodeUTF16("message"), encodeUTF16("filename"))
_, err = mod.ExportedFunction("abort").Call(testCtx, uint64(messageOff), uint64(filenameOff), 1, 2)
_, err = mod.ExportedFunction("abort").Call(ctx, uint64(messageOff), uint64(filenameOff), 1, 2)
require.Error(t, err)
require.Equal(t, uint32(255), err.(*sys.ExitError).ExitCode())
require.Equal(t, tc.expected, out.String())
require.Equal(t, `==> env.~lib/builtins/abort(message=4,fileName=22,lineNumber=1,columnNumber=2)
`, log.String())
})
}
}
@@ -95,16 +102,23 @@ func TestAbort_Error(t *testing.T) {
name string
messageUTF16 []byte
fileNameUTF16 []byte
expectedLog string
}{
{
name: "bad message",
messageUTF16: encodeUTF16("message")[:5],
fileNameUTF16: encodeUTF16("filename"),
expectedLog: `==> env.~lib/builtins/abort(message=4,fileName=13,lineNumber=1,columnNumber=2)
<== ()
`,
},
{
name: "bad filename",
messageUTF16: encodeUTF16("message"),
fileNameUTF16: encodeUTF16("filename")[:5],
expectedLog: `==> env.~lib/builtins/abort(message=4,fileName=22,lineNumber=1,columnNumber=2)
<== ()
`,
},
}
@@ -112,28 +126,33 @@ func TestAbort_Error(t *testing.T) {
tc := tt
t.Run(tc.name, func(t *testing.T) {
r := wazero.NewRuntime()
defer r.Close(testCtx)
var out, log bytes.Buffer
_, err := Instantiate(testCtx, r)
// Set context to one that has an experimental listener
ctx := context.WithValue(testCtx, FunctionListenerFactoryKey{}, NewLoggingListenerFactory(&log))
r := wazero.NewRuntimeWithConfig(wazero.NewRuntimeConfigInterpreter())
defer r.Close(ctx)
_, err := Instantiate(ctx, r)
require.NoError(t, err)
abortWasm, err := watzero.Wat2Wasm(abortWat)
require.NoError(t, err)
compiled, err := r.CompileModule(testCtx, abortWasm, wazero.NewCompileConfig())
compiled, err := r.CompileModule(ctx, abortWasm, wazero.NewCompileConfig())
require.NoError(t, err)
out := &bytes.Buffer{}
exporter := wazero.NewModuleConfig().WithName(t.Name()).WithStdout(out)
mod, err := r.InstantiateModule(testCtx, compiled, exporter)
exporter := wazero.NewModuleConfig().WithName(t.Name()).WithStdout(&out)
mod, err := r.InstantiateModule(ctx, compiled, exporter)
require.NoError(t, err)
messageOff, filenameOff := writeAbortMessageAndFileName(t, mod.Memory(), tc.messageUTF16, tc.fileNameUTF16)
messageOff, filenameOff := writeAbortMessageAndFileName(ctx, t, mod.Memory(), tc.messageUTF16, tc.fileNameUTF16)
_, err = mod.ExportedFunction("abort").Call(testCtx, uint64(messageOff), uint64(filenameOff), 1, 2)
_, err = mod.ExportedFunction("abort").Call(ctx, uint64(messageOff), uint64(filenameOff), 1, 2)
require.NoError(t, err)
require.Equal(t, "", out.String()) // nothing output if strings fail to read.
require.Equal(t, tc.expectedLog, log.String())
})
}
}
@@ -153,48 +172,63 @@ var unreachableAfterAbort = `(module
// TestAbort_UnreachableAfter ensures code that follows an abort isn't invoked.
func TestAbort_UnreachableAfter(t *testing.T) {
r := wazero.NewRuntime()
defer r.Close(testCtx)
var log bytes.Buffer
_, err := r.NewModuleBuilder("env").
// Disable the abort message as we are passing invalid memory offsets.
ExportFunctions(NewFunctionExporter().WithAbortMessageDisabled().ExportFunctions()).
Instantiate(testCtx, r)
// Set context to one that has an experimental listener
ctx := context.WithValue(testCtx, FunctionListenerFactoryKey{}, NewLoggingListenerFactory(&log))
r := wazero.NewRuntimeWithConfig(wazero.NewRuntimeConfigInterpreter())
defer r.Close(ctx)
envBuilder := r.NewModuleBuilder("env")
// Disable the abort message as we are passing invalid memory offsets.
NewFunctionExporter().WithAbortMessageDisabled().ExportFunctions(envBuilder)
_, err := envBuilder.Instantiate(ctx, r)
require.NoError(t, err)
abortWasm, err := watzero.Wat2Wasm(unreachableAfterAbort)
require.NoError(t, err)
_, err = r.InstantiateModuleFromBinary(testCtx, abortWasm)
_, err = r.InstantiateModuleFromBinary(ctx, abortWasm)
require.Error(t, err)
require.Equal(t, uint32(255), err.(*sys.ExitError).ExitCode())
require.Equal(t, `--> .main()
==> env.~lib/builtins/abort(message=0,fileName=0,lineNumber=0,columnNumber=0)
`, log.String())
}
func TestSeed(t *testing.T) {
r := wazero.NewRuntime()
defer r.Close(testCtx)
var log bytes.Buffer
// Set context to one that has an experimental listener
ctx := context.WithValue(testCtx, FunctionListenerFactoryKey{}, NewLoggingListenerFactory(&log))
r := wazero.NewRuntimeWithConfig(wazero.NewRuntimeConfigInterpreter())
defer r.Close(ctx)
seed := []byte{0, 1, 2, 3, 4, 5, 6, 7}
_, err := Instantiate(testCtx, r)
_, err := Instantiate(ctx, r)
require.NoError(t, err)
seedWasm, err := watzero.Wat2Wasm(seedWat)
require.NoError(t, err)
code, err := r.CompileModule(testCtx, seedWasm, wazero.NewCompileConfig())
code, err := r.CompileModule(ctx, seedWasm, wazero.NewCompileConfig())
require.NoError(t, err)
mod, err := r.InstantiateModule(testCtx, code, wazero.NewModuleConfig().WithRandSource(bytes.NewReader(seed)))
mod, err := r.InstantiateModule(ctx, code, wazero.NewModuleConfig().WithRandSource(bytes.NewReader(seed)))
require.NoError(t, err)
seedFn := mod.ExportedFunction("seed")
res, err := seedFn.Call(testCtx)
_, err = seedFn.Call(ctx)
require.NoError(t, err)
// If this test doesn't break, the seed is deterministic.
require.Equal(t, uint64(506097522914230528), res[0])
require.Equal(t, `==> env.~lib/builtins/seed()
<== (7.949928895127363e-275)
`, log.String())
}
func TestSeed_error(t *testing.T) {
@@ -208,14 +242,14 @@ func TestSeed_error(t *testing.T) {
source: bytes.NewReader([]byte{0, 1}),
expectedErr: `error reading random seed: unexpected EOF (recovered by wazero)
wasm stack trace:
env.seed() f64`,
env.~lib/builtins/seed() f64`,
},
{
name: "error reading",
source: iotest.ErrReader(errors.New("ice cream")),
expectedErr: `error reading random seed: ice cream (recovered by wazero)
wasm stack trace:
env.seed() f64`,
env.~lib/builtins/seed() f64`,
},
}
@@ -223,65 +257,84 @@ wasm stack trace:
tc := tt
t.Run(tc.name, func(t *testing.T) {
r := wazero.NewRuntime()
defer r.Close(testCtx)
var log bytes.Buffer
_, err := Instantiate(testCtx, r)
// Set context to one that has an experimental listener
ctx := context.WithValue(testCtx, FunctionListenerFactoryKey{}, NewLoggingListenerFactory(&log))
r := wazero.NewRuntimeWithConfig(wazero.NewRuntimeConfigInterpreter())
defer r.Close(ctx)
_, err := Instantiate(ctx, r)
require.NoError(t, err)
seedWasm, err := watzero.Wat2Wasm(seedWat)
require.NoError(t, err)
compiled, err := r.CompileModule(testCtx, seedWasm, wazero.NewCompileConfig())
compiled, err := r.CompileModule(ctx, seedWasm, wazero.NewCompileConfig())
require.NoError(t, err)
exporter := wazero.NewModuleConfig().WithName(t.Name()).WithRandSource(tc.source)
mod, err := r.InstantiateModule(testCtx, compiled, exporter)
mod, err := r.InstantiateModule(ctx, compiled, exporter)
require.NoError(t, err)
_, err = mod.ExportedFunction("seed").Call(testCtx)
_, err = mod.ExportedFunction("seed").Call(ctx)
require.EqualError(t, err, tc.expectedErr)
require.Equal(t, `==> env.~lib/builtins/seed()
`, log.String())
})
}
}
func TestTrace(t *testing.T) {
noArgs := []uint64{4, 0, 0, 0, 0, 0, 0}
noArgsLog := `==> env.~lib/builtins/trace(message=4,nArgs=0,arg0=0,arg1=0,arg2=0,arg3=0,arg4=0)
<== ()
`
tests := []struct {
name string
exporter FunctionExporter
params []uint64
expected string
name string
exporter FunctionExporter
params []uint64
expected, expectedLog string
}{
{
name: "disabled",
exporter: NewFunctionExporter(),
params: noArgs,
expected: "",
name: "disabled",
exporter: NewFunctionExporter(),
params: noArgs,
expected: "",
expectedLog: noArgsLog,
},
{
name: "ToStderr",
exporter: NewFunctionExporter().WithTraceToStderr(),
params: noArgs,
expected: "trace: hello\n",
name: "ToStderr",
exporter: NewFunctionExporter().WithTraceToStderr(),
params: noArgs,
expected: "trace: hello\n",
expectedLog: noArgsLog,
},
{
name: "ToStdout - no args",
exporter: NewFunctionExporter().WithTraceToStdout(),
params: noArgs,
expected: "trace: hello\n",
name: "ToStdout - no args",
exporter: NewFunctionExporter().WithTraceToStdout(),
params: noArgs,
expected: "trace: hello\n",
expectedLog: noArgsLog,
},
{
name: "ToStdout - one arg",
exporter: NewFunctionExporter().WithTraceToStdout(),
params: []uint64{4, 1, api.EncodeF64(1), 0, 0, 0, 0},
expected: "trace: hello 1\n",
expectedLog: `==> env.~lib/builtins/trace(message=4,nArgs=1,arg0=1,arg1=0,arg2=0,arg3=0,arg4=0)
<== ()
`,
},
{
name: "ToStdout - two args",
exporter: NewFunctionExporter().WithTraceToStdout(),
params: []uint64{4, 2, api.EncodeF64(1), api.EncodeF64(2), 0, 0, 0},
expected: "trace: hello 1,2\n",
expectedLog: `==> env.~lib/builtins/trace(message=4,nArgs=2,arg0=1,arg1=2,arg2=0,arg3=0,arg4=0)
<== ()
`,
},
{
name: "ToStdout - five args",
@@ -296,6 +349,9 @@ func TestTrace(t *testing.T) {
api.EncodeF64(5),
},
expected: "trace: hello 1,2,3.3,4.4,5\n",
expectedLog: `==> env.~lib/builtins/trace(message=4,nArgs=5,arg0=1,arg1=2,arg2=3.3,arg3=4.4,arg4=5)
<== ()
`,
},
}
@@ -303,40 +359,45 @@ func TestTrace(t *testing.T) {
tc := tt
t.Run(tc.name, func(t *testing.T) {
r := wazero.NewRuntime()
defer r.Close(testCtx)
var out, log bytes.Buffer
_, err := r.NewModuleBuilder("env").
ExportFunctions(tc.exporter.ExportFunctions()).
Instantiate(testCtx, r)
// Set context to one that has an experimental listener
ctx := context.WithValue(testCtx, FunctionListenerFactoryKey{}, NewLoggingListenerFactory(&log))
r := wazero.NewRuntimeWithConfig(wazero.NewRuntimeConfigInterpreter())
defer r.Close(ctx)
envBuilder := r.NewModuleBuilder("env")
tc.exporter.ExportFunctions(envBuilder)
_, err := envBuilder.Instantiate(ctx, r)
require.NoError(t, err)
traceWasm, err := watzero.Wat2Wasm(traceWat)
require.NoError(t, err)
code, err := r.CompileModule(testCtx, traceWasm, wazero.NewCompileConfig())
code, err := r.CompileModule(ctx, traceWasm, wazero.NewCompileConfig())
require.NoError(t, err)
out := &bytes.Buffer{}
config := wazero.NewModuleConfig()
if tc.name == "ToStderr" {
config.WithStderr(out)
if strings.Contains("ToStderr", tc.name) {
config = config.WithStderr(&out)
} else {
config.WithStdout(out)
config = config.WithStdout(&out)
}
mod, err := r.InstantiateModule(testCtx, code, wazero.NewModuleConfig().WithStdout(out).WithStderr(out))
mod, err := r.InstantiateModule(ctx, code, config)
require.NoError(t, err)
message := encodeUTF16("hello")
ok := mod.Memory().WriteUint32Le(testCtx, 0, uint32(len(message)))
ok := mod.Memory().WriteUint32Le(ctx, 0, uint32(len(message)))
require.True(t, ok)
ok = mod.Memory().Write(testCtx, uint32(4), message)
ok = mod.Memory().Write(ctx, uint32(4), message)
require.True(t, ok)
_, err = mod.ExportedFunction("trace").Call(testCtx, tc.params...)
_, err = mod.ExportedFunction("trace").Call(ctx, tc.params...)
require.NoError(t, err)
require.Equal(t, tc.expected, out.String())
require.Equal(t, tc.expectedLog, log.String())
})
}
}
@@ -354,7 +415,7 @@ func TestTrace_error(t *testing.T) {
out: &bytes.Buffer{},
expectedErr: `read an odd number of bytes for utf-16 string: 5 (recovered by wazero)
wasm stack trace:
env.trace(i32,i32,f64,f64,f64,f64,f64)`,
env.~lib/builtins/trace(i32,i32,f64,f64,f64,f64,f64)`,
},
{
name: "error writing",
@@ -362,7 +423,7 @@ wasm stack trace:
out: &errWriter{err: errors.New("ice cream")},
expectedErr: `ice cream (recovered by wazero)
wasm stack trace:
env.trace(i32,i32,f64,f64,f64,f64,f64)`,
env.~lib/builtins/trace(i32,i32,f64,f64,f64,f64,f64)`,
},
}
@@ -370,31 +431,38 @@ wasm stack trace:
tc := tt
t.Run(tc.name, func(t *testing.T) {
r := wazero.NewRuntime()
defer r.Close(testCtx)
var log bytes.Buffer
_, err := r.NewModuleBuilder("env").
ExportFunctions(NewFunctionExporter().WithTraceToStdout().ExportFunctions()).
Instantiate(testCtx, r)
// Set context to one that has an experimental listener
ctx := context.WithValue(testCtx, FunctionListenerFactoryKey{}, NewLoggingListenerFactory(&log))
r := wazero.NewRuntimeWithConfig(wazero.NewRuntimeConfigInterpreter())
defer r.Close(ctx)
envBuilder := r.NewModuleBuilder("env")
NewFunctionExporter().WithTraceToStdout().ExportFunctions(envBuilder)
_, err := envBuilder.Instantiate(ctx, r)
require.NoError(t, err)
traceWasm, err := watzero.Wat2Wasm(traceWat)
require.NoError(t, err)
compiled, err := r.CompileModule(testCtx, traceWasm, wazero.NewCompileConfig())
compiled, err := r.CompileModule(ctx, traceWasm, wazero.NewCompileConfig())
require.NoError(t, err)
exporter := wazero.NewModuleConfig().WithName(t.Name()).WithStdout(tc.out)
mod, err := r.InstantiateModule(testCtx, compiled, exporter)
mod, err := r.InstantiateModule(ctx, compiled, exporter)
require.NoError(t, err)
ok := mod.Memory().WriteUint32Le(testCtx, 0, uint32(len(tc.message)))
ok := mod.Memory().WriteUint32Le(ctx, 0, uint32(len(tc.message)))
require.True(t, ok)
ok = mod.Memory().Write(testCtx, uint32(4), tc.message)
ok = mod.Memory().Write(ctx, uint32(4), tc.message)
require.True(t, ok)
_, err = mod.ExportedFunction("trace").Call(testCtx, 4, 0, 0, 0, 0, 0, 0)
_, err = mod.ExportedFunction("trace").Call(ctx, 4, 0, 0, 0, 0, 0, 0)
require.EqualError(t, err, tc.expectedErr)
require.Equal(t, `==> env.~lib/builtins/trace(message=4,nArgs=0,arg0=0,arg1=0,arg2=0,arg3=0,arg4=0)
`, log.String())
})
}
}
@@ -402,45 +470,45 @@ wasm stack trace:
func Test_readAssemblyScriptString(t *testing.T) {
tests := []struct {
name string
memory func(api.Memory)
memory func(context.Context, api.Memory)
offset int
expected, expectedErr string
}{
{
name: "success",
memory: func(memory api.Memory) {
memory.WriteUint32Le(testCtx, 0, 10)
memory: func(ctx context.Context, memory api.Memory) {
memory.WriteUint32Le(ctx, 0, 10)
b := encodeUTF16("hello")
memory.Write(testCtx, 4, b)
memory.Write(ctx, 4, b)
},
offset: 4,
expected: "hello",
},
{
name: "can't read size",
memory: func(memory api.Memory) {
memory: func(ctx context.Context, memory api.Memory) {
b := encodeUTF16("hello")
memory.Write(testCtx, 0, b)
memory.Write(ctx, 0, b)
},
offset: 0, // will attempt to read size from offset -4
expectedErr: "Memory.ReadUint32Le(4294967292) out of range",
},
{
name: "odd size",
memory: func(memory api.Memory) {
memory.WriteUint32Le(testCtx, 0, 9)
memory: func(ctx context.Context, memory api.Memory) {
memory.WriteUint32Le(ctx, 0, 9)
b := encodeUTF16("hello")
memory.Write(testCtx, 4, b)
memory.Write(ctx, 4, b)
},
offset: 4,
expectedErr: "read an odd number of bytes for utf-16 string: 9",
},
{
name: "can't read string",
memory: func(memory api.Memory) {
memory.WriteUint32Le(testCtx, 0, 10_000_000) // set size to too large value
memory: func(ctx context.Context, memory api.Memory) {
memory.WriteUint32Le(ctx, 0, 10_000_000) // set size to too large value
b := encodeUTF16("hello")
memory.Write(testCtx, 4, b)
memory.Write(ctx, 4, b)
},
offset: 4,
expectedErr: "Memory.Read(4, 10000000) out of range",
@@ -459,7 +527,7 @@ func Test_readAssemblyScriptString(t *testing.T) {
Instantiate(testCtx, r)
require.NoError(t, err)
tc.memory(mod.Memory())
tc.memory(testCtx, mod.Memory())
s, err := readAssemblyScriptString(testCtx, mod, uint32(tc.offset))
if tc.expectedErr != "" {
@@ -472,20 +540,20 @@ func Test_readAssemblyScriptString(t *testing.T) {
}
}
func writeAbortMessageAndFileName(t *testing.T, mem api.Memory, messageUTF16, fileNameUTF16 []byte) (int, int) {
func writeAbortMessageAndFileName(ctx context.Context, t *testing.T, mem api.Memory, messageUTF16, fileNameUTF16 []byte) (int, int) {
off := 0
ok := mem.WriteUint32Le(testCtx, uint32(off), uint32(len(messageUTF16)))
ok := mem.WriteUint32Le(ctx, uint32(off), uint32(len(messageUTF16)))
require.True(t, ok)
off += 4
messageOff := off
ok = mem.Write(testCtx, uint32(off), messageUTF16)
ok = mem.Write(ctx, uint32(off), messageUTF16)
require.True(t, ok)
off += len(messageUTF16)
ok = mem.WriteUint32Le(testCtx, uint32(off), uint32(len(fileNameUTF16)))
ok = mem.WriteUint32Le(ctx, uint32(off), uint32(len(fileNameUTF16)))
require.True(t, ok)
off += 4
filenameOff := off
ok = mem.Write(testCtx, uint32(off), fileNameUTF16)
ok = mem.Write(ctx, uint32(off), fileNameUTF16)
require.True(t, ok)
return messageOff, filenameOff
}