Merge pull request #67 from codefromthecrypt/klog

Add klog.Info/Error support

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
 

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)
 	}

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"`
+}

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)

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.

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

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 {

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
 }

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()
 }

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(

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