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

@@ -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

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/<file name>.log` and run benchmarking as described
+above.  `-bench=BenchmarkLogging/<file name without .log suffix>` can be used
+to benchmark just the new file.
+
+When using `data/v<some number>/<file name>.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/<job ID> .
+```
+
+## 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 .
+```

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

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

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

staging/src/k8s.io/component-base/logs/benchmark/data/error-value.log

@@ -0,0 +1 @@
+{"v":0, "msg": "Pod status update", "err": "failed"}

staging/src/k8s.io/component-base/logs/benchmark/data/error.log

@@ -0,0 +1 @@
+{"msg": "Pod status update", "err": "failed"}

staging/src/k8s.io/component-base/logs/benchmark/data/simple.log

@@ -0,0 +1 @@
+{"v": 0, "msg": "Pod status updated"}

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

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

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