diff --git a/cmd/wazero/wazero.go b/cmd/wazero/wazero.go index 353bbb7b..bdbd7c01 100644 --- a/cmd/wazero/wazero.go +++ b/cmd/wazero/wazero.go @@ -3,6 +3,7 @@ package main import ( "context" "crypto/rand" + "errors" "flag" "fmt" "io" @@ -123,10 +124,10 @@ func doRun(args []string, stdOut io.Writer, stdErr logging.Writer, exit func(cod "This may be specified multiple times. When is unset, is used. "+ "For read-only mounts, append the suffix ':ro'.") - var hostlogging sliceFlag + var hostlogging logScopesFlag flags.Var(&hostlogging, "hostlogging", "A scope of host functions to log to stderr. "+ - "This may be specified multiple times. Supported values: filesystem,random") + "This may be specified multiple times. Supported values: clock,filesystem,random") cacheDir := cacheDirFlag(flags) @@ -173,7 +174,7 @@ func doRun(args []string, stdOut io.Writer, stdErr logging.Writer, exit func(cod wasmExe := filepath.Base(wasmPath) - ctx := maybeHostLogging(context.Background(), hostlogging, stdErr, exit) + ctx := maybeHostLogging(context.Background(), logging.LogScopes(hostlogging), stdErr) rtc := wazero.NewRuntimeConfig() if cache := maybeUseCacheDir(cacheDir, stdErr, exit); cache != nil { @@ -294,25 +295,10 @@ func detectImports(imports []api.FunctionDefinition) (needsWASI, needsGo bool) { return } -func maybeHostLogging(ctx context.Context, hostLogging []string, stdErr logging.Writer, exit func(code int)) context.Context { - var scopes logging.LogScopes - for _, h := range hostLogging { - switch h { - case "": - case "random": - scopes |= logging.LogScopeRandom - case "filesystem": - scopes |= logging.LogScopeFilesystem - default: - fmt.Fprintf(stdErr, "invalid hostLogging value: %v\n", h) - exit(1) - } - } - +func maybeHostLogging(ctx context.Context, scopes logging.LogScopes, stdErr logging.Writer) context.Context { if scopes != 0 { - ctx = context.WithValue(ctx, experimental.FunctionListenerFactoryKey{}, logging.NewHostLoggingListenerFactory(stdErr, scopes)) + return context.WithValue(ctx, experimental.FunctionListenerFactoryKey{}, logging.NewHostLoggingListenerFactory(stdErr, scopes)) } - return ctx } @@ -374,3 +360,24 @@ func (f *sliceFlag) Set(s string) error { *f = append(*f, s) return nil } + +type logScopesFlag logging.LogScopes + +func (f *logScopesFlag) String() string { + return logging.LogScopes(*f).String() +} + +func (f *logScopesFlag) Set(s string) error { + switch s { + case "": + case "clock": + *f |= logScopesFlag(logging.LogScopeClock) + case "filesystem": + *f |= logScopesFlag(logging.LogScopeFilesystem) + case "random": + *f |= logScopesFlag(logging.LogScopeRandom) + default: + return errors.New("not a log scope") + } + return nil +} diff --git a/cmd/wazero/wazero_test.go b/cmd/wazero/wazero_test.go index ac743d5f..7c83bcad 100644 --- a/cmd/wazero/wazero_test.go +++ b/cmd/wazero/wazero_test.go @@ -14,6 +14,7 @@ import ( "testing" "github.com/tetratelabs/wazero/api" + "github.com/tetratelabs/wazero/experimental/logging" "github.com/tetratelabs/wazero/imports/wasi_snapshot_preview1" "github.com/tetratelabs/wazero/internal/platform" "github.com/tetratelabs/wazero/internal/testing/require" @@ -354,9 +355,9 @@ func TestRun(t *testing.T) { } cryptoTest := test{ - name: "GOARCH=wasm GOOS=js hostlogging=random and filesystem", + name: "GOARCH=wasm GOOS=js hostlogging=filesystem random", wasm: wasmCat, - wazeroOpts: []string{"--hostlogging=random", "--hostlogging=filesystem"}, + wazeroOpts: []string{"--hostlogging=filesystem", "--hostlogging=random"}, wasmArgs: []string{"/bear.txt"}, expectedStderr: `==> go.runtime.getRandomData(r_len=32) <== @@ -526,6 +527,55 @@ func Test_detectImports(t *testing.T) { } } +func Test_logScopesFlag(t *testing.T) { + tests := []struct { + name string + values []string + expected logging.LogScopes + }{ + { + name: "defaults to none", + expected: logging.LogScopeNone, + }, + { + name: "ignores empty", + values: []string{""}, + expected: logging.LogScopeNone, + }, + { + name: "clock", + values: []string{"clock"}, + expected: logging.LogScopeClock, + }, + { + name: "filesystem", + values: []string{"filesystem"}, + expected: logging.LogScopeFilesystem, + }, + { + name: "random", + values: []string{"random"}, + expected: logging.LogScopeRandom, + }, + { + name: "clock filesystem random", + values: []string{"clock", "filesystem", "random"}, + expected: logging.LogScopeClock | logging.LogScopeFilesystem | logging.LogScopeRandom, + }, + } + + for _, tt := range tests { + tc := tt + t.Run(tc.name, func(t *testing.T) { + f := logScopesFlag(0) + for _, v := range tc.values { + require.NoError(t, f.Set(v)) + } + require.Equal(t, tc.expected, logging.LogScopes(f)) + }) + } +} + func TestHelp(t *testing.T) { exitCode, _, stdErr := runMain(t, []string{"-h"}) require.Equal(t, 0, exitCode) diff --git a/experimental/logging/log_listener.go b/experimental/logging/log_listener.go index 304012e3..0e977779 100644 --- a/experimental/logging/log_listener.go +++ b/experimental/logging/log_listener.go @@ -31,6 +31,8 @@ type LogScopes = logging.LogScopes const ( // LogScopeNone means nothing should be logged LogScopeNone = logging.LogScopeNone + // LogScopeClock enables logging for functions such as `clock_time_get`. + LogScopeClock = logging.LogScopeClock // LogScopeFilesystem enables logging for functions such as `path_open`. // Note: This doesn't log writes to the console. LogScopeFilesystem = logging.LogScopeFilesystem diff --git a/imports/wasi_snapshot_preview1/clock_test.go b/imports/wasi_snapshot_preview1/clock_test.go index 339d29e0..74835e5b 100644 --- a/imports/wasi_snapshot_preview1/clock_test.go +++ b/imports/wasi_snapshot_preview1/clock_test.go @@ -36,8 +36,8 @@ func Test_clockResGet(t *testing.T) { clockID: ClockIDRealtime, expectedMemory: expectedMemoryMicro, expectedLog: ` -==> wasi_snapshot_preview1.clock_res_get(id=0,result.resolution=16) -<== errno=ESUCCESS +==> wasi_snapshot_preview1.clock_res_get(id=realtime) +<== (resolution=1000,errno=ESUCCESS) `, }, { @@ -45,8 +45,8 @@ func Test_clockResGet(t *testing.T) { clockID: ClockIDMonotonic, expectedMemory: expectedMemoryNano, expectedLog: ` -==> wasi_snapshot_preview1.clock_res_get(id=1,result.resolution=16) -<== errno=ESUCCESS +==> wasi_snapshot_preview1.clock_res_get(id=monotonic) +<== (resolution=1,errno=ESUCCESS) `, }, } @@ -85,8 +85,8 @@ func Test_clockResGet_Unsupported(t *testing.T) { clockID: 2, expectedErrno: ErrnoInval, expectedLog: ` -==> wasi_snapshot_preview1.clock_res_get(id=2,result.resolution=16) -<== errno=EINVAL +==> wasi_snapshot_preview1.clock_res_get(id=2) +<== (resolution=,errno=EINVAL) `, }, { @@ -94,8 +94,8 @@ func Test_clockResGet_Unsupported(t *testing.T) { clockID: 3, expectedErrno: ErrnoInval, expectedLog: ` -==> wasi_snapshot_preview1.clock_res_get(id=3,result.resolution=16) -<== errno=EINVAL +==> wasi_snapshot_preview1.clock_res_get(id=3) +<== (resolution=,errno=EINVAL) `, }, { @@ -103,12 +103,11 @@ func Test_clockResGet_Unsupported(t *testing.T) { clockID: 100, expectedErrno: ErrnoInval, expectedLog: ` -==> wasi_snapshot_preview1.clock_res_get(id=100,result.resolution=16) -<== errno=EINVAL +==> wasi_snapshot_preview1.clock_res_get(id=100) +<== (resolution=,errno=EINVAL) `, }, } - for _, tt := range tests { tc := tt @@ -141,8 +140,8 @@ func Test_clockTimeGet(t *testing.T) { '?', // stopped after encoding }, expectedLog: ` -==> wasi_snapshot_preview1.clock_time_get(id=0,precision=0,result.timestamp=16) -<== errno=ESUCCESS +==> wasi_snapshot_preview1.clock_time_get(id=realtime,precision=0) +<== (timestamp=1640995200000000000,errno=ESUCCESS) `, }, { @@ -154,8 +153,8 @@ func Test_clockTimeGet(t *testing.T) { '?', // stopped after encoding }, expectedLog: ` -==> wasi_snapshot_preview1.clock_time_get(id=1,precision=0,result.timestamp=16) -<== errno=ESUCCESS +==> wasi_snapshot_preview1.clock_time_get(id=monotonic,precision=0) +<== (timestamp=0,errno=ESUCCESS) `, }, } @@ -193,8 +192,8 @@ func Test_clockTimeGet_Unsupported(t *testing.T) { clockID: 2, expectedErrno: ErrnoInval, expectedLog: ` -==> wasi_snapshot_preview1.clock_time_get(id=2,precision=0,result.timestamp=16) -<== errno=EINVAL +==> wasi_snapshot_preview1.clock_time_get(id=2,precision=0) +<== (timestamp=,errno=EINVAL) `, }, { @@ -202,8 +201,8 @@ func Test_clockTimeGet_Unsupported(t *testing.T) { clockID: 3, expectedErrno: ErrnoInval, expectedLog: ` -==> wasi_snapshot_preview1.clock_time_get(id=3,precision=0,result.timestamp=16) -<== errno=EINVAL +==> wasi_snapshot_preview1.clock_time_get(id=3,precision=0) +<== (timestamp=,errno=EINVAL) `, }, { @@ -211,8 +210,8 @@ func Test_clockTimeGet_Unsupported(t *testing.T) { clockID: 100, expectedErrno: ErrnoInval, expectedLog: ` -==> wasi_snapshot_preview1.clock_time_get(id=100,precision=0,result.timestamp=16) -<== errno=EINVAL +==> wasi_snapshot_preview1.clock_time_get(id=100,precision=0) +<== (timestamp=,errno=EINVAL) `, }, } @@ -245,16 +244,16 @@ func Test_clockTimeGet_Errors(t *testing.T) { name: "resultTimestamp OOM", resultTimestamp: memorySize, expectedLog: ` -==> wasi_snapshot_preview1.clock_time_get(id=0,precision=0,result.timestamp=65536) -<== errno=EFAULT +==> wasi_snapshot_preview1.clock_time_get(id=realtime,precision=0) +<== (timestamp=,errno=EFAULT) `, }, { name: "resultTimestamp exceeds the maximum valid address by 1", resultTimestamp: memorySize - 4 + 1, // 4 is the size of uint32, the type of the count of args expectedLog: ` -==> wasi_snapshot_preview1.clock_time_get(id=0,precision=0,result.timestamp=65533) -<== errno=EFAULT +==> wasi_snapshot_preview1.clock_time_get(id=realtime,precision=0) +<== (timestamp=,errno=EFAULT) `, }, } diff --git a/internal/gojs/crypto_test.go b/internal/gojs/crypto_test.go index 5b95d090..81b61413 100644 --- a/internal/gojs/crypto_test.go +++ b/internal/gojs/crypto_test.go @@ -25,21 +25,10 @@ func Test_crypto(t *testing.T) { require.Equal(t, `7a0c9f9f0d `, stdout) - // TODO: Go 1.17 initializes randoms in a different order than Go 1.18,19 - // When we move to 1.20, remove the workaround. - if log.String() != `==> go.runtime.getRandomData(r_len=32) -<== -==> go.runtime.getRandomData(r_len=8) -<== -==> go.syscall/js.valueCall(crypto.getRandomValues(r_len=5)) -<== (n=5) -` { - require.Equal(t, `==> go.runtime.getRandomData(r_len=8) -<== -==> go.runtime.getRandomData(r_len=32) -<== -==> go.syscall/js.valueCall(crypto.getRandomValues(r_len=5)) -<== (n=5) -`, log.String()) - } + // Search for the two functions that should be in scope, flexibly, to pass + // go 1.17-19 + require.Contains(t, log.String(), `go.runtime.getRandomData(r_len=32) +<==`) + require.Contains(t, log.String(), `==> go.syscall/js.valueCall(crypto.getRandomValues(r_len=5)) +<== (n=5)`) } diff --git a/internal/gojs/custom/date.go b/internal/gojs/custom/date.go new file mode 100644 index 00000000..0649122a --- /dev/null +++ b/internal/gojs/custom/date.go @@ -0,0 +1,17 @@ +package custom + +const ( + NameDate = "Date" + NameDateGetTimezoneOffset = "getTimezoneOffset" +) + +// DateNameSection are the functions defined in the object named NameDate. +// Results here are those set to the current event object, but effectively are +// results of the host function. +var DateNameSection = map[string]*Names{ + NameDateGetTimezoneOffset: { + Name: NameDateGetTimezoneOffset, + ParamNames: []string{}, + ResultNames: []string{"tz"}, + }, +} diff --git a/internal/gojs/custom/names.go b/internal/gojs/custom/names.go index 3793466c..09a97bb9 100644 --- a/internal/gojs/custom/names.go +++ b/internal/gojs/custom/names.go @@ -190,5 +190,6 @@ var NameSection = map[string]*Names{ var NameSectionSyscallValueCall = map[string]map[string]*Names{ NameCrypto: CryptoNameSection, + NameDate: DateNameSection, NameFs: FsNameSection, } diff --git a/internal/gojs/logging/logging.go b/internal/gojs/logging/logging.go index 6ebe7ac7..4bb566a2 100644 --- a/internal/gojs/logging/logging.go +++ b/internal/gojs/logging/logging.go @@ -18,11 +18,11 @@ import ( // IsInLogScope returns true if the current function is in any of the scopes. func IsInLogScope(fnd api.FunctionDefinition, scopes logging.LogScopes) bool { - if scopes.IsEnabled(logging.LogScopeRandom) { + if scopes.IsEnabled(logging.LogScopeClock) { switch fnd.Name() { - case custom.NameRuntimeGetRandomData: + case custom.NameRuntimeNanotime1, custom.NameRuntimeWalltime: return true - case custom.NameSyscallValueCall: // e.g. crypto.getRandomValues + case custom.NameSyscallValueCall: // e.g. Date.getTimezoneOffset return true } } @@ -33,6 +33,15 @@ func IsInLogScope(fnd api.FunctionDefinition, scopes logging.LogScopes) bool { } } + if scopes.IsEnabled(logging.LogScopeRandom) { + switch fnd.Name() { + case custom.NameRuntimeGetRandomData: + return true + case custom.NameSyscallValueCall: // e.g. crypto.getRandomValues + return true + } + } + return scopes == logging.LogScopeAll } @@ -44,14 +53,20 @@ func Config(fnd api.FunctionDefinition, scopes logging.LogScopes) (pSampler logg pLoggers = []logging.ParamLogger{syscallValueCallParamLogger} rLoggers = []logging.ResultLogger{syscallValueCallResultLogger} case custom.NameRuntimeGetRandomData: - _, rLoggers = logging.Config(fnd) - pLoggers = []logging.ParamLogger{syscallGetRandomParamLogger} + pLoggers = []logging.ParamLogger{runtimeGetRandomDataParamLogger} + // no results + case custom.NameRuntimeNanotime1: + // no params + rLoggers = []logging.ResultLogger{runtimeNanotime1ResultLogger} + case custom.NameRuntimeWalltime: + // no params + rLoggers = []logging.ResultLogger{runtimeWalltimeResultLogger} default: // TODO: make generic logger for gojs } return } -func syscallGetRandomParamLogger(_ context.Context, mod api.Module, w logging.Writer, params []uint64) { +func runtimeGetRandomDataParamLogger(_ context.Context, mod api.Module, w logging.Writer, params []uint64) { funcName := custom.NameRuntimeGetRandomData paramNames := custom.NameSection[funcName].ParamNames paramIdx := 1 /* there are two params, only write the length */ @@ -62,6 +77,28 @@ func syscallGetRandomParamLogger(_ context.Context, mod api.Module, w logging.Wr writeI32(w, stack.ParamUint32(paramIdx)) } +func runtimeNanotime1ResultLogger(_ context.Context, mod api.Module, w logging.Writer, params, _ []uint64) { + writeResults(w, custom.NameRuntimeNanotime1, mod, params, 0) +} + +func runtimeWalltimeResultLogger(_ context.Context, mod api.Module, w logging.Writer, params, _ []uint64) { + writeResults(w, custom.NameRuntimeWalltime, mod, params, 0) +} + +func writeResults(w logging.Writer, funcName string, mod api.Module, params []uint64, resultOffset int) { + stack := goos.NewStack(funcName, mod.Memory(), uint32(params[0])) + + resultNames := custom.NameSection[funcName].ResultNames + results := make([]interface{}, len(resultNames)) + for i := range resultNames { + results[i] = stack.ParamUint32(i + resultOffset) + } + + w.WriteByte('(') //nolint + writeVals(w, resultNames, results) + w.WriteByte(')') //nolint +} + type syscallValueCallParamSampler struct { scopes logging.LogScopes } @@ -70,6 +107,10 @@ func (s *syscallValueCallParamSampler) isSampled(ctx context.Context, mod api.Mo vRef, m, args := syscallValueCallParams(ctx, mod, params) switch vRef { + case goos.RefJsCrypto: + return logging.LogScopeRandom.IsEnabled(s.scopes) + case goos.RefJsDate: + return logging.LogScopeClock.IsEnabled(s.scopes) case goos.RefJsfs: if !logging.LogScopeFilesystem.IsEnabled(s.scopes) { return false @@ -81,8 +122,6 @@ func (s *syscallValueCallParamSampler) isSampled(ctx context.Context, mod api.Mo return fd > sys.FdStderr } return true - case goos.RefJsCrypto: - return logging.LogScopeRandom.IsEnabled(s.scopes) } return s.scopes == logging.LogScopeAll @@ -94,6 +133,8 @@ func syscallValueCallParamLogger(ctx context.Context, mod api.Module, w logging. switch vRef { case goos.RefJsCrypto: logSyscallValueCallArgs(w, custom.NameCrypto, m, args) + case goos.RefJsDate: + logSyscallValueCallArgs(w, custom.NameDate, m, args) case goos.RefJsfs: logFsParams(m, w, args) default: @@ -151,6 +192,10 @@ func syscallValueCallResultLogger(ctx context.Context, mod api.Module, w logging resultNames = custom.CryptoNameSection[m].ResultNames rRef := stack.ParamVal(ctx, 6, gojs.LoadValue) // val is after padding resultVals = []interface{}{rRef} + case goos.RefJsDate: + resultNames = custom.DateNameSection[m].ResultNames + rRef := stack.ParamVal(ctx, 6, gojs.LoadValue) // val is after padding + resultVals = []interface{}{rRef} case goos.RefJsfs: resultNames = custom.FsNameSection[m].ResultNames resultVals = gojs.GetLastEventArgs(ctx) diff --git a/internal/gojs/time.go b/internal/gojs/time.go index c15313e7..8b40b7d8 100644 --- a/internal/gojs/time.go +++ b/internal/gojs/time.go @@ -4,6 +4,7 @@ import ( "context" "github.com/tetratelabs/wazero/api" + "github.com/tetratelabs/wazero/internal/gojs/custom" "github.com/tetratelabs/wazero/internal/gojs/goos" ) @@ -11,12 +12,12 @@ var ( // jsDateConstructor returns jsDate. // // This is defined as `Get("Date")` in zoneinfo_js.go time.initLocal - jsDateConstructor = newJsVal(goos.RefJsDateConstructor, "Date") + jsDateConstructor = newJsVal(goos.RefJsDateConstructor, custom.NameDate) // jsDate is used inline in zoneinfo_js.go for time.initLocal. // `.Call("getTimezoneOffset").Int()` returns a timezone offset. - jsDate = newJsVal(goos.RefJsDate, "jsDate"). - addFunction("getTimezoneOffset", jsDateGetTimezoneOffset{}) + jsDate = newJsVal(goos.RefJsDate, custom.NameDate). + addFunction(custom.NameDateGetTimezoneOffset, jsDateGetTimezoneOffset{}) ) // jsDateGetTimezoneOffset implements jsFn diff --git a/internal/gojs/time_test.go b/internal/gojs/time_test.go index 4e8e7d9e..55a384b2 100644 --- a/internal/gojs/time_test.go +++ b/internal/gojs/time_test.go @@ -1,20 +1,39 @@ package gojs_test import ( + "bytes" + "context" "testing" "github.com/tetratelabs/wazero" + "github.com/tetratelabs/wazero/experimental" + "github.com/tetratelabs/wazero/experimental/logging" "github.com/tetratelabs/wazero/internal/testing/require" ) func Test_time(t *testing.T) { t.Parallel() - stdout, stderr, err := compileAndRun(testCtx, "time", wazero.NewModuleConfig()) + var log bytes.Buffer + loggingCtx := context.WithValue(testCtx, experimental.FunctionListenerFactoryKey{}, + logging.NewHostLoggingListenerFactory(&log, logging.LogScopeClock)) + + stdout, stderr, err := compileAndRun(loggingCtx, "time", wazero.NewModuleConfig()) require.EqualError(t, err, `module "" closed with exit_code(0)`) require.Zero(t, stderr) require.Equal(t, `Local 1ms `, stdout) + + // Search for the three functions that should be in scope, flexibly, to pass + // go 1.17-19 + require.Contains(t, log.String(), `==> go.runtime.nanotime1() +<== (nsec=0)`) + require.Contains(t, log.String(), `==> go.runtime.walltime() +<== (sec=1640995200,nsec=0) +`) + require.Contains(t, log.String(), `==> go.syscall/js.valueCall(Date.getTimezoneOffset()) +<== (tz=0) +`) } diff --git a/internal/logging/logging.go b/internal/logging/logging.go index a7cb8ff4..ed3e661c 100644 --- a/internal/logging/logging.go +++ b/internal/logging/logging.go @@ -37,14 +37,17 @@ const ( type LogScopes uint64 const ( - LogScopeNone = LogScopes(0) - LogScopeFilesystem LogScopes = 1 << iota + LogScopeNone = LogScopes(0) + LogScopeClock LogScopes = 1 << iota + LogScopeFilesystem LogScopeRandom LogScopeAll = LogScopes(0xffffffffffffffff) ) func scopeName(s LogScopes) string { switch s { + case LogScopeClock: + return "clock" case LogScopeFilesystem: return "filesystem" case LogScopeRandom: diff --git a/internal/logging/logging_test.go b/internal/logging/logging_test.go index a4affb41..74dbca64 100644 --- a/internal/logging/logging_test.go +++ b/internal/logging/logging_test.go @@ -51,10 +51,11 @@ func TestLogScopes_String(t *testing.T) { }{ {name: "none", scopes: LogScopeNone, expected: ""}, {name: "any", scopes: LogScopeAll, expected: "all"}, + {name: "clock", scopes: LogScopeClock, expected: "clock"}, {name: "filesystem", scopes: LogScopeFilesystem, expected: "filesystem"}, {name: "random", scopes: LogScopeRandom, expected: "random"}, {name: "filesystem|random", scopes: LogScopeFilesystem | LogScopeRandom, expected: "filesystem|random"}, - {name: "undefined", scopes: 1 << 3, expected: fmt.Sprintf("", (1 << 3))}, + {name: "undefined", scopes: 1 << 14, expected: fmt.Sprintf("", 1<<14)}, } for _, tt := range tests { diff --git a/internal/wasi_snapshot_preview1/logging/logging.go b/internal/wasi_snapshot_preview1/logging/logging.go index 0475f3e8..c0494f96 100644 --- a/internal/wasi_snapshot_preview1/logging/logging.go +++ b/internal/wasi_snapshot_preview1/logging/logging.go @@ -14,6 +14,10 @@ import ( var le = binary.LittleEndian +func isClockFunction(fnd api.FunctionDefinition) bool { + return strings.HasPrefix(fnd.Name(), "clock_") +} + func isFilesystemFunction(fnd api.FunctionDefinition) bool { switch { case strings.HasPrefix(fnd.Name(), "path_"): @@ -30,8 +34,8 @@ func isRandomFunction(fnd api.FunctionDefinition) bool { // IsInLogScope returns true if the current function is in any of the scopes. func IsInLogScope(fnd api.FunctionDefinition, scopes logging.LogScopes) bool { - if scopes.IsEnabled(logging.LogScopeRandom) { - if isRandomFunction(fnd) { + if scopes.IsEnabled(logging.LogScopeClock) { + if isClockFunction(fnd) { return true } } @@ -42,6 +46,12 @@ func IsInLogScope(fnd api.FunctionDefinition, scopes logging.LogScopes) bool { } } + if scopes.IsEnabled(logging.LogScopeRandom) { + if isRandomFunction(fnd) { + return true + } + } + return scopes == logging.LogScopeAll } @@ -83,6 +93,26 @@ func Config(fnd api.FunctionDefinition) (pSampler logging.ParamSampler, pLoggers continue } + if strings.HasPrefix(fnd.Name(), "clock_") { + switch name { + case "id": + logger = logClockId(idx).Log + pLoggers = append(pLoggers, logger) + case "result.resolution": + name = resultParamName(name) + logger = logMemI32(idx).Log + rLoggers = append(rLoggers, resultParamLogger(name, logger)) + case "result.timestamp": + name = resultParamName(name) + logger = logMemI64(idx).Log + rLoggers = append(rLoggers, resultParamLogger(name, logger)) + default: + logger = logging.NewParamLogger(idx, name, fnd.ParamTypes()[idx]) + pLoggers = append(pLoggers, logger) + } + continue + } + switch name { case "fdflags": logger = logFdflags(idx).Log @@ -149,6 +179,14 @@ func (i logMemI32) Log(_ context.Context, mod api.Module, w logging.Writer, para } } +type logMemI64 uint32 + +func (i logMemI64) Log(_ context.Context, mod api.Module, w logging.Writer, params []uint64) { + if v, ok := mod.Memory().ReadUint64Le(uint32(params[i])); ok { + writeI64(w, v) + } +} + type logFilestat uint32 func (i logFilestat) Log(_ context.Context, mod api.Module, w logging.Writer, params []uint64) { @@ -214,6 +252,21 @@ func resultParamLogger(name string, pLogger logging.ParamLogger) logging.ResultL } } +type logClockId int + +func (i logClockId) Log(_ context.Context, _ api.Module, w logging.Writer, params []uint64) { + id := uint32(params[i]) + w.WriteString("id=") //nolint + switch id { + case ClockIDRealtime: + w.WriteString("realtime") //nolint + case ClockIDMonotonic: + w.WriteString("monotonic") //nolint + default: + writeI32(w, id) + } +} + type logFdflags int func (i logFdflags) Log(_ context.Context, _ api.Module, w logging.Writer, params []uint64) { diff --git a/internal/wasi_snapshot_preview1/logging/logging_test.go b/internal/wasi_snapshot_preview1/logging/logging_test.go index 3d4b3140..405c666e 100644 --- a/internal/wasi_snapshot_preview1/logging/logging_test.go +++ b/internal/wasi_snapshot_preview1/logging/logging_test.go @@ -21,8 +21,9 @@ func (f *testFunctionDefinition) Name() string { } func TestIsInLogScope(t *testing.T) { - randomGet := &testFunctionDefinition{name: RandomGetName} + clockTimeGet := &testFunctionDefinition{name: ClockTimeGetName} fdRead := &testFunctionDefinition{name: FdReadName} + randomGet := &testFunctionDefinition{name: RandomGetName} tests := []struct { name string fnd api.FunctionDefinition @@ -30,32 +31,32 @@ func TestIsInLogScope(t *testing.T) { expected bool }{ { - name: "randomGet in LogScopeRandom", - fnd: randomGet, - scopes: logging.LogScopeRandom, + name: "clockTimeGet in LogScopeClock", + fnd: clockTimeGet, + scopes: logging.LogScopeClock, expected: true, }, { - name: "randomGet not in LogScopeFilesystem", - fnd: randomGet, + name: "clockTimeGet not in LogScopeFilesystem", + fnd: clockTimeGet, scopes: logging.LogScopeFilesystem, expected: false, }, { - name: "randomGet in LogScopeRandom|LogScopeFilesystem", - fnd: randomGet, - scopes: logging.LogScopeRandom | logging.LogScopeFilesystem, + name: "clockTimeGet in LogScopeClock|LogScopeFilesystem", + fnd: clockTimeGet, + scopes: logging.LogScopeClock | logging.LogScopeFilesystem, expected: true, }, { - name: "randomGet in LogScopeAll", - fnd: randomGet, + name: "clockTimeGet in LogScopeAll", + fnd: clockTimeGet, scopes: logging.LogScopeAll, expected: true, }, { - name: "randomGet not in LogScopeNone", - fnd: randomGet, + name: "clockTimeGet not in LogScopeNone", + fnd: clockTimeGet, scopes: logging.LogScopeNone, expected: false, }, @@ -89,6 +90,36 @@ func TestIsInLogScope(t *testing.T) { scopes: logging.LogScopeNone, expected: false, }, + { + name: "randomGet in LogScopeRandom", + fnd: randomGet, + scopes: logging.LogScopeRandom, + expected: true, + }, + { + name: "randomGet not in LogScopeFilesystem", + fnd: randomGet, + scopes: logging.LogScopeFilesystem, + expected: false, + }, + { + name: "randomGet in LogScopeRandom|LogScopeFilesystem", + fnd: randomGet, + scopes: logging.LogScopeRandom | logging.LogScopeFilesystem, + expected: true, + }, + { + name: "randomGet in LogScopeAll", + fnd: randomGet, + scopes: logging.LogScopeAll, + expected: true, + }, + { + name: "randomGet not in LogScopeNone", + fnd: randomGet, + scopes: logging.LogScopeNone, + expected: false, + }, } for _, tt := range tests {