diff --git a/Makefile b/Makefile index 40ac4db1..705f5c39 100644 --- a/Makefile +++ b/Makefile @@ -9,7 +9,7 @@ examples/advanced/main.wasm: examples/advanced/main.go @(cd $(@D); tinygo build -o main.wasm -scheduler=none --no-debug -target=wasi .) .PHONY: build-tinygo -build-tinygo: examples/nodenumber/main.wasm examples/advanced/main.wasm guest/testdata/all/main.wasm guest/testdata/cyclestate/main.wasm guest/testdata/filter/main.wasm guest/testdata/score/main.wasm +build-tinygo: examples/nodenumber/main.wasm examples/advanced/main.wasm guest/testdata/cyclestate/main.wasm guest/testdata/filter/main.wasm guest/testdata/score/main.wasm %/main-debug.wasm: %/main.go @(cd $(@D); tinygo build -o main-debug.wasm -gc=custom -tags=custommalloc -scheduler=none -target=wasi .) @@ -120,8 +120,10 @@ format: # all_mods are the go modules including examples. Examples should also be # formatted, lint checked, etc. even if they are are built with TinyGo. -all_mods := ./internal/e2e/go.mod ./scheduler/go.mod ./guest/go.mod ./guest/testdata/go.mod ./kubernetes/proto/go.mod ./examples/go.mod ./examples/advanced/go.mod -all_nottinygo := ./examples/go.mod ./guest/testdata/go.mod +all_mods := ./internal/e2e/go.mod ./internal/e2e/guest/go.mod ./scheduler/go.mod ./examples/advanced/go.mod ./guest/testdata/go.mod ./guest/go.mod ./kubernetes/proto/go.mod +# all_mods are modules that can't be built with normal Go, such as due to being +# a tool, or a TinyGo main package. +all_unbuildable_mods := ./examples/go.mod ./kubernetes/proto/tools/go.mod .PHONY: tidy tidy: @@ -131,9 +133,7 @@ tidy: .PHONY: build build: - @# We filter out the examples main packages, as nottinygo cannot compile \ - # to a normal platform executable. - @for f in $(filter-out $(all_nottinygo), $(all_mods)); do \ + @for f in $(filter-out $(all_unbuildable_mods), $(all_mods)); do \ (cd $$(dirname $$f); go build ./...); \ done diff --git a/examples/advanced/main.go b/examples/advanced/main.go index 9b421139..9104d0de 100644 --- a/examples/advanced/main.go +++ b/examples/advanced/main.go @@ -28,6 +28,7 @@ import ( "sigs.k8s.io/kube-scheduler-wasm-extension/examples/advanced/plugin" "sigs.k8s.io/kube-scheduler-wasm-extension/guest/config" "sigs.k8s.io/kube-scheduler-wasm-extension/guest/enqueue" + "sigs.k8s.io/kube-scheduler-wasm-extension/guest/klog" "sigs.k8s.io/kube-scheduler-wasm-extension/guest/prescore" "sigs.k8s.io/kube-scheduler-wasm-extension/guest/score" ) @@ -40,7 +41,7 @@ func main() { // // The real implementations, such as `config.Get()` use Wasm host functions // (go:wasmimport), which cannot be tested with `tinygo test -target=wasi`. - plugin, err := plugin.New(config.Get()) + plugin, err := plugin.New(klog.Get(), config.Get()) if err != nil { panic(err) } diff --git a/examples/advanced/main.wasm b/examples/advanced/main.wasm index d04bcd77..b429e62b 100755 Binary files a/examples/advanced/main.wasm and b/examples/advanced/main.wasm differ diff --git a/examples/advanced/plugin/plugin.go b/examples/advanced/plugin/plugin.go index 29ccc5e4..2454e5cc 100644 --- a/examples/advanced/plugin/plugin.go +++ b/examples/advanced/plugin/plugin.go @@ -21,7 +21,6 @@ // - Logic was refactored to be cleaner and more testable. // - Doesn't return an error if state has the wrong type, as it is // impossible: this panics instead with the default message. -// - TODO: logging // // See https://github.com/kubernetes-sigs/kube-scheduler-simulator/blob/simulator/v0.1.0/simulator/docs/sample/nodenumber/plugin.go // @@ -34,6 +33,7 @@ import ( "sigs.k8s.io/kube-scheduler-wasm-extension/guest/api" "sigs.k8s.io/kube-scheduler-wasm-extension/guest/api/proto" + klog "sigs.k8s.io/kube-scheduler-wasm-extension/guest/klog/api" ) // NodeNumber is an example plugin that favors nodes that share a numerical @@ -50,25 +50,7 @@ import ( // a numeric match gets a results in a lower score than a match. type NodeNumber struct { reverse bool -} - -// New creates a new NodeNumber plugin with the given jsonConfig or returns an -// error. -// -// Note: This accepts config instead of implicitly calling config.Get for -// testing. -func New(jsonConfig []byte) (*NodeNumber, error) { - var args nodeNumberArgs - if jsonConfig != nil { - if err := json.Unmarshal(jsonConfig, &args); err != nil { - return nil, fmt.Errorf("decode arg into NodeNumberArgs: %w", err) - } - } - return &NodeNumber{reverse: args.Reverse}, nil -} - -type nodeNumberArgs struct { - Reverse bool `json:"reverse"` + klog klog.Klog } const ( @@ -91,6 +73,8 @@ func (pl *NodeNumber) EventsToRegister() []api.ClusterEvent { // PreScore implements api.PreScorePlugin func (pl *NodeNumber) PreScore(state api.CycleState, pod proto.Pod, _ proto.NodeList) *api.Status { + pl.klog.InfoS("execute PreScore on NodeNumber plugin", "pod", klog.KObj(pod)) + podnum, ok := lastNumber(pod.Spec().GetNodeName()) if !ok { return nil // return success even if its suffix is non-number. @@ -101,7 +85,9 @@ func (pl *NodeNumber) PreScore(state api.CycleState, pod proto.Pod, _ proto.Node } // Score implements api.ScorePlugin -func (pl *NodeNumber) Score(state api.CycleState, _ proto.Pod, nodeName string) (int32, *api.Status) { +func (pl *NodeNumber) Score(state api.CycleState, pod proto.Pod, nodeName string) (int32, *api.Status) { + pl.klog.InfoS("execute Score on NodeNumber plugin", "pod", klog.KObj(pod)) + var match bool if data, ok := state.Read(preScoreStateKey); ok { // Match is when there is a last digit, and it is the pod suffix. @@ -135,3 +121,23 @@ func lastNumber(str string) (uint8, bool) { } return 0, false } + +// New creates a new NodeNumber plugin with the given jsonConfig or returns an +// error. +// +// Note: This accepts config instead of implicitly calling config.Get for +// testing. +func New(klog klog.Klog, jsonConfig []byte) (*NodeNumber, error) { + var args nodeNumberArgs + if jsonConfig != nil { + if err := json.Unmarshal(jsonConfig, &args); err != nil { + return nil, fmt.Errorf("decode arg into NodeNumberArgs: %w", err) + } + klog.Info("NodeNumberArgs is successfully applied") + } + return &NodeNumber{klog: klog, reverse: args.Reverse}, nil +} + +type nodeNumberArgs struct { + Reverse bool `json:"reverse"` +} diff --git a/examples/advanced/plugin/plugin_test.go b/examples/advanced/plugin/plugin_test.go index 515f34c6..0ca9b3f0 100644 --- a/examples/advanced/plugin/plugin_test.go +++ b/examples/advanced/plugin/plugin_test.go @@ -21,6 +21,7 @@ import ( "sigs.k8s.io/kube-scheduler-wasm-extension/guest/api" "sigs.k8s.io/kube-scheduler-wasm-extension/guest/api/proto" + klogapi "sigs.k8s.io/kube-scheduler-wasm-extension/guest/klog/api" protoapi "sigs.k8s.io/kube-scheduler-wasm-extension/kubernetes/proto/api" ) @@ -51,7 +52,7 @@ func Test_NodeNumber(t *testing.T) { expectedMatch = !expectedMatch } t.Run(name, func(t *testing.T) { - plugin := &NodeNumber{reverse: reverse} + plugin := &NodeNumber{klog: klogapi.UnimplementedKlog{}, reverse: reverse} state := testCycleState{} status := plugin.PreScore(state, tc.pod, nil) diff --git a/examples/nodenumber/main.go b/examples/nodenumber/main.go index f46bd138..490c1acf 100644 --- a/examples/nodenumber/main.go +++ b/examples/nodenumber/main.go @@ -25,6 +25,7 @@ import ( "sigs.k8s.io/kube-scheduler-wasm-extension/guest/api" "sigs.k8s.io/kube-scheduler-wasm-extension/guest/api/proto" "sigs.k8s.io/kube-scheduler-wasm-extension/guest/config" + "sigs.k8s.io/kube-scheduler-wasm-extension/guest/klog" "sigs.k8s.io/kube-scheduler-wasm-extension/guest/plugin" ) @@ -36,6 +37,7 @@ func main() { if err := json.Unmarshal(jsonConfig, &args); err != nil { panic(fmt.Errorf("decode arg into NodeNumberArgs: %w", err)) } + klog.Info("NodeNumberArgs is successfully applied") } plugin.Set(&NodeNumber{reverse: args.Reverse}) } @@ -80,6 +82,8 @@ func (pl *NodeNumber) EventsToRegister() []api.ClusterEvent { // PreScore implements api.PreScorePlugin func (pl *NodeNumber) PreScore(state api.CycleState, pod proto.Pod, _ proto.NodeList) *api.Status { + klog.InfoS("execute PreScore on NodeNumber plugin", "pod", klog.KObj(pod)) + podnum, ok := lastNumber(pod.Spec().GetNodeName()) if !ok { return nil // return success even if its suffix is non-number. @@ -90,7 +94,9 @@ func (pl *NodeNumber) PreScore(state api.CycleState, pod proto.Pod, _ proto.Node } // Score implements api.ScorePlugin -func (pl *NodeNumber) Score(state api.CycleState, _ proto.Pod, nodeName string) (int32, *api.Status) { +func (pl *NodeNumber) Score(state api.CycleState, pod proto.Pod, nodeName string) (int32, *api.Status) { + klog.InfoS("execute Score on NodeNumber plugin", "pod", klog.KObj(pod)) + var match bool if data, ok := state.Read(preScoreStateKey); ok { // Match is when there is a last digit, and it is the pod suffix. diff --git a/examples/nodenumber/main.wasm b/examples/nodenumber/main.wasm index 8353ee83..e466f970 100755 Binary files a/examples/nodenumber/main.wasm and b/examples/nodenumber/main.wasm differ diff --git a/guest/RATIONALE.md b/guest/RATIONALE.md index 07d56ab5..40f68306 100644 --- a/guest/RATIONALE.md +++ b/guest/RATIONALE.md @@ -114,6 +114,49 @@ Considering the above, we recommend nottinygc, but as an opt-in process. Our examples default to configure it, and all our integration tests use it. However, we can't make this default until it no longer crashes our unit tests. +## Why don't we use the normal k8s.io/klog/v2 package for logging? + +The scheduler framework uses the k8s.io/klog/v2 package for logging, like: +```go +klog.InfoS("execute Score on NodeNumber plugin", "pod", klog.KObj(pod)) +``` + +The guest SDK cannot use this because some parts of the klog package do not +compile with TinyGo, due to heavy use of reflection. Also, the initialization +of the wasm guest is separate from the scheduler process, and it wouldn't be +able to read the same configuration including filters that need to be applied. + +Instead, this adds a minimal working abstraction of klog functions which pass +strings to the host to log using a real klog function. + +As discussed in other sections, you cannot pass an object between the guest and +the host by reference, rather only by value. For this reason, the guest klog +package stringifies args including key/values and sends them to the host for +processing via functions like `klog.Info` or `klog.ErrorS`. + +Stringification is expensive in Wasm due to factors including inlined garbage +collection. To avoid performance problems when not logging, the host includes a +function not in the normal `klog` package, which exposes the current severity +level. Anything outside that level won't be logged, and that's how excess +overhead is avoided. + +### Why does `klog.KObj` return a `fmt.Stringer` instead of `ObjectRef` + +`klog.KObj` works differently in wasm because unlike the normal scheduler +framework, objects such as `proto.Node` are lazy unmarshalled. To avoid +triggering this when logging is disabled, `klog.KObj` returns a `fmt.Stringer` +which lazy accessed fields needed. + +### Why is there an `api` package in `klog`? + +The `klog` package imports functions from the host, via `//go:wasmimport`. This +makes code in that package untestable via `tinygo test -target=wasi`, as the +implicit Wasm runtime launched does not export these (they are custom to this +codebase). To allow unit testing of the core logic with both Go and TinyGo, we +have an `api` package which includes an interface representing the logging +functions in the `klog` package. Advanced users can also use these interfaces +for the same reason: to keep their core logic testable in TinyGo. + [1]: https://tinygo.org/ [2]: https://pkg.go.dev/golang.org/dl/gotip [3]: https://github.com/golang/go/issues/42372 diff --git a/guest/api/proto/proto.go b/guest/api/proto/proto.go index afe30d07..67094d3a 100644 --- a/guest/api/proto/proto.go +++ b/guest/api/proto/proto.go @@ -17,9 +17,7 @@ // Package proto includes any types derived from Kubernetes protobuf messages. package proto -import ( - api "sigs.k8s.io/kube-scheduler-wasm-extension/kubernetes/proto/api" -) +import api "sigs.k8s.io/kube-scheduler-wasm-extension/kubernetes/proto/api" // Metadata are fields on top-level types, used for logging and metrics. type Metadata interface { diff --git a/guest/api/types.go b/guest/api/types.go index e05a6d6d..1e5579b1 100644 --- a/guest/api/types.go +++ b/guest/api/types.go @@ -92,5 +92,8 @@ type ScorePlugin interface { } type NodeInfo interface { + // Metadata is a convenience that triggers Get. + proto.Metadata + Node() proto.Node } diff --git a/guest/filter/filter.go b/guest/filter/filter.go index 635bc65a..336fc451 100644 --- a/guest/filter/filter.go +++ b/guest/filter/filter.go @@ -82,6 +82,18 @@ type nodeInfo struct { node proto.Node } +func (n *nodeInfo) GetUid() string { + return n.lazyNode().GetUid() +} + +func (n *nodeInfo) GetName() string { + return n.lazyNode().GetName() +} + +func (n *nodeInfo) GetNamespace() string { + return n.lazyNode().GetNamespace() +} + func (n *nodeInfo) Node() proto.Node { return n.lazyNode() } diff --git a/guest/internal/mem/mem.go b/guest/internal/mem/mem.go index 142a28ec..b0718ec8 100644 --- a/guest/internal/mem/mem.go +++ b/guest/internal/mem/mem.go @@ -34,13 +34,22 @@ var ( // StringToPtr returns a pointer and size pair for the given string in a way // compatible with WebAssembly numeric types. -// The returned pointer aliases the string hence the string must be kept alive -// until ptr is no longer needed. +// The returned pointer aliases the string hence it must be kept alive until +// ptr is no longer needed. func StringToPtr(s string) (uint32, uint32) { ptr := unsafe.Pointer(unsafe.StringData(s)) return uint32(uintptr(ptr)), uint32(len(s)) } +// BytesToPtr returns a pointer and size pair for the given byte slice in a way +// compatible with WebAssembly numeric types. +// The returned pointer aliases the slice hence it must be kept alive until ptr +// is no longer needed. +func BytesToPtr(b []byte) (uint32, uint32) { + ptr := unsafe.Pointer(&b[0]) + return uint32(uintptr(ptr)), uint32(len(b)) +} + // Update is for decoding values from memory. The updater doesn't keep a // reference to the underlying bytes, so we don't need to copy them. func Update( diff --git a/guest/internal/prefilter/cstring.go b/guest/internal/prefilter/cstring.go index 33ae0ff1..04cdedeb 100644 --- a/guest/internal/prefilter/cstring.go +++ b/guest/internal/prefilter/cstring.go @@ -17,20 +17,21 @@ package prefilter func toNULTerminated(input []string) []byte { - count := uint32(len(input)) + count := len(input) if count == 0 { return nil } size := count // NUL terminator count for _, s := range input { - size += uint32(len(s)) + size += len(s) } // Write the NUL-terminated string to a byte slice. cStrings := make([]byte, size) pos := 0 - for _, s := range input { + for i := 0; i < count; i++ { + s := input[i] if len(s) == 0 { size-- continue // skip empty diff --git a/guest/klog/api/k8s_references.go b/guest/klog/api/k8s_references.go new file mode 100644 index 00000000..adbe0f89 --- /dev/null +++ b/guest/klog/api/k8s_references.go @@ -0,0 +1,131 @@ +/* + Copyright 2023 The Kubernetes Authors. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ + +package api + +import ( + "fmt" + "strings" + + "sigs.k8s.io/kube-scheduler-wasm-extension/guest/api/proto" +) + +// Note: This includes some functions in k8s.io/klog/v2 k8s_references.go, +// customized from the original source where noted. + +// logBuf is shared as logging cannot happen concurrently in wasm. By sharing +// a buffer, we reduce log allocation/GC overhead. +var logBuf strings.Builder + +// writeRef writes the reference to the shared log buffer +func writeRef(ns, name string) { + logBuf.Grow(len(ns) + len(name) + 1) + logBuf.WriteString(ns) + logBuf.WriteRune('/') + logBuf.WriteString(name) +} + +type objectRef struct { + proto.Metadata +} + +// String implements fmt.Stringer +func (ref *objectRef) String() string { + obj := ref.Metadata + if obj == nil { + return "" + } + if name, ns := obj.GetName(), obj.GetNamespace(); ns != "" { + logBuf.Reset() + writeRef(ns, name) + return logBuf.String() + } else { + return name + } +} + +// KObj wraps a proto.Metadata to normalize log values. +// +// Note: This is similar klog.KObj, except references proto.Metadata and avoids +// reflection calls that don't compile in TinyGo 0.28 +func KObj(obj proto.Metadata) fmt.Stringer { + return &objectRef{obj} +} + +// KObjSlice wraps a slice of proto.Metadata to normalize log values. +// +// Note: This is similar klog.KObjSlice, except references proto.Metadata and +// avoids reflection calls that don't compile in TinyGo 0.28 +func KObjSlice[M proto.Metadata](objs []M) fmt.Stringer { + return &kobjSlice[M]{objs} +} + +// kobjSlice is a normalized logging reference of proto.Metadata. Construct +// this using KObjSlice. +// +// Note: This is like klog.KObjSlice except lazy to avoid eagerly unmarshalling +// protos. +type kobjSlice[M proto.Metadata] struct { + objs []M +} + +// String implements fmt.Stringer +func (ks *kobjSlice[M]) String() string { + return kobjSliceString(ks.objs) +} + +// KObjSliceFn wraps function that produces a slice of proto.Metadata to +// normalize log values. +// +// Note: This is the same as KObjSlice, except avoids calling a function when +// logging is disabled. +func KObjSliceFn[M proto.Metadata](lazy func() []M) fmt.Stringer { + return &kObjSliceFn[M]{lazy} +} + +type kObjSliceFn[M proto.Metadata] struct { + fn func() []M +} + +// String implements fmt.Stringer +func (kl *kObjSliceFn[M]) String() string { + if fn := kl.fn; fn == nil { + return "[]" + } else { + return kobjSliceString(fn()) + } +} + +func kobjSliceString[M proto.Metadata](objs []M) string { + if len(objs) == 0 { + return "[]" + } + logBuf.Reset() + logBuf.WriteRune('[') + for i := range objs { + if i > 0 { + logBuf.WriteRune(' ') + } + obj := objs[i] + if name, ns := obj.GetName(), obj.GetNamespace(); ns != "" { + writeRef(ns, name) + } else { + logBuf.WriteString(name) + } + } + logBuf.WriteRune(']') + return logBuf.String() +} diff --git a/guest/klog/api/k8s_references_test.go b/guest/klog/api/k8s_references_test.go new file mode 100644 index 00000000..e166f5b2 --- /dev/null +++ b/guest/klog/api/k8s_references_test.go @@ -0,0 +1,248 @@ +/* + Copyright 2023 The Kubernetes Authors. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ + +package api + +import ( + "fmt" + "reflect" + "testing" + + "sigs.k8s.io/kube-scheduler-wasm-extension/guest/api/proto" +) + +var _ proto.Metadata = &testMetadata{} + +type testMetadata struct { + Name, Namespace, UID string +} + +func (t *testMetadata) GetName() string { + return t.Name +} + +func (t *testMetadata) GetNamespace() string { + return t.Namespace +} + +func (t *testMetadata) GetUid() string { + return t.UID +} + +var _ proto.Metadata = &panicMetadata{} + +type panicMetadata struct { + Name, Namespace, UID string +} + +func (panicMetadata) GetName() string { + panic("unexpected") +} + +func (panicMetadata) GetNamespace() string { + panic("unexpected") +} + +func (panicMetadata) GetUid() string { + panic("unexpected") +} + +func TestKObj(t *testing.T) { + tests := []struct { + name string + input proto.Metadata + expected *objectRef + }{ + { + name: "nil", + }, + { + // If calling KObj called methods, it would hurt performance as + // unmarshalling is very expensive in wasm. + name: "doesn't call methods", + input: panicMetadata{}, + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + if want, have := tc.input, KObj(tc.input).(*objectRef).Metadata; want != have { + t.Fatalf("unexpected ref: %v != %v", want, have) + } + }) + } +} + +func TestKObjSlice(t *testing.T) { + tests := []struct { + name string + input []proto.Metadata + expected *objectRef + }{ + { + name: "nil", + }, + { + // If calling KObjSlice called methods, it would hurt performance + // as unmarshalling is very expensive in wasm. + name: "doesn't call methods", + input: []proto.Metadata{panicMetadata{}}, + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + if want, have := tc.input, KObjSlice(tc.input).(*kobjSlice[proto.Metadata]).objs; !reflect.DeepEqual(want, have) { + t.Fatalf("unexpected refs: %v != %v", want, have) + } + }) + } +} + +func TestKObjSliceFn(t *testing.T) { + t.Run("nil", func(t *testing.T) { + have := KObjSliceFn((func() []proto.Metadata)(nil)) + if have.(*kObjSliceFn[proto.Metadata]).fn != nil { + t.Fatalf("unexpected fn: %v", have) + } + if want, have := "[]", have.String(); want != have { + t.Fatalf("unexpected string: %v != %v", want, have) + } + }) + + // If creating a KObjSliceFn called Get, it would hurt performance as + // unmarshalling is very expensive in wasm. + t.Run("doesn't call methods", func(t *testing.T) { + lazySlice := panicLazySlice{} + have := KObjSliceFn(lazySlice.Get) + if lazySlice.called == true { + t.Fatalf("unexpected call to items") + } + if want, have := "[good-pod]", have.String(); want != have { + t.Fatalf("unexpected string: %v != %v", want, have) + } + }) +} + +type panicLazySlice struct{ called bool } + +func (panicLazySlice) Get() []proto.Metadata { + return []proto.Metadata{&testMetadata{Name: "good-pod"}} +} + +func TestKObj_String(t *testing.T) { + tests := []struct { + name string + input fmt.Stringer + expected string + }{ + { + name: "nil -> empty", + input: KObj(nil), + }, + { + name: "empty -> empty", + input: KObj(&testMetadata{}), + }, + { + name: "name but not ns", + input: KObj(&testMetadata{Name: "good-pod"}), + expected: "good-pod", + }, + { + name: "ns but not name", + input: KObj(&testMetadata{Namespace: "test"}), + expected: "test/", + }, + { + name: "all", + input: KObj(&testMetadata{ + Name: "good-pod", + Namespace: "test", + UID: "384900cd-dc7b-41ec-837e-9c4c1762363e", + }), + expected: "test/good-pod", + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + if want, have := tc.expected, tc.input.String(); want != have { + t.Fatalf("unexpected string: %v != %v", want, have) + } + }) + } +} + +func Test_sliceString(t *testing.T) { + tests := []struct { + name string + input []proto.Metadata + expected string + }{ + { + name: "nil -> empty slice", + input: nil, + expected: "[]", + }, + { + name: "empty -> empty slice", + input: []proto.Metadata{&testMetadata{}}, + expected: "[]", + }, + { + name: "name but not ns", + input: []proto.Metadata{&testMetadata{Name: "good-pod"}}, + expected: "[good-pod]", + }, + { + name: "ns but not name", + input: []proto.Metadata{&testMetadata{Namespace: "test"}}, + expected: "[test/]", + }, + { + name: "all", + input: []proto.Metadata{ + &testMetadata{ + Name: "good-pod", + Namespace: "test", + UID: "384900cd-dc7b-41ec-837e-9c4c1762363e", + }, + }, + expected: "[test/good-pod]", + }, + { + name: "multiple", + input: []proto.Metadata{ + &testMetadata{ + Name: "good-pod", + Namespace: "test", + UID: "384900cd-dc7b-41ec-837e-9c4c1762363e", + }, + &testMetadata{Name: "bad-pod"}, + }, + expected: "[test/good-pod bad-pod]", + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + if want, have := tc.expected, kobjSliceString(tc.input); want != have { + t.Fatalf("unexpected string: %v != %v", want, have) + } + }) + } +} diff --git a/guest/klog/api/klog.go b/guest/klog/api/klog.go new file mode 100644 index 00000000..0b021fe2 --- /dev/null +++ b/guest/klog/api/klog.go @@ -0,0 +1,69 @@ +/* + Copyright 2023 The Kubernetes Authors. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ + +package api + +// Klog is a logger that exposes functions typically in the klog package. +// +// This contains functions like klog.Info, but allows flexibility to disable +// logging in WebAssembly, where it is more expensive due to inlined garbage +// collection. +// +// Note: Embed UnimplementedKlog when implementing for real or test usage. +type Klog interface { + // Info records an event at INFO level. + // + // The event is a concatenation of the arguments. A newline is appended when + // the last arg doesn't already end with one. + // + // # Notes + // + // - See Klog godoc for an example. + // - Wrap args in objectRef where possible, to normalize the output of types + // such as proto.Pod. + Info(args ...any) + + // InfoS is like klog.InfoS. This records the description of an event, + // `msg` followed by key/value pairs to describe it. + // + // # Notes + // + // - See Klog godoc for an example. + // - Wrap values in objectRef where possible, to normalize the output of types + // such as proto.Pod. + InfoS(msg string, keysAndValues ...any) + + // Error is like Info, except ERROR level. + Error(args ...any) + + // ErrorS is like InfoS, except ERROR level. Also, the `err` parameter + // becomes the value of the "err" key in `keysAndValues`. + ErrorS(err error, msg string, keysAndValues ...any) +} + +type UnimplementedKlog struct{} + +// Info implements Klog.Info +func (UnimplementedKlog) Info(args ...any) {} + +// InfoS implements Klog.InfoS +func (UnimplementedKlog) InfoS(msg string, keysAndValues ...any) {} + +// Error implements Klog.Error +func (UnimplementedKlog) Error(args ...any) {} + +// ErrorS implements Klog.ErrorS +func (UnimplementedKlog) ErrorS(err error, msg string, keysAndValues ...any) {} diff --git a/guest/klog/api/klog_test.go b/guest/klog/api/klog_test.go new file mode 100644 index 00000000..9040a8a8 --- /dev/null +++ b/guest/klog/api/klog_test.go @@ -0,0 +1,50 @@ +/* + Copyright 2023 The Kubernetes Authors. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ + +package api_test + +import ( + "fmt" + + "sigs.k8s.io/kube-scheduler-wasm-extension/guest/api/proto" + "sigs.k8s.io/kube-scheduler-wasm-extension/guest/klog/api" +) + +var ( + klog api.Klog = api.UnimplementedKlog{} + pod proto.Pod +) + +func ExampleKlog() { + klog.Info("NodeNumberArgs is successfully applied") + + // For structured logging, use pairs, wrapping values in api.KObj where possible. + klog.InfoS("execute Score on NodeNumber plugin", "pod", api.KObj(pod)) + + metricName := "scheduler_framework_extension_point_duration_milliseconds" + err := fmt.Errorf("metric %q not found", metricName) + klog.Error(err) + + bucketSize := 32 + histBucketSize := 16 + index := 2 + err = fmt.Errorf("found different bucket size: expect %v, but got %v at index %v", bucketSize, histBucketSize, index) + labels := map[string]string{"Name": "some-name"} + klog.ErrorS(err, "the validation for HistogramVec is failed. The data for this metric won't be stored in a benchmark result file", "metric", metricName, "labels", labels) + + // Output: + // +} diff --git a/guest/klog/imports.go b/guest/klog/imports.go new file mode 100644 index 00000000..4a452f5c --- /dev/null +++ b/guest/klog/imports.go @@ -0,0 +1,30 @@ +//go:build tinygo.wasm + +/* + Copyright 2023 The Kubernetes Authors. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ + +package klog + +import "sigs.k8s.io/kube-scheduler-wasm-extension/guest/klog/internal" + +//go:wasmimport k8s.io/klog log +func log(severity internal.Severity, ptr, size uint32) + +//go:wasmimport k8s.io/klog logs +func logs(severity internal.Severity, msgPtr, msgSize, kvsPtr, kvsSize uint32) + +//go:wasmimport k8s.io/klog severity +func severity() internal.Severity diff --git a/guest/klog/imports_stub.go b/guest/klog/imports_stub.go new file mode 100644 index 00000000..bf5baedd --- /dev/null +++ b/guest/klog/imports_stub.go @@ -0,0 +1,30 @@ +//go:build !tinygo.wasm + +/* + Copyright 2023 The Kubernetes Authors. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ + +package klog + +import "sigs.k8s.io/kube-scheduler-wasm-extension/guest/klog/internal" + +// log is stubbed for compilation outside TinyGo. +func log(severity internal.Severity, ptr, size uint32) {} + +// logs is stubbed for compilation outside TinyGo. +func logs(severity internal.Severity, msgPtr, msgSize, kvsPtr, kvsSize uint32) {} + +// severity is stubbed for compilation outside TinyGo. +func severity() (severity internal.Severity) { return } diff --git a/guest/klog/internal/klog.go b/guest/klog/internal/klog.go new file mode 100644 index 00000000..587ba5c6 --- /dev/null +++ b/guest/klog/internal/klog.go @@ -0,0 +1,138 @@ +/* + Copyright 2023 The Kubernetes Authors. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ + +// Package internal allows unit testing without requiring wasm imports. +package internal + +import ( + "bytes" + "fmt" + "strings" + + "sigs.k8s.io/kube-scheduler-wasm-extension/guest/klog/api" +) + +// Severity is the same as severity.Severity in klog +type Severity = int32 + +const ( + InfoLog Severity = iota + WarningLog + ErrorLog + FatalLog +) + +type Klog struct { + api.UnimplementedKlog + + Severity + LogFn func(severity Severity, msg []byte) + LogSFn func(severity Severity, msg string, kvs []byte) +} + +// Info implements the same method as documented on api.Klog. +func (k *Klog) Info(args ...any) { + k.log(InfoLog, args) +} + +// Error implements the same method as documented on api.Klog. +func (k *Klog) Error(args ...any) { + k.log(ErrorLog, args) +} + +// InfoS implements the same method as documented on api.Klog. +func (k *Klog) InfoS(msg string, keysAndValues ...any) { + k.logs(InfoLog, msg, keysAndValues) +} + +// ErrorS implements the same method as documented on api.Klog. +func (k *Klog) ErrorS(err error, msg string, keysAndValues ...any) { + if err != nil { + errKV := [2]any{"err", err} + keysAndValues = append(errKV[:], keysAndValues...) + } + k.logs(ErrorLog, msg, keysAndValues) +} + +// log coerces the args to a string and logs them, when the severity is loggable. +func (k *Klog) log(severity Severity, args []any) { + if severity < k.Severity { + return // don't incur host call overhead + } + msg := logString(args) + k.LogFn(severity, msg) +} + +// logs encodes `keysAndValues` as a NUL-terminated string, when the severity +// is loggable. +func (k *Klog) logs(severity Severity, msg string, keysAndValues []any) { + if severity < k.Severity { + return // don't incur host call overhead + } + k.LogSFn(severity, msg, logKVs(keysAndValues)) +} + +// buf is a reusable unbounded buffer. +var buf bytes.Buffer + +// logString returns the bytes representing the args joined like Klog.Info. +func logString(args []any) []byte { + buf.Reset() + _, _ = fmt.Fprint(&buf, args...) + if buf.Len() == 0 || buf.Bytes()[buf.Len()-1] != '\n' { + buf.WriteByte('\n') + } + return buf.Bytes() +} + +// logKVs makes a NUL-terminated string of values +func logKVs(kvs []any) []byte { + buf.Reset() + + count := len(kvs) + if count == 0 { + return nil + } + + for i := 0; i < count; i++ { + var s string + if i%2 == 0 { // key + switch k := kvs[i].(type) { + case string: + s = k + default: + s = fmt.Sprintf("%s", k) + } + } else { // value + switch v := kvs[i].(type) { + case fmt.Stringer: + s = v.String() + case string: + s = v + case error: + s = v.Error() + default: + s = fmt.Sprintf("%s", v) + } + } + if strings.ContainsRune(s, '\x00') { + panic(fmt.Errorf("invalid log message %q", s)) + } + buf.WriteString(s) + buf.WriteByte(0) // NUL-terminator + } + return buf.Bytes() +} diff --git a/guest/klog/internal/klog_test.go b/guest/klog/internal/klog_test.go new file mode 100644 index 00000000..98f9dc4a --- /dev/null +++ b/guest/klog/internal/klog_test.go @@ -0,0 +1,283 @@ +/* + Copyright 2023 The Kubernetes Authors. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ + +package internal + +import ( + "errors" + "reflect" + "strings" + "testing" + + "sigs.k8s.io/kube-scheduler-wasm-extension/guest/klog/api" +) + +func TestLog(t *testing.T) { + tests := []struct { + name string + severity Severity + input func(api.Klog) + expectedSeverity Severity + expectedMsg string + }{ + { + name: "nothing", + input: func(klog api.Klog) { + klog.Info() + }, + expectedSeverity: InfoLog, + expectedMsg: "\n", + }, + { + name: "adds newline", + input: func(klog api.Klog) { + klog.Info("hello world") + }, + expectedSeverity: InfoLog, + expectedMsg: "hello world\n", + }, + { + name: "Error", + severity: ErrorLog, + input: func(klog api.Klog) { + klog.Error("hello world") + }, + expectedSeverity: ErrorLog, + expectedMsg: "hello world\n", + }, + { + name: "Info: disabled", + severity: ErrorLog, + input: func(klog api.Klog) { + klog.Info("hello world") + }, + }, + { + name: "Error: disabled", + severity: FatalLog, + input: func(klog api.Klog) { + klog.Error("hello world") + }, + }, + { + name: "no spaces between strings", + input: func(klog api.Klog) { + klog.Info("1", "2") + }, + expectedSeverity: InfoLog, + expectedMsg: "12\n", + }, + { + name: "spaces between non-strings", + input: func(klog api.Klog) { + klog.Info(1, 2) + }, + expectedSeverity: InfoLog, + expectedMsg: "1 2\n", + }, + { + name: "newline terminated", + input: func(klog api.Klog) { + klog.Info("hello", "\n") + }, + expectedSeverity: InfoLog, + expectedMsg: "hello\n", + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + defer func() { + buf.Reset() + }() + + var severity Severity + var msg string + klog := &Klog{ + Severity: tc.severity, + LogFn: func(s Severity, m []byte) { + severity = s + msg = string(m) + }, + } + tc.input(klog) + if want, have := tc.expectedSeverity, severity; want != have { + t.Fatalf("unexpected severity: %v != %v", want, have) + } + if want, have := tc.expectedMsg, msg; want != have { + t.Fatalf("unexpected msg: %v != %v", want, have) + } + }) + } +} + +func TestLogS(t *testing.T) { + tests := []struct { + name string + severity Severity + input func(api.Klog) + expectedSeverity Severity + expectedMsg string + expectedKVs []string + }{ + { + name: "nothing", + input: func(klog api.Klog) { + klog.InfoS("") + }, + expectedSeverity: InfoLog, + expectedMsg: "", + }, + { + name: "ErrorS nil error", + severity: ErrorLog, + input: func(klog api.Klog) { + klog.ErrorS(nil, "hello world") + }, + expectedSeverity: ErrorLog, + expectedMsg: "hello world", + }, + { + name: "ErrorS empty error", + severity: ErrorLog, + input: func(klog api.Klog) { + klog.ErrorS(errors.New(""), "hello world") + }, + expectedSeverity: ErrorLog, + expectedMsg: "hello world", + expectedKVs: []string{"err", ""}, + }, + { + name: "ErrorS empty msg", + severity: ErrorLog, + input: func(klog api.Klog) { + klog.ErrorS(errors.New("error"), "") + }, + expectedSeverity: ErrorLog, + expectedKVs: []string{"err", "error"}, + }, + { + name: "InfoS: disabled", + severity: ErrorLog, + input: func(klog api.Klog) { + klog.InfoS("hello world") + }, + }, + { + name: "ErrorS: disabled", + severity: FatalLog, + input: func(klog api.Klog) { + klog.ErrorS(nil, "hello world") + }, + }, + { + name: "kvs: strings", + input: func(klog api.Klog) { + klog.InfoS("", "a", "1") + }, + expectedSeverity: InfoLog, + expectedKVs: []string{"a", "1"}, + }, + { + name: "kvs: duplicated", // host will decide what to do + input: func(klog api.Klog) { + klog.InfoS("", "a", "1", "a", "1") + }, + expectedSeverity: InfoLog, + expectedKVs: []string{"a", "1", "a", "1"}, + }, + { + name: "kvs: fmt.Stringer", + input: func(klog api.Klog) { + klog.InfoS("", "pod", api.KObj(podSmall{})) + }, + expectedSeverity: InfoLog, + expectedKVs: []string{"pod", "test/good-pod"}, + }, + { + name: "kvs: struct", + input: func(klog api.Klog) { + klog.InfoS("", "pod", podSmall{}) + }, + expectedSeverity: InfoLog, + expectedKVs: []string{"pod", "{}"}, + }, + { + name: "kvs: redundant error", + input: func(klog api.Klog) { + klog.ErrorS(errors.New("ice"), "", "err", errors.New("cream")) + }, + expectedSeverity: ErrorLog, + expectedKVs: []string{"err", "ice", "err", "cream"}, + }, + { + name: "kvs: non-strings", + input: func(klog api.Klog) { + klog.InfoS("", 1, 2) + }, + expectedSeverity: InfoLog, + expectedKVs: []string{"%!s(int=1)", "%!s(int=2)"}, + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + defer func() { + buf.Reset() + }() + + var severity Severity + var msg string + var kvs []string + klog := &Klog{ + Severity: tc.severity, + LogSFn: func(s Severity, m string, kvBytes []byte) { + severity = s + msg = m + if len(kvBytes) != 0 { + // strip the last NUL character + kvBytes = kvBytes[:len(kvBytes)-1] + kvs = strings.Split(string(kvBytes), string('\x00')) + } + }, + } + tc.input(klog) + if want, have := tc.expectedSeverity, severity; want != have { + t.Fatalf("unexpected severity: %v != %v", want, have) + } + if want, have := tc.expectedMsg, msg; want != have { + t.Fatalf("unexpected msg: %v != %v", want, have) + } + if want, have := tc.expectedKVs, kvs; !reflect.DeepEqual(want, have) { + t.Fatalf("unexpected kvs: %v != %v", want, have) + } + }) + } +} + +type podSmall struct{} + +func (podSmall) GetName() string { + return "good-pod" +} + +func (podSmall) GetNamespace() string { + return "test" +} + +func (podSmall) GetUid() string { + return "384900cd-dc7b-41ec-837e-9c4c1762363e" +} diff --git a/guest/klog/klog.go b/guest/klog/klog.go new file mode 100644 index 00000000..ea6817e7 --- /dev/null +++ b/guest/klog/klog.go @@ -0,0 +1,114 @@ +/* + Copyright 2023 The Kubernetes Authors. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ + +package klog + +import ( + "fmt" + "runtime" + + "sigs.k8s.io/kube-scheduler-wasm-extension/guest/api/proto" + "sigs.k8s.io/kube-scheduler-wasm-extension/guest/internal/mem" + "sigs.k8s.io/kube-scheduler-wasm-extension/guest/klog/api" + "sigs.k8s.io/kube-scheduler-wasm-extension/guest/klog/internal" +) + +// Get can be called at any time, to get a logger that writes to the +// WebAssembly host. +// +// For example: +// +// func main() { +// klog := klog.Get() +// klog.Info("hello", "world") +// } +func Get() api.Klog { + return instance +} + +var instance api.Klog = &internal.Klog{ + Severity: severity(), + LogFn: logFn, + LogSFn: logSFn, +} + +func logFn(severity internal.Severity, msg []byte) { + ptr, size := mem.BytesToPtr(msg) + log(severity, ptr, size) + runtime.KeepAlive(msg) // keep msg alive until ptr is no longer needed. +} + +func logSFn(severity internal.Severity, msg string, kvs []byte) { + msgPtr, msgSize := mem.StringToPtr(msg) + kvsPtr, kvsSize := mem.BytesToPtr(kvs) + logs(severity, msgPtr, msgSize, kvsPtr, kvsSize) + runtime.KeepAlive(msg) // keep msg alive until ptr is no longer needed. + runtime.KeepAlive(kvs) // keep kvs alive until ptr is no longer needed. +} + +// KObj is a convenience that calls api.KObj. This is re-declared here for +// familiarity. +// +// Note: See Info for unit test and benchmarking impact. +func KObj(obj proto.Metadata) fmt.Stringer { + return api.KObj(obj) +} + +// KObjSlice is a convenience that calls api.KObjSlice. This is re-declared +// here for familiarity. +// +// Note: See Info for unit test and benchmarking impact. +func KObjSlice[M proto.Metadata](objs []M) fmt.Stringer { + return api.KObjSlice(objs) +} + +// KObjSliceFn is a convenience that calls api.KObjSliceFn. This is re-declared here +// for familiarity. +// +// Note: See Info for unit test and benchmarking impact. +func KObjSliceFn[M proto.Metadata](lazy func() []M) fmt.Stringer { + return api.KObjSliceFn(lazy) +} + +// Info is a convenience that calls the same method documented on api.Klog. +// +// Note: Code that uses can be unit tested in normal Go, but cannot be unit +// tested or benchmarked via `tinygo test -target=wasi`. To avoid this problem, +// use Get instead. +func Info(args ...any) { + instance.Info(args...) +} + +// InfoS is a convenience that calls the same method documented on api.Klog. +// +// Note: See Info for unit test and benchmarking impact. +func InfoS(msg string, keysAndValues ...any) { + instance.InfoS(msg, keysAndValues...) +} + +// Error is a convenience that calls the same method documented on api.Klog. +// +// Note: See Info for unit test and benchmarking impact. +func Error(args ...any) { + instance.Error(args...) +} + +// ErrorS is a convenience that calls the same method documented on api.Klog. +// +// Note: See Info for unit test and benchmarking impact. +func ErrorS(err error, msg string, keysAndValues ...any) { + instance.ErrorS(err, msg, keysAndValues...) +} diff --git a/guest/klog/klog_test.go b/guest/klog/klog_test.go new file mode 100644 index 00000000..898f2707 --- /dev/null +++ b/guest/klog/klog_test.go @@ -0,0 +1,69 @@ +//go:build !tinygo.wasm + +/* + Copyright 2023 The Kubernetes Authors. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ + +// Package klog_test ensures that even though this package can't be tested with +// `tinygo test -target=wasi`, due to imports required, it can be tested with +// normal Go (due to stubbed implementation). +package klog_test + +import ( + "fmt" + + "sigs.k8s.io/kube-scheduler-wasm-extension/guest/api/proto" + "sigs.k8s.io/kube-scheduler-wasm-extension/guest/klog" + klogapi "sigs.k8s.io/kube-scheduler-wasm-extension/guest/klog/api" +) + +func ExampleInfo() { + klog.Info("NodeNumberArgs is successfully applied") + + // Output: + // +} + +var pod proto.Pod + +func ExampleInfoS() { + klog.InfoS("execute Score on NodeNumber plugin", "pod", klogapi.KObj(pod)) + + // Output: + // +} + +func ExampleError() { + metricName := "scheduler_framework_extension_point_duration_milliseconds" + err := fmt.Errorf("metric %q not found", metricName) + klog.Error(err) + + // Output: + // +} + +func ExampleErrorS() { + bucketSize := 32 + histBucketSize := 16 + index := 2 + err := fmt.Errorf("found different bucket size: expect %v, but got %v at index %v", bucketSize, histBucketSize, index) + metricName := "scheduler_framework_extension_point_duration_milliseconds" + labels := map[string]string{"Name": "some-name"} + + klog.ErrorS(err, "the validation for HistogramVec is failed. The data for this metric won't be stored in a benchmark result file", "metric", metricName, "labels", labels) + + // Output: + // +} diff --git a/guest/testdata/all/main.go b/guest/testdata/all/main.go deleted file mode 100644 index 065060f5..00000000 --- a/guest/testdata/all/main.go +++ /dev/null @@ -1,104 +0,0 @@ -/* - Copyright 2023 The Kubernetes Authors. - - Licensed under the Apache License, Version 2.0 (the "License"); - you may not use this file except in compliance with the License. - You may obtain a copy of the License at - - http://www.apache.org/licenses/LICENSE-2.0 - - Unless required by applicable law or agreed to in writing, software - distributed under the License is distributed on an "AS IS" BASIS, - WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - See the License for the specific language governing permissions and - limitations under the License. -*/ - -package main - -import ( - "os" - - "sigs.k8s.io/kube-scheduler-wasm-extension/guest/api" - "sigs.k8s.io/kube-scheduler-wasm-extension/guest/api/proto" - "sigs.k8s.io/kube-scheduler-wasm-extension/guest/enqueue" - "sigs.k8s.io/kube-scheduler-wasm-extension/guest/filter" - "sigs.k8s.io/kube-scheduler-wasm-extension/guest/prefilter" - "sigs.k8s.io/kube-scheduler-wasm-extension/guest/score" -) - -type extensionPoints interface { - api.EnqueueExtensions - api.PreFilterPlugin - api.FilterPlugin - api.ScorePlugin -} - -func main() { - // Multiple tests are here to reduce re-compilation time and size checked - // into git. - var plugin extensionPoints - if len(os.Args) == 2 && os.Args[1] == "params" { - plugin = paramsPlugin{} - } else { - plugin = noopPlugin{} - } - - enqueue.SetPlugin(plugin) - prefilter.SetPlugin(plugin) - filter.SetPlugin(plugin) - score.SetPlugin(plugin) -} - -// noopPlugin doesn't do anything, and this style isn't recommended. This shows the -// impact two things: -// -// - implementing multiple interfaces -// - overhead of constructing function parameters -type noopPlugin struct{} - -func (noopPlugin) EventsToRegister() (clusterEvents []api.ClusterEvent) { return } - -func (noopPlugin) PreFilter(api.CycleState, proto.Pod) (nodeNames []string, status *api.Status) { - return -} - -func (noopPlugin) Filter(api.CycleState, proto.Pod, api.NodeInfo) (status *api.Status) { return } - -func (noopPlugin) Score(api.CycleState, proto.Pod, string) (score int32, status *api.Status) { return } - -// paramsPlugin doesn't do anything, except evaluate each parameter. This shows -// if protobuf unmarshal caching works (for the pod), and also baseline -// performance of reading each parameter. -type paramsPlugin struct{} - -func (paramsPlugin) EventsToRegister() (clusterEvents []api.ClusterEvent) { - return -} - -func (paramsPlugin) PreFilter(state api.CycleState, pod proto.Pod) (nodeNames []string, status *api.Status) { - _, _ = state.Read("ok") - _ = pod.Spec() - return -} - -func (paramsPlugin) Filter(state api.CycleState, pod proto.Pod, nodeInfo api.NodeInfo) (status *api.Status) { - _, _ = state.Read("ok") - _ = pod.Spec() - _ = nodeInfo.Node().Spec() // trigger lazy loading - return -} - -func (paramsPlugin) PreScore(state api.CycleState, pod proto.Pod, nodeList proto.NodeList) *api.Status { - _, _ = state.Read("ok") - _ = pod.Spec() - _ = nodeList.Items() - return nil -} - -func (paramsPlugin) Score(state api.CycleState, pod proto.Pod, nodeName string) (score int32, status *api.Status) { - _, _ = state.Read("ok") - _ = pod.Spec() - _ = nodeName - return -} diff --git a/guest/testdata/all/main.wasm b/guest/testdata/all/main.wasm deleted file mode 100755 index 7de9924e..00000000 Binary files a/guest/testdata/all/main.wasm and /dev/null differ diff --git a/guest/testdata/filter/main.wasm b/guest/testdata/filter/main.wasm index 17741fda..bc2802c7 100755 Binary files a/guest/testdata/filter/main.wasm and b/guest/testdata/filter/main.wasm differ diff --git a/internal/e2e/guest/go.mod b/internal/e2e/guest/go.mod index d0deff8c..7a4b2a4e 100644 --- a/internal/e2e/guest/go.mod +++ b/internal/e2e/guest/go.mod @@ -3,12 +3,12 @@ module sigs.k8s.io/kube-scheduler-wasm-extension/internal/e2e/guest go 1.20 require ( - github.com/wasilibs/nottinygc v0.3.0 + github.com/wasilibs/nottinygc v0.4.0 + sigs.k8s.io/kube-scheduler-wasm-extension/guest v0.0.0-00010101000000-000000000000 sigs.k8s.io/kube-scheduler-wasm-extension/kubernetes/proto v0.0.0-00010101000000-000000000000 ) require ( - github.com/google/go-cmp v0.5.9 // indirect github.com/magefile/mage v1.14.0 // indirect google.golang.org/protobuf v1.30.0 // indirect ) diff --git a/internal/e2e/guest/go.sum b/internal/e2e/guest/go.sum index 478a14ba..f69bfb90 100644 --- a/internal/e2e/guest/go.sum +++ b/internal/e2e/guest/go.sum @@ -1,11 +1,10 @@ github.com/golang/protobuf v1.5.0/go.mod h1:FsONVRAS9T7sI+LIUmWTfcYkHO4aIWwzhcaSAoJOfIk= github.com/google/go-cmp v0.5.5/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE= github.com/google/go-cmp v0.5.9 h1:O2Tfq5qg4qc4AmwVlvv0oLiVAGB7enBSJ2x2DqQFi38= -github.com/google/go-cmp v0.5.9/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY= github.com/magefile/mage v1.14.0 h1:6QDX3g6z1YvJ4olPhT1wksUcSa/V0a1B+pJb73fBjyo= github.com/magefile/mage v1.14.0/go.mod h1:z5UZb/iS3GoOSn0JgWuiw7dxlurVYTu+/jHXqQg881A= -github.com/wasilibs/nottinygc v0.3.0 h1:0L1jsJ1MsyN5tdinmFbLfuEA0TnHRcqaBM9pDTJVJmU= -github.com/wasilibs/nottinygc v0.3.0/go.mod h1:oDcIotskuYNMpqMF23l7Z8uzD4TC0WXHK8jetlB3HIo= +github.com/wasilibs/nottinygc v0.4.0 h1:h1TJMihMC4neN6Zq+WKpLxgd9xCFMw7O9ETLwY2exJQ= +github.com/wasilibs/nottinygc v0.4.0/go.mod h1:oDcIotskuYNMpqMF23l7Z8uzD4TC0WXHK8jetlB3HIo= golang.org/x/xerrors v0.0.0-20191204190536-9bdfabe68543/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0= google.golang.org/protobuf v1.26.0-rc.1/go.mod h1:jlhhOSvTdKEhbULTjvd4ARK9grFBp09yW+WbY/TyQbw= google.golang.org/protobuf v1.30.0 h1:kPPoIgf3TsEvrm0PFe15JQ+570QVxYzEvvHqChK+cng= diff --git a/internal/e2e/guest/guest_test.go b/internal/e2e/guest/guest_test.go index 4bc0e1c7..9d6c239e 100644 --- a/internal/e2e/guest/guest_test.go +++ b/internal/e2e/guest/guest_test.go @@ -19,10 +19,13 @@ package guest_test // Override the default GC with a more performant one. // Note: this requires tinygo flags: -gc=custom -tags=custommalloc import ( + "fmt" "testing" _ "github.com/wasilibs/nottinygc" + "sigs.k8s.io/kube-scheduler-wasm-extension/guest/api/proto" + klogapi "sigs.k8s.io/kube-scheduler-wasm-extension/guest/klog/api" protoapi "sigs.k8s.io/kube-scheduler-wasm-extension/kubernetes/proto/api" meta "sigs.k8s.io/kube-scheduler-wasm-extension/kubernetes/proto/meta" ) @@ -38,6 +41,72 @@ var podSmall = &protoapi.Pod{ Spec: &protoapi.PodSpec{NodeName: nodeSmall.Metadata.Name}, } +var _ proto.Metadata = &testMetadata{} + +type testMetadata struct { + Name, Namespace, UID string +} + +func (t *testMetadata) GetName() string { + return t.Name +} + +func (t *testMetadata) GetNamespace() string { + return t.Namespace +} + +func (t *testMetadata) GetUid() string { + return t.UID +} + +type stringerFunc func() string + +func (s stringerFunc) String() string { + return s() +} + +// BenchmarkKlog shows that slice functions like api.KObjSlice are more optimal +// than doing concatenation manually. +func BenchmarkKlog(b *testing.B) { + pod := &testMetadata{ + Name: "good-pod", + Namespace: "test", + UID: "384900cd-dc7b-41ec-837e-9c4c1762363e", + } + + benches := []struct { + name string + input fmt.Stringer + }{ + { + name: "KObj", + input: stringerFunc(func() string { + return fmt.Sprint("[", klogapi.KObj(pod), klogapi.KObj(pod), "]") + }), + }, + { + name: "KObjSlice", + input: klogapi.KObjSlice([]proto.Metadata{pod, pod}), + }, + { + name: "KObjSliceFn", + input: klogapi.KObjSliceFn(func() []proto.Metadata { + return []proto.Metadata{pod, pod} + }), + }, + } + + for _, bc := range benches { + b.Run(bc.name, func(b *testing.B) { + b.ResetTimer() + + for i := 0; i < b.N; i++ { + _ = bc.input.String() + } + }) + } +} + func BenchmarkUnmarshalVT(b *testing.B) { unmarshalNode := func(data []byte) error { var msg protoapi.Node @@ -51,7 +120,7 @@ func BenchmarkUnmarshalVT(b *testing.B) { // TODO: Find a way to convert yaml to proto in a way that compiles in // TinyGo, so that we can use real data. Or check in the serialized protos. - tests := []struct { + benches := []struct { name string input []byte unmarshal func(data []byte) error @@ -68,12 +137,12 @@ func BenchmarkUnmarshalVT(b *testing.B) { }, } - for _, tc := range tests { - b.Run(tc.name, func(b *testing.B) { + for _, bc := range benches { + b.Run(bc.name, func(b *testing.B) { b.ResetTimer() for i := 0; i < b.N; i++ { - if err := tc.unmarshal(tc.input); err != nil { + if err := bc.unmarshal(bc.input); err != nil { b.Fatal(err) } } diff --git a/internal/e2e/scheduler/scheduler_test.go b/internal/e2e/scheduler/scheduler_test.go index c65b9ee5..3c89846a 100644 --- a/internal/e2e/scheduler/scheduler_test.go +++ b/internal/e2e/scheduler/scheduler_test.go @@ -17,12 +17,17 @@ package scheduler_test import ( + "bytes" "context" "fmt" "io" + "strings" "testing" v1 "k8s.io/api/core/v1" + v1meta "k8s.io/apimachinery/pkg/apis/meta/v1" + "k8s.io/klog/v2" + k8stest "k8s.io/klog/v2/test" "k8s.io/kubernetes/pkg/scheduler/framework" "sigs.k8s.io/kube-scheduler-wasm-extension/internal/e2e" @@ -30,8 +35,8 @@ import ( "sigs.k8s.io/kube-scheduler-wasm-extension/scheduler/test" ) -// TestGuest_CycleStateCoherence ensures cycle state data is coherent in a -// scheduling context. +// TestCycleStateCoherence ensures cycle state data is coherent in a scheduling +// context. func TestCycleStateCoherence(t *testing.T) { ctx := context.Background() @@ -61,63 +66,111 @@ func TestExample_NodeNumber(t *testing.T) { } func testExample_NodeNumber(t *testing.T, advanced bool) { + // Reinit klog for tests. + fs := k8stest.InitKlog(t) + + // Disable timestamps. + fs.Set("skip_headers", "true") //nolint + ctx := context.Background() - plugin := newNodeNumberPlugin(ctx, t, advanced, false) + plugin := newNodeNumberPlugin(ctx, t, advanced, false, 0) defer plugin.(io.Closer).Close() - pod := &v1.Pod{Spec: v1.PodSpec{NodeName: "happy8"}} + pod := &v1.Pod{ObjectMeta: v1meta.ObjectMeta{Name: "happy8-meta"}, Spec: v1.PodSpec{NodeName: "happy8"}} t.Run("Score zero on unmatch", func(t *testing.T) { // The pod spec node name doesn't end with the same number as the node, so // we expect to score zero. + var buf bytes.Buffer + klog.SetOutput(&buf) + score := e2e.RunAll(ctx, t, plugin, pod, nodeInfoWithName("glad9")) if want, have := int64(0), score; want != have { t.Fatalf("unexpected score: want %v, have %v", want, have) } + + want := `"execute PreScore on NodeNumber plugin" pod="happy8-meta" +"execute Score on NodeNumber plugin" pod="happy8-meta" +` // klog always adds newline + if have := buf.String(); want != have { + t.Fatalf("unexpected log: want %v, have %v", want, have) + } }) t.Run("Score ten on match", func(t *testing.T) { // The pod spec node name isn't the same as the node name. However, // they both end in the same number, so we expect to score ten. + var buf bytes.Buffer + klog.SetOutput(&buf) + score := e2e.RunAll(ctx, t, plugin, pod, nodeInfoWithName("glad8")) if want, have := int64(10), score; want != have { t.Fatalf("unexpected score: want %v, have %v", want, have) } + + wantLog := `"execute PreScore on NodeNumber plugin" pod="happy8-meta" +"execute Score on NodeNumber plugin" pod="happy8-meta"` + if wantLog != strings.TrimSpace(buf.String()) { + t.Fatalf("unexpected log: want %v, have %v", wantLog, buf.String()) + } }) t.Run("Reverse means score zero on match", func(t *testing.T) { // This proves we can read configuration. - reversed := newNodeNumberPlugin(ctx, t, advanced, true) + var buf bytes.Buffer + klog.SetOutput(&buf) + + reversed := newNodeNumberPlugin(ctx, t, advanced, true, 0) defer reversed.(io.Closer).Close() score := e2e.RunAll(ctx, t, reversed, pod, nodeInfoWithName("glad8")) if want, have := int64(0), score; want != have { t.Fatalf("unexpected score: want %v, have %v", want, have) } + + wantLog := `NodeNumberArgs is successfully applied +"execute PreScore on NodeNumber plugin" pod="happy8-meta" +"execute Score on NodeNumber plugin" pod="happy8-meta"` + if wantLog != strings.TrimSpace(buf.String()) { + t.Fatalf("unexpected log: want %v, have %v", wantLog, buf.String()) + } }) } func BenchmarkExample_NodeNumber(b *testing.B) { b.Run("Simple", func(b *testing.B) { - benchmarkExample_NodeNumber(b, false) + benchmarkExample_NodeNumber(b, false, 3) + }) + b.Run("Simple Log", func(b *testing.B) { + benchmarkExample_NodeNumber(b, false, 0) }) b.Run("Advanced", func(b *testing.B) { - benchmarkExample_NodeNumber(b, true) + benchmarkExample_NodeNumber(b, true, 3) + }) + b.Run("Advanced Log", func(b *testing.B) { + benchmarkExample_NodeNumber(b, true, 0) }) } -func benchmarkExample_NodeNumber(b *testing.B, advanced bool) { +func benchmarkExample_NodeNumber(b *testing.B, advanced bool, logSeverity int32) { b.Helper() + // Reinit klog for tests. + fs := k8stest.InitKlog(b) + // Disable timestamps. + fs.Set("skip_headers", "true") //nolint + + klog.SetOutput(io.Discard) + ctx := context.Background() b.Run("New", func(b *testing.B) { b.ResetTimer() for i := 0; i < b.N; i++ { - newNodeNumberPlugin(ctx, b, advanced, false).(io.Closer).Close() + newNodeNumberPlugin(ctx, b, advanced, false, logSeverity).(io.Closer).Close() } }) - plugin := newNodeNumberPlugin(ctx, b, advanced, false) + plugin := newNodeNumberPlugin(ctx, b, advanced, false, logSeverity) defer plugin.(io.Closer).Close() pod := *test.PodReal // copy @@ -134,7 +187,7 @@ func benchmarkExample_NodeNumber(b *testing.B, advanced bool) { }) } -func newNodeNumberPlugin(ctx context.Context, t e2e.Testing, advanced, reverse bool) framework.Plugin { +func newNodeNumberPlugin(ctx context.Context, t e2e.Testing, advanced, reverse bool, logSeverity int32) framework.Plugin { t.Helper() guestURL := test.URLExampleNodeNumber if advanced { @@ -142,6 +195,7 @@ func newNodeNumberPlugin(ctx context.Context, t e2e.Testing, advanced, reverse b } plugin, err := wasm.NewFromConfig(ctx, wasm.PluginConfig{ GuestURL: guestURL, + LogSeverity: logSeverity, GuestConfig: fmt.Sprintf(`{"reverse": %v}`, reverse), }) if err != nil { diff --git a/scheduler/go.mod b/scheduler/go.mod index 25bd8f44..5604b103 100644 --- a/scheduler/go.mod +++ b/scheduler/go.mod @@ -40,6 +40,7 @@ require ( k8s.io/api v0.27.3 k8s.io/apimachinery v0.27.3 k8s.io/component-base v0.27.3 + k8s.io/klog/v2 v2.90.1 k8s.io/kubectl v0.27.3 k8s.io/kubernetes v1.27.3 ) @@ -136,7 +137,6 @@ require ( k8s.io/controller-manager v0.27.3 // indirect k8s.io/csi-translation-lib v0.0.0 // indirect k8s.io/dynamic-resource-allocation v0.0.0 // indirect - k8s.io/klog/v2 v2.90.1 // indirect k8s.io/kms v0.27.3 // indirect k8s.io/kube-openapi v0.0.0-20230501164219-8b0f38b5fd1f // indirect k8s.io/kube-scheduler v0.0.0 // indirect diff --git a/scheduler/plugin/config.go b/scheduler/plugin/config.go index 581796c1..bf7169fe 100644 --- a/scheduler/plugin/config.go +++ b/scheduler/plugin/config.go @@ -25,6 +25,14 @@ type PluginConfig struct { // GuestConfig is any configuration to give to the guest. GuestConfig string `json:"guestConfig"` + // LogSeverity has the following values: + // + // - 0: info (default) + // - 1: warning + // - 2: error + // - 3: fatal + LogSeverity int32 `json:"logSeverity"` + // Args are the os.Args the guest will receive, exposed for tests. Args []string } diff --git a/scheduler/plugin/host.go b/scheduler/plugin/host.go index bd148cf4..5befeb10 100644 --- a/scheduler/plugin/host.go +++ b/scheduler/plugin/host.go @@ -22,6 +22,7 @@ import ( "github.com/tetratelabs/wazero" wazeroapi "github.com/tetratelabs/wazero/api" v1 "k8s.io/api/core/v1" + "k8s.io/klog/v2" "k8s.io/kubernetes/pkg/scheduler/framework" ) @@ -33,6 +34,10 @@ const ( k8sApiNodeList = "nodeList" k8sApiNodeName = "nodeName" k8sApiPod = "pod" + k8sKlog = "k8s.io/klog" + k8sKlogLog = "log" + k8sKlogLogs = "logs" + k8sKlogSeverity = "severity" k8sScheduler = "k8s.io/scheduler" k8sSchedulerGetConfig = "get_config" k8sSchedulerResultClusterEvents = "result.cluster_events" @@ -57,6 +62,21 @@ func instantiateHostApi(ctx context.Context, runtime wazero.Runtime) (wazeroapi. Instantiate(ctx) } +func instantiateHostKlog(ctx context.Context, runtime wazero.Runtime, logSeverity int32) (wazeroapi.Module, error) { + host := &host{logSeverity: logSeverity} + return runtime.NewHostModuleBuilder(k8sKlog). + NewFunctionBuilder(). + WithGoModuleFunction(wazeroapi.GoModuleFunc(host.k8sKlogLogFn), []wazeroapi.ValueType{i32, i32, i32}, []wazeroapi.ValueType{}). + WithParameterNames("severity", "msg", "msg_len").Export(k8sKlogLog). + NewFunctionBuilder(). + WithGoModuleFunction(wazeroapi.GoModuleFunc(host.k8sKlogLogsFn), []wazeroapi.ValueType{i32, i32, i32, i32, i32}, []wazeroapi.ValueType{}). + WithParameterNames("severity", "msg", "msg_len", "kvs", "kvs_len").Export(k8sKlogLogs). + NewFunctionBuilder(). + WithGoModuleFunction(wazeroapi.GoModuleFunc(host.k8sKlogSeverityFn), []wazeroapi.ValueType{}, []wazeroapi.ValueType{i32}). + WithResultNames("severity").Export(k8sKlogSeverity). + Instantiate(ctx) +} + func instantiateHostScheduler(ctx context.Context, runtime wazero.Runtime, guestConfig string) (wazeroapi.Module, error) { host := &host{guestConfig: guestConfig} return runtime.NewHostModuleBuilder(k8sScheduler). @@ -161,6 +181,7 @@ func k8sApiPodFn(ctx context.Context, mod wazeroapi.Module, stack []uint64) { type host struct { guestConfig string + logSeverity int32 } func (h host) k8sSchedulerGetConfigFn(_ context.Context, mod wazeroapi.Module, stack []uint64) { @@ -172,14 +193,94 @@ func (h host) k8sSchedulerGetConfigFn(_ context.Context, mod wazeroapi.Module, s stack[0] = uint64(writeStringIfUnderLimit(mod.Memory(), config, buf, bufLimit)) } +const ( + severityInfo int32 = iota + severityWarning + severityError + severityFatal +) + +// k8sKlogLogFn is a function used by the wasm guest to access klog.Info and +// klog.Error. +func (h host) k8sKlogLogFn(_ context.Context, mod wazeroapi.Module, stack []uint64) { + severity := int32(stack[0]) + msg := uint32(stack[1]) + msgLen := uint32(stack[2]) + + if severity > h.logSeverity { + return + } + + if b, ok := mod.Memory().Read(msg, msgLen); !ok { + // don't panic if we can't read the message. + } else { + switch severity { + case severityInfo: + klog.Info(string(b)) + case severityError: + klog.Error(string(b)) + } + } +} + +// k8sKlogLogsFn is a function used by the wasm guest to access klog.InfoS and +// klog.ErrorS. +func (h host) k8sKlogLogsFn(ctx context.Context, mod wazeroapi.Module, stack []uint64) { + severity := int32(stack[0]) + msg := uint32(stack[1]) + msgLen := uint32(stack[2]) + kvs := uint32(stack[3]) + kvsLen := uint32(stack[4]) + + // no key-values is unlikely, but possible + if kvsLen == 0 { + h.k8sKlogLogFn(ctx, mod, stack) + return + } + + if severity < h.logSeverity { + return + } + + var msgS string + if b, ok := mod.Memory().Read(msg, msgLen); !ok { + return // don't panic if we can't read the message. + } else { + msgS = string(b) + } + + var kvsS []any + if b, ok := mod.Memory().Read(kvs, kvsLen); !ok { + return // don't panic if we can't read the kvs. + } else if strings := fromNULTerminated(b); len(strings) > 0 { + kvsS = make([]any, len(strings)) + for i := range strings { + kvsS[i] = strings[i] + } + } + + switch severity { + case severityInfo: + klog.InfoS(msgS, kvsS...) + case severityError: + klog.ErrorS(nil, msgS, kvsS...) + } +} + +// k8sKlogSeverityFn is a function used by the wasm guest to obviate log +// overhead when a message won't be written. +func (h host) k8sKlogSeverityFn(_ context.Context, _ wazeroapi.Module, stack []uint64) { + stack[0] = uint64(h.logSeverity) +} + // k8sSchedulerResultClusterEventsFn is a function used by the wasm guest to set the // cluster events result from guestExportEnqueue. func k8sSchedulerResultClusterEventsFn(ctx context.Context, mod wazeroapi.Module, stack []uint64) { - ptr := uint32(stack[0]) - size := uint32(stack[1]) + buf := uint32(stack[0]) + bufLen := uint32(stack[1]) var clusterEvents []framework.ClusterEvent - if b, ok := mod.Memory().Read(ptr, size); !ok { + if b, ok := mod.Memory().Read(buf, bufLen); !ok { panic("out of memory reading clusterEvents") } else { clusterEvents = decodeClusterEvents(b) @@ -190,11 +291,11 @@ func k8sSchedulerResultClusterEventsFn(ctx context.Context, mod wazeroapi.Module // k8sSchedulerResultNodeNamesFn is a function used by the wasm guest to set the // node names result from guestExportPreFilter. func k8sSchedulerResultNodeNamesFn(ctx context.Context, mod wazeroapi.Module, stack []uint64) { - ptr := uint32(stack[0]) - size := uint32(stack[1]) + buf := uint32(stack[0]) + bufLen := uint32(stack[1]) var nodeNames []string - if b, ok := mod.Memory().Read(ptr, size); !ok { + if b, ok := mod.Memory().Read(buf, bufLen); !ok { panic("out of memory reading nodeNames") } else { nodeNames = fromNULTerminated(b) @@ -205,11 +306,11 @@ func k8sSchedulerResultNodeNamesFn(ctx context.Context, mod wazeroapi.Module, st // k8sSchedulerResultStatusReasonFn is a function used by the wasm guest to set the // framework.Status reason result from all functions. func k8sSchedulerResultStatusReasonFn(ctx context.Context, mod wazeroapi.Module, stack []uint64) { - ptr := uint32(stack[0]) - size := uint32(stack[1]) + buf := uint32(stack[0]) + bufLen := uint32(stack[1]) var reason string - if b, ok := mod.Memory().Read(ptr, size); !ok { + if b, ok := mod.Memory().Read(buf, bufLen); !ok { // don't panic if we can't read the message. reason = "BUG: out of memory reading message" } else { diff --git a/scheduler/plugin/host_test.go b/scheduler/plugin/host_test.go new file mode 100644 index 00000000..1876226b --- /dev/null +++ b/scheduler/plugin/host_test.go @@ -0,0 +1,93 @@ +/* + Copyright 2023 The Kubernetes Authors. + + Licensed under the Apache License, Version 2.0 (the "License"); + you may not use this file except in compliance with the License. + You may obtain a copy of the License at + + http://www.apache.org/licenses/LICENSE-2.0 + + Unless required by applicable law or agreed to in writing, software + distributed under the License is distributed on an "AS IS" BASIS, + WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + See the License for the specific language governing permissions and + limitations under the License. +*/ + +package wasm + +import ( + "bytes" + "context" + "testing" + + "github.com/tetratelabs/wazero/experimental/wazerotest" + "k8s.io/klog/v2" + k8stest "k8s.io/klog/v2/test" +) + +func Test_k8sKlogLogFn(t *testing.T) { + var buf bytes.Buffer + initKlog(t, &buf) + + // Configure the host to log info. + h := host{logSeverity: severityInfo} + + // Create a fake wasm module, which has data the guest should write. + mem := wazerotest.NewMemory(wazerotest.PageSize) + mod := wazerotest.NewModule(mem) + message := "hello" + copy(mem.Bytes, message) + + // Invoke the host function in the same way the guest would have. + h.k8sKlogLogFn(context.Background(), mod, []uint64{ + uint64(severityInfo), // severity + 0, // msg + uint64(len(message)), // msg_len + }) + + want := message + "\n" // klog always adds newline + if have := buf.String(); want != have { + t.Fatalf("unexpected log message: %v != %v", want, have) + } +} + +func Test_k8sKlogLogsFn(t *testing.T) { + var buf bytes.Buffer + initKlog(t, &buf) + + // Configure the host to log info. + h := host{logSeverity: severityInfo} + + // Create a fake wasm module, which has data the guest should write. + mem := wazerotest.NewMemory(wazerotest.PageSize) + mod := wazerotest.NewModule(mem) + message := "hello" + copy(mem.Bytes, message) + kvs := "err\x00unhandled\u0000" + copy(mem.Bytes[32:], kvs) + + // Invoke the host function in the same way the guest would have. + h.k8sKlogLogsFn(context.Background(), mod, []uint64{ + uint64(severityInfo), // severity + 0, // msg + uint64(len(message)), // msg_len + 32, // kvs + uint64(len(kvs)), // kvs_len + }) + + want := `"hello" err="unhandled" +` // klog always adds newline + if have := buf.String(); want != have { + t.Fatalf("unexpected log message: %v != %v", want, have) + } +} + +func initKlog(t *testing.T, buf *bytes.Buffer) { + // Re-initialize klog for tests. + fs := k8stest.InitKlog(t) + // Disable timestamps. + _ = fs.Set("skip_headers", "true") + // Write log output to the buffer + klog.SetOutput(buf) +} diff --git a/scheduler/plugin/plugin.go b/scheduler/plugin/plugin.go index 8e9e56db..c87f8ade 100644 --- a/scheduler/plugin/plugin.go +++ b/scheduler/plugin/plugin.go @@ -60,7 +60,7 @@ func NewFromConfig(ctx context.Context, config PluginConfig) (framework.Plugin, return nil, fmt.Errorf("wasm: error reading guestURL %s: %w", url, err) } - runtime, guestModule, err := prepareRuntime(ctx, guestBin, config.GuestConfig) + runtime, guestModule, err := prepareRuntime(ctx, guestBin, config.LogSeverity, config.GuestConfig) if err != nil { return nil, err } diff --git a/scheduler/plugin/plugin_test.go b/scheduler/plugin/plugin_test.go index 9247c46f..5be9886d 100644 --- a/scheduler/plugin/plugin_test.go +++ b/scheduler/plugin/plugin_test.go @@ -45,7 +45,7 @@ var ctx = context.Background() // Test_guestPool_bindingCycles tests that the bindingCycles field is set correctly. func Test_guestPool_bindingCycles(t *testing.T) { - p, err := wasm.NewFromConfig(ctx, wasm.PluginConfig{GuestURL: test.URLTestAll}) + p, err := wasm.NewFromConfig(ctx, wasm.PluginConfig{GuestURL: test.URLTestCycleState}) if err != nil { t.Fatalf("failed to create plugin: %v", err) } @@ -123,7 +123,7 @@ func Test_guestPool_bindingCycles(t *testing.T) { // Test_guestPool_assignedToSchedulingPod tests that the scheduledPodUID is assigned during PreFilter expectedly. func Test_guestPool_assignedToSchedulingPod(t *testing.T) { - p, err := wasm.NewFromConfig(ctx, wasm.PluginConfig{GuestURL: test.URLTestAll}) + p, err := wasm.NewFromConfig(ctx, wasm.PluginConfig{GuestURL: test.URLTestCycleState}) if err != nil { t.Fatalf("failed to create plugin: %v", err) } diff --git a/scheduler/plugin/runtime.go b/scheduler/plugin/runtime.go index 8921baed..bfe70c5e 100644 --- a/scheduler/plugin/runtime.go +++ b/scheduler/plugin/runtime.go @@ -26,7 +26,7 @@ import ( ) // prepareRuntime compiles the guest and instantiates any host modules it needs. -func prepareRuntime(ctx context.Context, guestBin []byte, guestConfig string) (runtime wazero.Runtime, guest wazero.CompiledModule, err error) { +func prepareRuntime(ctx context.Context, guestBin []byte, logSeverity int32, guestConfig string) (runtime wazero.Runtime, guest wazero.CompiledModule, err error) { // Create the runtime, which when closed releases any resources associated with it. runtime = wazero.NewRuntimeWithConfig(ctx, wazero.NewRuntimeConfig(). // Here are settings required by the wasm profiler wzprof: @@ -61,6 +61,12 @@ func prepareRuntime(ctx context.Context, guestBin []byte, guestConfig string) (r return } } + if imports&importK8sKlog != 0 { + if _, err = instantiateHostKlog(ctx, runtime, logSeverity); err != nil { + err = fmt.Errorf("wasm: error instantiating klog functions: %w", err) + return + } + } if imports&importK8sScheduler != 0 { if _, err = instantiateHostScheduler(ctx, runtime, guestConfig); err != nil { err = fmt.Errorf("wasm: error instantiating scheduler host functions: %w", err) @@ -75,6 +81,7 @@ type imports uint const ( importWasiP1 imports = 1 << iota importK8sApi + importK8sKlog importK8sScheduler ) @@ -85,6 +92,8 @@ func detectImports(importedFns []api.FunctionDefinition) imports { switch moduleName { case k8sApi: imports |= importK8sApi + case k8sKlog: + imports |= importK8sKlog case k8sScheduler: imports |= importK8sScheduler case wasi_snapshot_preview1.ModuleName: diff --git a/scheduler/test/testdata.go b/scheduler/test/testdata.go index 13b3e0e6..52219ca3 100644 --- a/scheduler/test/testdata.go +++ b/scheduler/test/testdata.go @@ -38,8 +38,6 @@ var URLExampleNodeNumber = localURL(pathTinyGoExample("nodenumber")) var URLExampleAdvanced = localURL(pathTinyGoExample("advanced")) -var URLTestAll = localURL(pathTinyGoTest("all")) - var URLTestAllNoopWat = localURL(pathWatTest("all_noop")) var URLTestCycleState = localURL(pathTinyGoTest("cyclestate"))