[KNI] log: add the KNI logger

Introduce the KNI logger.
The KNI logger builds upon and augments the existing klog (+logr)
infrastructure to provide per-object (vs per-component) log.

In a nutshell, the logger aims to make it possible/easier to correlate
all the logs pertaining to a container during a scheduling cycle

For full design details please check the upcoming
`pkg-kni/logger/DESIGN.md`.

Signed-off-by: Francesco Romani <fromani@redhat.com>

cmd/noderesourcetopology-plugin/main.go

@@ -17,6 +17,7 @@ limitations under the License.
 package main
 
 import (
+	"context"
 	"math/rand"
 	"os"
 	"time"
@@ -33,6 +34,7 @@ import (
 	_ "sigs.k8s.io/scheduler-plugins/apis/config/scheme"
 
 	knifeatures "sigs.k8s.io/scheduler-plugins/pkg-kni/features"
+	knilogger "sigs.k8s.io/scheduler-plugins/pkg-kni/logger"
 	knistatus "sigs.k8s.io/scheduler-plugins/pkg-kni/pfpstatus"
 )
 
@@ -41,8 +43,11 @@ func main() {
 
 	rand.Seed(time.Now().UnixNano())
 
-	logh := klogr.NewWithOptions(klogr.WithFormat(klogr.FormatKlog))
-
+	logh, ok := knilogger.Setup(context.Background())
+	if !ok {
+		// KNI logger disabled
+		logh = klogr.NewWithOptions(klogr.WithFormat(klogr.FormatKlog))
+	}
 	knistatus.Setup(logh)
 
 	// Register custom plugins to the scheduler framework.

go.mod

@@ -7,6 +7,7 @@ require (
 	github.com/diktyo-io/networktopology-api v1.0.1-alpha
 	github.com/dustin/go-humanize v1.0.1
 	github.com/go-logr/logr v1.2.4
+	github.com/go-logr/stdr v1.2.2
 	github.com/google/go-cmp v0.5.9
 	github.com/k8stopologyawareschedwg/noderesourcetopology-api v0.1.1
 	github.com/k8stopologyawareschedwg/podfingerprint v0.2.2
@@ -51,7 +52,6 @@ require (
 	github.com/felixge/httpsnoop v1.0.3 // indirect
 	github.com/francoispqt/gojay v1.2.13 // indirect
 	github.com/fsnotify/fsnotify v1.6.0 // indirect
-	github.com/go-logr/stdr v1.2.2 // indirect
 	github.com/go-openapi/jsonpointer v0.19.6 // indirect
 	github.com/go-openapi/jsonreference v0.20.2 // indirect
 	github.com/go-openapi/swag v0.22.3 // indirect

pkg-kni/logger/dump.go

@@ -0,0 +1,90 @@
+/*
+ * Copyright 2023 Red Hat, Inc.
+ *
+ * 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 logger
+
+import (
+	"bytes"
+	"context"
+	"os"
+	"path/filepath"
+	"strings"
+	"time"
+
+	"github.com/go-logr/logr"
+)
+
+func RunForever(ctx context.Context, logger logr.Logger, interval time.Duration, baseDirectory string, lc *LogCache) {
+	// let's try to keep the amount of code we do in init() at minimum.
+	// This may happen if the container didn't have the directory mounted
+	discard := !existsBaseDirectory(baseDirectory)
+	if discard {
+		logger.Info("base directory not found, will discard everything", "baseDirectory", baseDirectory)
+	}
+
+	delta := interval - 10*time.Millisecond // TODO
+	logger.Info("dump loop info", "interval", interval, "delta", delta)
+
+	ticker := time.NewTicker(interval)
+	defer ticker.Stop()
+
+	for {
+		select {
+		case <-ctx.Done():
+			return
+		case now := <-ticker.C:
+			// keep the size at bay by popping old data even if we just discard it
+			expireds := lc.PopExpired(now, delta)
+			for _, expired := range expireds {
+				if discard {
+					continue
+				}
+				// intentionally swallow error.
+				// - if we hit issues and we do log (V=2, like), we will clog the regular log
+				// - if we hit issues and we do NOT log (v=5, like) we will not see it anyway
+				DumpLogNode(baseDirectory, expired.logID, expired.data)
+			}
+			if len(expireds) > 0 {
+				logger.V(4).Info("written logs to storage", "entries", len(expireds))
+			}
+		}
+	}
+}
+
+func DumpLogNode(statusDir string, logName string, data bytes.Buffer) error {
+	logName = fixLogName(logName)
+	dst, err := os.OpenFile(filepath.Join(statusDir, logName+".log"), os.O_WRONLY|os.O_CREATE|os.O_APPEND, 0644)
+	if err != nil {
+		return err
+	}
+	if _, err := dst.Write(data.Bytes()); err != nil {
+		dst.Close() // swallow error because we want to bubble up the write error
+		return err
+	}
+	return dst.Close()
+}
+
+func existsBaseDirectory(baseDir string) bool {
+	info, err := os.Stat(baseDir)
+	if err != nil {
+		return false
+	}
+	return info.IsDir()
+}
+
+func fixLogName(name string) string {
+	return strings.ReplaceAll(name, "/", "__")
+}

pkg-kni/logger/dump_test.go

@@ -0,0 +1,55 @@
+/*
+ * Copyright 2023 Red Hat, Inc.
+ *
+ * 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 logger
+
+import (
+	"bytes"
+	"os"
+	"path/filepath"
+	"testing"
+)
+
+func TestDumpLogNodeAppendsData(t *testing.T) {
+	dir, err := os.MkdirTemp("", "kni-logger-dump-data")
+	if err != nil {
+		t.Fatal(err)
+	}
+	defer os.RemoveAll(dir) // clean up
+
+	buf1 := bytes.NewBufferString("fizzbuzz\n")
+	err = DumpLogNode(dir, "foo-test", *buf1)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	buf2 := bytes.NewBufferString("foobar\n")
+	err = DumpLogNode(dir, "foo-test", *buf2)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	data, err := os.ReadFile(filepath.Join(dir, "foo-test.log"))
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	got := string(data)
+	expected := "fizzbuzz\nfoobar\n"
+	if got != expected {
+		t.Errorf("read error\ngot=[%s]\nexp=[%s]", got, expected)
+	}
+}

pkg-kni/logger/knilogr.go

@@ -0,0 +1,113 @@
+/*
+ * Copyright 2019 The logr Authors.
+ * Copyright 2023 Red Hat, Inc.
+ *
+ * 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.
+ *
+ * Derived from https://github.com/go-logr/stdr/blob/v1.2.2/stdr.go
+ */
+
+package logger
+
+import (
+	"github.com/go-logr/logr"
+	"github.com/go-logr/logr/funcr"
+	"github.com/go-logr/stdr"
+)
+
+type knilogger struct {
+	funcr.Formatter
+	std      stdr.StdLogger
+	cache    *LogCache
+	logID    string
+	hasLogID bool
+	verbose  int
+}
+
+func New(std stdr.StdLogger, lc *LogCache, verbose int, opts stdr.Options) logr.Logger {
+	sl := &knilogger{
+		Formatter: funcr.NewFormatter(funcr.Options{
+			LogCaller: funcr.MessageClass(opts.LogCaller),
+		}),
+		std:     std,
+		cache:   lc,
+		verbose: verbose,
+	}
+
+	// For skipping our own logger.Info/Error.
+	sl.Formatter.AddCallDepth(1 + opts.Depth)
+
+	return logr.New(sl)
+}
+
+func (l knilogger) Enabled(level int) bool {
+	return l.verbose >= level || l.logID != ""
+}
+
+func (l knilogger) Info(level int, msg string, kvList ...interface{}) {
+	prefix, args := l.FormatInfo(level, msg, kvList)
+	if prefix != "" {
+		args = prefix + ": " + args
+	}
+	if l.cache != nil {
+		logID, ok := l.logID, l.hasLogID
+		if !ok {
+			logID, ok = StartsWithLogID(kvList...)
+		}
+		if ok {
+			l.cache.Put(logID, args) // ignore error intentionally
+		}
+	}
+	// because we can be here because either we have enough verbosiness
+	// OR because stored logID. So we must redo this check.
+	if l.verbose < level {
+		return
+	}
+	_ = l.std.Output(l.Formatter.GetDepth()+1, args)
+}
+
+func (l knilogger) Error(err error, msg string, kvList ...interface{}) {
+	prefix, args := l.FormatError(err, msg, kvList)
+	if prefix != "" {
+		args = prefix + ": " + args
+	}
+	if l.cache != nil {
+		logID, ok := l.logID, l.hasLogID
+		if !ok {
+			logID, ok = StartsWithLogID(kvList...)
+		}
+		if ok {
+			l.cache.Put(logID, args) // ignore error intentionally
+		}
+	}
+	_ = l.std.Output(l.Formatter.GetDepth()+1, args)
+}
+
+func (l knilogger) WithName(name string) logr.LogSink {
+	l.Formatter.AddName(name)
+	return &l
+}
+
+func (l knilogger) WithValues(kvList ...interface{}) logr.LogSink {
+	l.logID, l.hasLogID = FindLogID(kvList)
+	l.Formatter.AddValues(kvList)
+	return &l
+}
+
+func (l knilogger) WithCallDepth(depth int) logr.LogSink {
+	l.Formatter.AddCallDepth(depth)
+	return &l
+}
+
+var _ logr.LogSink = &knilogger{}
+var _ logr.CallDepthLogSink = &knilogger{}