From 8e2f03d3366a8d7fdc6f398a20ef16b2d3a36fe8 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Fri, 19 Nov 2021 20:46:00 +0100 Subject: [PATCH] logs: add benchmark The benchmark reads a JSON log file and measures how long it takes to re-encode it. The focus is on the encoding of message and values, therefore additional work (time stamping, caller, writing to file) gets avoided. --- staging/src/k8s.io/component-base/go.mod | 1 + .../component-base/logs/benchmark/README.md | 43 +++ .../logs/benchmark/benchmark_test.go | 108 +++++++ .../logs/benchmark/common_test.go | 79 +++++ .../logs/benchmark/data/container.log | 2 + .../logs/benchmark/data/error-value.log | 1 + .../logs/benchmark/data/error.log | 1 + .../logs/benchmark/data/simple.log | 1 + .../logs/benchmark/data/values.log | 1 + .../component-base/logs/benchmark/load.go | 269 ++++++++++++++++++ .../logs/benchmark/load_test.go | 221 ++++++++++++++ 11 files changed, 727 insertions(+) create mode 100644 staging/src/k8s.io/component-base/logs/benchmark/README.md create mode 100644 staging/src/k8s.io/component-base/logs/benchmark/benchmark_test.go create mode 100644 staging/src/k8s.io/component-base/logs/benchmark/common_test.go create mode 100644 staging/src/k8s.io/component-base/logs/benchmark/data/container.log create mode 100644 staging/src/k8s.io/component-base/logs/benchmark/data/error-value.log create mode 100644 staging/src/k8s.io/component-base/logs/benchmark/data/error.log create mode 100644 staging/src/k8s.io/component-base/logs/benchmark/data/simple.log create mode 100644 staging/src/k8s.io/component-base/logs/benchmark/data/values.log create mode 100644 staging/src/k8s.io/component-base/logs/benchmark/load.go create mode 100644 staging/src/k8s.io/component-base/logs/benchmark/load_test.go diff --git a/staging/src/k8s.io/component-base/go.mod b/staging/src/k8s.io/component-base/go.mod index f0e79049687..c4bc0d41a03 100644 --- a/staging/src/k8s.io/component-base/go.mod +++ b/staging/src/k8s.io/component-base/go.mod @@ -28,6 +28,7 @@ require ( golang.org/x/tools v0.1.8 // indirect google.golang.org/genproto v0.0.0-20210831024726-fe130286e0e2 // indirect gotest.tools/v3 v3.0.3 // indirect + k8s.io/api v0.0.0 k8s.io/apimachinery v0.0.0 k8s.io/client-go v0.0.0 k8s.io/klog/v2 v2.40.1 diff --git a/staging/src/k8s.io/component-base/logs/benchmark/README.md b/staging/src/k8s.io/component-base/logs/benchmark/README.md new file mode 100644 index 00000000000..d68a9a8deda --- /dev/null +++ b/staging/src/k8s.io/component-base/logs/benchmark/README.md @@ -0,0 +1,43 @@ +# Benchmarking logging + +Any major changes to the logging code, whether it is in Kubernetes or in klog, +must be benchmarked before and after the change. + +## Running the benchmark + +``` +$ go test -bench=. -test.benchmem -benchmem . +``` + +## Real log data + +The files under `data` define test cases for specific aspects of formatting. To +test with a log file that represents output under some kind of real load, copy +the log file into `data/.log` and run benchmarking as described +above. `-bench=BenchmarkLogging/` can be used +to benchmark just the new file. + +When using `data/v/.log`, formatting will be done at +that log level. Symlinks can be created to simulating writing of the same log +data at different levels. + +No such real data is included in the Kubernetes repo because of their size. +They can be found in the "artifacts" of this +https://testgrid.kubernetes.io/sig-instrumentation-tests#kind-json-logging-master +Prow job: +- `artifacts/logs/kind-control-plane/containers` +- `artifacts/logs/kind-*/kubelet.log` + +With sufficient credentials, `gsutil` can be used to download everything for a job with: +``` +gsutil -m cp -R gs://kubernetes-jenkins/logs/ci-kubernetes-kind-e2e-json-logging/ . +``` + +## Analyzing log data + +While loading a file, some statistics about it are collected. Those are shown +when running with: + +``` +$ go test -v -bench=. -test.benchmem -benchmem . +``` diff --git a/staging/src/k8s.io/component-base/logs/benchmark/benchmark_test.go b/staging/src/k8s.io/component-base/logs/benchmark/benchmark_test.go new file mode 100644 index 00000000000..ba15085410d --- /dev/null +++ b/staging/src/k8s.io/component-base/logs/benchmark/benchmark_test.go @@ -0,0 +1,108 @@ +/* +Copyright 2021 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 benchmark + +import ( + "fmt" + "io/fs" + "path/filepath" + "regexp" + "strconv" + "strings" + "testing" + + "k8s.io/klog/v2" +) + +func BenchmarkLogging(b *testing.B) { + // Each "data/(v[0-9]/)?*.log" file is expected to contain JSON log + // messages. We generate one sub-benchmark for each file where logging + // is tested with the log level from the directory. Symlinks can be + // used to test the same file with different levels. + if err := filepath.Walk("data", func(path string, info fs.FileInfo, err error) error { + if err != nil { + return err + } + if !strings.HasSuffix(path, ".log") { + return nil + } + messages, stats, err := loadLog(path) + if err != nil { + return err + } + if info.Mode()&fs.ModeSymlink == 0 { + b.Log(path + "\n" + stats.String()) + } + b.Run(strings.TrimSuffix(strings.TrimPrefix(path, "data/"), ".log"), func(b *testing.B) { + // Take verbosity threshold from directory, if present. + vMatch := regexp.MustCompile(`/v(\d+)/`).FindStringSubmatch(path) + v := 0 + if vMatch != nil { + v, _ = strconv.Atoi(vMatch[1]) + } + fileSizes := map[string]int{} + b.Run("stats", func(b *testing.B) { + // Nothing to do. Use this for "go test -v + // -bench=BenchmarkLogging/.*/stats" to print + // just the statistics. + }) + b.Run("printf", func(b *testing.B) { + b.ResetTimer() + output = 0 + for i := 0; i < b.N; i++ { + for _, item := range messages { + if item.verbosity <= v { + printf(item) + } + } + } + fileSizes["printf"] = int(output) / b.N + }) + b.Run("structured", func(b *testing.B) { + b.ResetTimer() + output = 0 + for i := 0; i < b.N; i++ { + for _, item := range messages { + if item.verbosity <= v { + prints(item) + } + } + } + fileSizes["structured"] = int(output) / b.N + }) + b.Run("JSON", func(b *testing.B) { + klog.SetLogger(jsonLogger) + defer klog.ClearLogger() + b.ResetTimer() + output = 0 + for i := 0; i < b.N; i++ { + for _, item := range messages { + if item.verbosity <= v { + prints(item) + } + } + } + fileSizes["JSON"] = int(output) / b.N + }) + + b.Log(fmt.Sprintf("file sizes: %v\n", fileSizes)) + }) + return nil + }); err != nil { + b.Fatalf("reading 'data' directory: %v", err) + } +} diff --git a/staging/src/k8s.io/component-base/logs/benchmark/common_test.go b/staging/src/k8s.io/component-base/logs/benchmark/common_test.go new file mode 100644 index 00000000000..7fee16c76fe --- /dev/null +++ b/staging/src/k8s.io/component-base/logs/benchmark/common_test.go @@ -0,0 +1,79 @@ +/* +Copyright 2021 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 benchmark + +import ( + "flag" + "io" + + "github.com/go-logr/logr" + "go.uber.org/zap/zapcore" + + logsjson "k8s.io/component-base/logs/json" + "k8s.io/klog/v2" +) + +func init() { + // Cause all klog output to be discarded with minimal overhead. + // We don't include time stamps and caller information. + klog.InitFlags(nil) + flag.Set("alsologtostderr", "false") + flag.Set("logtostderr", "false") + flag.Set("skip_headers", "true") + flag.Set("one_output", "true") + flag.Set("stderrthreshold", "FATAL") + klog.SetOutput(&output) +} + +type bytesWritten int64 + +func (b *bytesWritten) Write(data []byte) (int, error) { + l := len(data) + *b += bytesWritten(l) + return l, nil +} + +func (b *bytesWritten) Sync() error { + return nil +} + +var output bytesWritten +var jsonLogger = newJSONLogger(&output) + +func newJSONLogger(out io.Writer) logr.Logger { + encoderConfig := &zapcore.EncoderConfig{ + MessageKey: "msg", + } + logger, _ := logsjson.NewJSONLogger(zapcore.AddSync(out), nil, encoderConfig) + return logger +} + +func printf(item logMessage) { + if item.isError { + klog.Errorf("%s: %v %s", item.msg, item.err, item.kvs) + } else { + klog.Infof("%s: %v", item.msg, item.kvs) + } +} + +func prints(item logMessage) { + if item.isError { + klog.ErrorS(item.err, item.msg, item.kvs...) + } else { + klog.InfoS(item.msg, item.kvs...) + } +} diff --git a/staging/src/k8s.io/component-base/logs/benchmark/data/container.log b/staging/src/k8s.io/component-base/logs/benchmark/data/container.log new file mode 100644 index 00000000000..4f8a6676f73 --- /dev/null +++ b/staging/src/k8s.io/component-base/logs/benchmark/data/container.log @@ -0,0 +1,2 @@ +# This is a manually created message. See https://github.com/kubernetes/kubernetes/issues/106652 for the real one. +Nov 19 02:13:48 kind-worker2 kubelet[250]: {"ts":1637288028968.0125,"caller":"kuberuntime/kuberuntime_manager.go:902","msg":"Creating container in pod","v":0,"container":{"Name":"terminate-cmd-rpn","Image":"k8s.gcr.io/e2e-test-images/busybox:1.29-2","Command":["sh -c \nf=/restart-count/restartCount\ncount=$(echo 'hello' >> $f ; wc -l $f | awk {'print $1'})\nif [ $count -eq 1 ]; then\n\texit 1\nfi\nif [ $count -eq 2 ]; then\n\texit 0\nfi\nwhile true; do sleep 1; done\n"],"TerminationMessagePath":"/dev/termination-log"}} diff --git a/staging/src/k8s.io/component-base/logs/benchmark/data/error-value.log b/staging/src/k8s.io/component-base/logs/benchmark/data/error-value.log new file mode 100644 index 00000000000..9c5bd4ced5d --- /dev/null +++ b/staging/src/k8s.io/component-base/logs/benchmark/data/error-value.log @@ -0,0 +1 @@ +{"v":0, "msg": "Pod status update", "err": "failed"} diff --git a/staging/src/k8s.io/component-base/logs/benchmark/data/error.log b/staging/src/k8s.io/component-base/logs/benchmark/data/error.log new file mode 100644 index 00000000000..114dd2a45ab --- /dev/null +++ b/staging/src/k8s.io/component-base/logs/benchmark/data/error.log @@ -0,0 +1 @@ +{"msg": "Pod status update", "err": "failed"} diff --git a/staging/src/k8s.io/component-base/logs/benchmark/data/simple.log b/staging/src/k8s.io/component-base/logs/benchmark/data/simple.log new file mode 100644 index 00000000000..2a4345b3bbe --- /dev/null +++ b/staging/src/k8s.io/component-base/logs/benchmark/data/simple.log @@ -0,0 +1 @@ +{"v": 0, "msg": "Pod status updated"} diff --git a/staging/src/k8s.io/component-base/logs/benchmark/data/values.log b/staging/src/k8s.io/component-base/logs/benchmark/data/values.log new file mode 100644 index 00000000000..f7c20c745f7 --- /dev/null +++ b/staging/src/k8s.io/component-base/logs/benchmark/data/values.log @@ -0,0 +1 @@ +{"v":0, "msg": "Example", "someValue": 1, "someString": "hello world", "pod": {"namespace": "system", "name": "kube-scheduler"}, "pv": {"name": "volume"}} diff --git a/staging/src/k8s.io/component-base/logs/benchmark/load.go b/staging/src/k8s.io/component-base/logs/benchmark/load.go new file mode 100644 index 00000000000..ccb5727b146 --- /dev/null +++ b/staging/src/k8s.io/component-base/logs/benchmark/load.go @@ -0,0 +1,269 @@ +/* +Copyright 2021 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 benchmark + +import ( + "bufio" + "bytes" + "encoding/json" + "errors" + "fmt" + "os" + "reflect" + "regexp" + "sort" + "strings" + "text/template" + + "k8s.io/api/core/v1" + "k8s.io/klog/v2" +) + +type logMessage struct { + msg string + verbosity int + err error + isError bool + kvs []interface{} +} + +const ( + stringArg = "string" + multiLineStringArg = "multiLineString" + objectStringArg = "objectString" + numberArg = "number" + krefArg = "kref" + otherArg = "other" + totalArg = "total" +) + +type logStats struct { + TotalLines, JsonLines, ErrorMessages int + + ArgCounts map[string]int + OtherLines []string + OtherArgs []interface{} + MultiLineArgs [][]string + ObjectTypes map[string]int +} + +var ( + logStatsTemplate = template.Must(template.New("format").Funcs(template.FuncMap{ + "percent": func(x, y int) string { + if y == 0 { + return "NA" + } + return fmt.Sprintf("%d%%", x*100/y) + }, + "sub": func(x, y int) int { + return x - y + }, + }).Parse(`Total number of lines: {{.TotalLines}} +Valid JSON messages: {{.JsonLines}} ({{percent .JsonLines .TotalLines}} of total lines) +Error messages: {{.ErrorMessages}} ({{percent .ErrorMessages .JsonLines}} of valid JSON messages) +Unrecognized lines: {{sub .TotalLines .JsonLines}} +{{range .OtherLines}} {{.}} +{{end}} +Args: + total: {{if .ArgCounts.total}}{{.ArgCounts.total}}{{else}}0{{end}}{{if .ArgCounts.string}} + strings: {{.ArgCounts.string}} ({{percent .ArgCounts.string .ArgCounts.total}}){{end}} {{if .ArgCounts.multiLineString}} + with line breaks: {{.ArgCounts.multiLineString}} ({{percent .ArgCounts.multiLineString .ArgCounts.total}} of all arguments) + {{range .MultiLineArgs}} ===== {{index . 0}} ===== +{{index . 1}} + +{{end}}{{end}}{{if .ArgCounts.objectString}} + with API objects: {{.ArgCounts.objectString}} ({{percent .ArgCounts.objectString .ArgCounts.total}} of all arguments) + types and their number of usage:{{range $key, $value := .ObjectTypes}} {{ $key }}:{{ $value }}{{end}}{{end}}{{if .ArgCounts.number}} + numbers: {{.ArgCounts.number}} ({{percent .ArgCounts.number .ArgCounts.total}}){{end}}{{if .ArgCounts.kref}} + ObjectRef: {{.ArgCounts.kref}} ({{percent .ArgCounts.kref .ArgCounts.total}}){{end}}{{if .ArgCounts.other}} + others: {{.ArgCounts.other}} ({{percent .ArgCounts.other .ArgCounts.total}}){{end}} +`)) +) + +// This produces too much output: +// {{range .OtherArgs}} {{.}} +// {{end}} + +// Doesn't work? +// Unrecognized lines: {{with $delta := sub .TotalLines .JsonLines}}{{$delta}} ({{percent $delta .TotalLines}} of total lines){{end}} + +func (s logStats) String() string { + var buffer bytes.Buffer + err := logStatsTemplate.Execute(&buffer, &s) + if err != nil { + return err.Error() + } + return buffer.String() +} + +func loadLog(path string) (messages []logMessage, stats logStats, err error) { + file, err := os.Open(path) + if err != nil { + return nil, logStats{}, err + } + defer file.Close() + + stats.ArgCounts = map[string]int{} + scanner := bufio.NewScanner(file) + for lineNo := 0; scanner.Scan(); lineNo++ { + line := scanner.Bytes() + msg, err := parseLine(line, &stats) + if err != nil { + stats.OtherLines = append(stats.OtherLines, fmt.Sprintf("%d: %s", lineNo, string(line))) + continue + } + messages = append(messages, msg) + } + + if err := scanner.Err(); err != nil { + return nil, logStats{}, fmt.Errorf("reading %s failed: %v", path, err) + } + + return +} + +// systemd prefix: +// Nov 19 02:08:51 kind-worker2 kubelet[250]: {"ts":1637287731687.8315,... +// +// kubectl (?) prefix: +// 2021-11-19T02:08:28.475825534Z stderr F {"ts": ... +var prefixRE = regexp.MustCompile(`^\w+ \d+ \S+ \S+ \S+: |\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d+Z stderr . `) + +// String format for API structs from generated.pb.go. +// &Container{...} +var objectRE = regexp.MustCompile(`^&([a-zA-Z]*)\{`) + +func parseLine(line []byte, stats *logStats) (item logMessage, err error) { + stats.TotalLines++ + line = prefixRE.ReplaceAll(line, nil) + + content := map[string]interface{}{} + if err := json.Unmarshal(line, &content); err != nil { + return logMessage{}, fmt.Errorf("JSON parsing failed: %v", err) + } + stats.JsonLines++ + + kvs := map[string]interface{}{} + item.isError = true + for key, value := range content { + switch key { + case "v": + verbosity, ok := value.(float64) + if !ok { + return logMessage{}, fmt.Errorf("expected number for v, got: %T %v", value, value) + } + item.verbosity = int(verbosity) + item.isError = false + case "msg": + msg, ok := value.(string) + if !ok { + return logMessage{}, fmt.Errorf("expected string for msg, got: %T %v", value, value) + } + item.msg = msg + case "ts", "caller": + // ignore + case "err": + errStr, ok := value.(string) + if !ok { + return logMessage{}, fmt.Errorf("expected string for err, got: %T %v", value, value) + } + item.err = errors.New(errStr) + stats.ArgCounts[stringArg]++ + stats.ArgCounts[totalArg]++ + default: + if obj := toObject(value); obj != nil { + value = obj + } + switch value := value.(type) { + case string: + stats.ArgCounts[stringArg]++ + if strings.Contains(value, "\n") { + stats.ArgCounts[multiLineStringArg]++ + stats.MultiLineArgs = append(stats.MultiLineArgs, []string{key, value}) + } + match := objectRE.FindStringSubmatch(value) + if match != nil { + if stats.ObjectTypes == nil { + stats.ObjectTypes = map[string]int{} + } + stats.ArgCounts[objectStringArg]++ + stats.ObjectTypes[match[1]]++ + } + case float64: + stats.ArgCounts[numberArg]++ + case klog.ObjectRef: + stats.ArgCounts[krefArg]++ + default: + stats.ArgCounts[otherArg]++ + stats.OtherArgs = append(stats.OtherArgs, value) + } + stats.ArgCounts[totalArg]++ + kvs[key] = value + } + } + + // Sort by key. + var keys []string + for key := range kvs { + keys = append(keys, key) + } + sort.Strings(keys) + for _, key := range keys { + item.kvs = append(item.kvs, key, kvs[key]) + } + + if !item.isError && item.err != nil { + // Error is a normal key/value. + item.kvs = append(item.kvs, "err", item.err) + item.err = nil + } + if item.isError { + stats.ErrorMessages++ + } + return +} + +// This is a list of objects that might have been dumped. The simple ones must +// come first because unmarshaling will try one after the after and an +// ObjectRef would unmarshal fine into any of the others whereas any of the +// other types hopefully have enough extra fields that they won't fit (unknown +// fields are an error). +var objectTypes = []reflect.Type{ + reflect.TypeOf(klog.ObjectRef{}), + reflect.TypeOf(&v1.Pod{}), + reflect.TypeOf(&v1.Container{}), +} + +func toObject(value interface{}) interface{} { + data, ok := value.(map[string]interface{}) + if !ok { + return nil + } + jsonData, err := json.Marshal(data) + if err != nil { + return nil + } + for _, t := range objectTypes { + obj := reflect.New(t) + decoder := json.NewDecoder(bytes.NewBuffer(jsonData)) + decoder.DisallowUnknownFields() + if err := decoder.Decode(obj.Interface()); err == nil { + return reflect.Indirect(obj).Interface() + } + } + return nil +} diff --git a/staging/src/k8s.io/component-base/logs/benchmark/load_test.go b/staging/src/k8s.io/component-base/logs/benchmark/load_test.go new file mode 100644 index 00000000000..f6f3b33a5db --- /dev/null +++ b/staging/src/k8s.io/component-base/logs/benchmark/load_test.go @@ -0,0 +1,221 @@ +/* +Copyright 2021 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 benchmark + +import ( + "bytes" + "errors" + "testing" + + "github.com/stretchr/testify/assert" + + "k8s.io/api/core/v1" + "k8s.io/klog/v2" +) + +func TestData(t *testing.T) { + container := v1.Container{ + Command: []string{"sh -c \nf=/restart-count/restartCount\ncount=$(echo 'hello' >> $f ; wc -l $f | awk {'print $1'})\nif [ $count -eq 1 ]; then\n\texit 1\nfi\nif [ $count -eq 2 ]; then\n\texit 0\nfi\nwhile true; do sleep 1; done\n"}, + Image: "k8s.gcr.io/e2e-test-images/busybox:1.29-2", + Name: "terminate-cmd-rpn", + TerminationMessagePath: "/dev/termination-log", + } + + testcases := map[string]struct { + messages []logMessage + printf, structured, json string + stats logStats + }{ + "data/simple.log": { + messages: []logMessage{ + { + msg: "Pod status updated", + }, + }, + printf: `Pod status updated: [] +`, + structured: `"Pod status updated" +`, + json: `{"msg":"Pod status updated","v":0} +`, + stats: logStats{ + TotalLines: 1, + JsonLines: 1, + ArgCounts: map[string]int{}, + }, + }, + "data/error.log": { + messages: []logMessage{ + { + msg: "Pod status update", + err: errors.New("failed"), + isError: true, + }, + }, + printf: `Pod status update: failed [] +`, + structured: `"Pod status update" err="failed" +`, + json: `{"msg":"Pod status update","err":"failed"} +`, + stats: logStats{ + TotalLines: 1, + JsonLines: 1, + ErrorMessages: 1, + ArgCounts: map[string]int{ + stringArg: 1, + totalArg: 1, + }, + }, + }, + "data/error-value.log": { + messages: []logMessage{ + { + msg: "Pod status update", + kvs: []interface{}{"err", errors.New("failed")}, + }, + }, + printf: `Pod status update: [err failed] +`, + structured: `"Pod status update" err="failed" +`, + json: `{"msg":"Pod status update","v":0,"err":"failed"} +`, + stats: logStats{ + TotalLines: 1, + JsonLines: 1, + ArgCounts: map[string]int{ + stringArg: 1, + totalArg: 1, + }, + }, + }, + "data/values.log": { + messages: []logMessage{ + { + msg: "Example", + kvs: []interface{}{ + "pod", klog.KRef("system", "kube-scheduler"), + "pv", klog.KRef("", "volume"), + "someString", "hello world", + "someValue", 1.0, + }, + }, + }, + printf: `Example: [pod system/kube-scheduler pv volume someString hello world someValue 1] +`, + structured: `"Example" pod="system/kube-scheduler" pv="volume" someString="hello world" someValue=1 +`, + json: `{"msg":"Example","v":0,"pod":{"name":"kube-scheduler","namespace":"system"},"pv":{"name":"volume"},"someString":"hello world","someValue":1} +`, + stats: logStats{ + TotalLines: 1, + JsonLines: 1, + ArgCounts: map[string]int{ + stringArg: 1, + krefArg: 2, + numberArg: 1, + totalArg: 4, + }, + }, + }, + "data/container.log": { + messages: []logMessage{ + { + msg: "Creating container in pod", + kvs: []interface{}{ + "container", &container, + }, + }, + }, + printf: `Creating container in pod: [container &Container{Name:terminate-cmd-rpn,Image:k8s.gcr.io/e2e-test-images/busybox:1.29-2,Command:[sh -c +f=/restart-count/restartCount +count=$(echo 'hello' >> $f ; wc -l $f | awk {'print $1'}) +if [ $count -eq 1 ]; then + exit 1 +fi +if [ $count -eq 2 ]; then + exit 0 +fi +while true; do sleep 1; done +],Args:[],WorkingDir:,Ports:[]ContainerPort{},Env:[]EnvVar{},Resources:ResourceRequirements{Limits:ResourceList{},Requests:ResourceList{},},VolumeMounts:[]VolumeMount{},LivenessProbe:nil,ReadinessProbe:nil,Lifecycle:nil,TerminationMessagePath:/dev/termination-log,ImagePullPolicy:,SecurityContext:nil,Stdin:false,StdinOnce:false,TTY:false,EnvFrom:[]EnvFromSource{},TerminationMessagePolicy:,VolumeDevices:[]VolumeDevice{},StartupProbe:nil,}] +`, + structured: `"Creating container in pod" container="&Container{Name:terminate-cmd-rpn,Image:k8s.gcr.io/e2e-test-images/busybox:1.29-2,Command:[sh -c \nf=/restart-count/restartCount\ncount=$(echo 'hello' >> $f ; wc -l $f | awk {'print $1'})\nif [ $count -eq 1 ]; then\n\texit 1\nfi\nif [ $count -eq 2 ]; then\n\texit 0\nfi\nwhile true; do sleep 1; done\n],Args:[],WorkingDir:,Ports:[]ContainerPort{},Env:[]EnvVar{},Resources:ResourceRequirements{Limits:ResourceList{},Requests:ResourceList{},},VolumeMounts:[]VolumeMount{},LivenessProbe:nil,ReadinessProbe:nil,Lifecycle:nil,TerminationMessagePath:/dev/termination-log,ImagePullPolicy:,SecurityContext:nil,Stdin:false,StdinOnce:false,TTY:false,EnvFrom:[]EnvFromSource{},TerminationMessagePolicy:,VolumeDevices:[]VolumeDevice{},StartupProbe:nil,}" +`, + // This is what the output would look like with JSON object. Because of https://github.com/kubernetes/kubernetes/issues/106652 we get the string instead. + // json: `{"msg":"Creating container in pod","v":0,"container":{"name":"terminate-cmd-rpn","image":"k8s.gcr.io/e2e-test-images/busybox:1.29-2","command":["sh -c \nf=/restart-count/restartCount\ncount=$(echo 'hello' >> $f ; wc -l $f | awk {'print $1'})\nif [ $count -eq 1 ]; then\n\texit 1\nfi\nif [ $count -eq 2 ]; then\n\texit 0\nfi\nwhile true; do sleep 1; done\n"],"resources":{},"terminationMessagePath":"/dev/termination-log"}} + // `, + json: `{"msg":"Creating container in pod","v":0,"container":"&Container{Name:terminate-cmd-rpn,Image:k8s.gcr.io/e2e-test-images/busybox:1.29-2,Command:[sh -c \nf=/restart-count/restartCount\ncount=$(echo 'hello' >> $f ; wc -l $f | awk {'print $1'})\nif [ $count -eq 1 ]; then\n\texit 1\nfi\nif [ $count -eq 2 ]; then\n\texit 0\nfi\nwhile true; do sleep 1; done\n],Args:[],WorkingDir:,Ports:[]ContainerPort{},Env:[]EnvVar{},Resources:ResourceRequirements{Limits:ResourceList{},Requests:ResourceList{},},VolumeMounts:[]VolumeMount{},LivenessProbe:nil,ReadinessProbe:nil,Lifecycle:nil,TerminationMessagePath:/dev/termination-log,ImagePullPolicy:,SecurityContext:nil,Stdin:false,StdinOnce:false,TTY:false,EnvFrom:[]EnvFromSource{},TerminationMessagePolicy:,VolumeDevices:[]VolumeDevice{},StartupProbe:nil,}"} +`, + stats: logStats{ + TotalLines: 2, + JsonLines: 1, + ArgCounts: map[string]int{ + totalArg: 1, + otherArg: 1, + }, + OtherLines: []string{ + "0: # This is a manually created message. See https://github.com/kubernetes/kubernetes/issues/106652 for the real one.", + }, + OtherArgs: []interface{}{ + &container, + }, + }, + }, + } + + for path, expected := range testcases { + t.Run(path, func(t *testing.T) { + messages, stats, err := loadLog(path) + if err != nil { + t.Fatalf("unexpected load error: %v", err) + } + assert.Equal(t, expected.messages, messages) + assert.Equal(t, expected.stats, stats) + print := func(format func(item logMessage)) { + for _, item := range expected.messages { + format(item) + } + } + testBuffered := func(t *testing.T, expected string, format func(item logMessage)) { + var buffer bytes.Buffer + klog.SetOutput(&buffer) + defer klog.SetOutput(&output) + + print(format) + klog.Flush() + assert.Equal(t, expected, buffer.String()) + } + + t.Run("printf", func(t *testing.T) { + testBuffered(t, expected.printf, printf) + }) + t.Run("structured", func(t *testing.T) { + testBuffered(t, expected.structured, prints) + }) + t.Run("json", func(t *testing.T) { + var buffer bytes.Buffer + logger := newJSONLogger(&buffer) + klog.SetLogger(logger) + defer klog.ClearLogger() + print(prints) + klog.Flush() + assert.Equal(t, expected.json, buffer.String()) + }) + }) + } +}