From 10888e7a3ed17d1b307f3f324460d09ec1c13b0c Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 14 Feb 2022 10:38:17 +0100 Subject: [PATCH 01/12] README.md: clarify API stability We need the ability to make experimental changes without new definitions immediately becoming part of the stable v2 API. --- README.md | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/README.md b/README.md index b52bfcdc..a9c945e1 100644 --- a/README.md +++ b/README.md @@ -23,6 +23,18 @@ Historical context is available here: * https://groups.google.com/forum/#!msg/kubernetes-sig-architecture/wCWiWf3Juzs/hXRVBH90CgAJ * https://groups.google.com/forum/#!msg/kubernetes-dev/7vnijOMhLS0/1oRiNtigBgAJ +## Release versioning + +Semantic versioning is used in this repository. It contains several Go modules +with different levels of stability: +- `k8s.io/klog/v2` - stable API, `vX.Y.Z` tags +- `k8s.io/tools` - no stable API yet (may change eventually), `tools/v0.Y.Z` tags +- `examples` - no stable API, no tags, no intention to ever stabilize + +Exempt from the API stability guarantee are items (packages, functions, etc.) +which are marked explicitly as `EXPERIMENTAL` in their docs comment. Those +may still change in incompatible ways or get removed entirely. + ---- How to use klog From 7cad178d464bfd8f2040c0425ccbecdfe2f77bf7 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 9 Feb 2022 16:57:32 +0100 Subject: [PATCH 02/12] test: unified testing of structured logging The new test cases are applied to structured logging calls in klog and the stand-alone klogr logger with output through klog. The output is expected to be the same. --- test/output.go | 464 ++++++++++++++++++++++++++++++++++++++++++ test/output_helper.go | 32 +++ test/output_test.go | 62 ++++++ 3 files changed, 558 insertions(+) create mode 100644 test/output.go create mode 100644 test/output_helper.go create mode 100644 test/output_test.go diff --git a/test/output.go b/test/output.go new file mode 100644 index 00000000..f0a883eb --- /dev/null +++ b/test/output.go @@ -0,0 +1,464 @@ +/* +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 test contains a reusable unit test for logging output and behavior. +// +// Experimental +// +// Notice: This package is EXPERIMENTAL and may be changed or removed in a +// later release. +package test + +import ( + "bytes" + "encoding/json" + "errors" + "flag" + "fmt" + "io" + "regexp" + "runtime" + "strings" + "testing" + "time" + + "github.com/go-logr/logr" + + "k8s.io/klog/v2" +) + +// InitKlog must be called once in an init function of a test package to +// configure klog for testing with Output. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func InitKlog() { + // klog gets configured so that it writes to a single output file that + // will be set during tests with SetOutput. + klog.InitFlags(nil) + flag.Set("v", "10") + flag.Set("log_file", "/dev/null") + flag.Set("logtostderr", "false") + flag.Set("alsologtostderr", "false") + flag.Set("stderrthreshold", "10") +} + +// OutputConfig contains optional settings for Output. +// +// Experimental +// +// Notice: This type is EXPERIMENTAL and may be changed or removed in a +// later release. +type OutputConfig struct { + // NewLogger is called to create a new logger. If nil, output via klog + // is tested. Support for -vmodule is optional. + NewLogger func(out io.Writer, v int, vmodule string) logr.Logger + + // AsBackend enables testing through klog and the logger set there with + // SetLogger. + AsBackend bool + + // ExpectedOutputMapping replaces the builtin expected output for test + // cases with something else. If nil or a certain case is not present, + // the original text is used. + // + // The expected output uses as a placeholder for the line of the + // log call. The source code is always the output.go file itself. When + // testing a logger directly, is used for the first + // WithValues call, for a second and + // for a third. + ExpectedOutputMapping map[string]string + + // SupportsVModule indicates that the logger supports the vmodule + // parameter. Ignored when logging through klog. + SupportsVModule bool +} + +// Output covers various special cases of emitting log output. +// It can be used for arbitrary logr.Logger implementations. +// +// The expected output is what klog would print. When testing loggers +// that emit different output, a mapping from klog output to the +// corresponding logger output must be provided, otherwise the +// test will compare against the expected klog output. +// +// Loggers will be tested with direct calls to Info or +// as backend for klog. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. The test cases and thus the expected output also may +// change. +func Output(t *testing.T, config OutputConfig) { + tests := map[string]struct { + withHelper bool // use wrappers that get skipped during stack unwinding + withNames []string + // For a first WithValues call: logger1 := logger.WithValues() + withValues []interface{} + // For another WithValues call: logger2 := logger1.WithValues() + moreValues []interface{} + // For another WithValues call on the same logger as before: logger3 := logger1.WithValues() + evenMoreValues []interface{} + v int + vmodule string + text string + values []interface{} + err error + expectedOutput string + }{ + "log with values": { + text: "test", + values: []interface{}{"akey", "avalue"}, + expectedOutput: `I output.go:] "test" akey="avalue" +`, + }, + "call depth": { + text: "helper", + withHelper: true, + values: []interface{}{"akey", "avalue"}, + expectedOutput: `I output.go:] "helper" akey="avalue" +`, + }, + "verbosity enabled": { + text: "you see me", + v: 9, + expectedOutput: `I output.go:] "you see me" +`, + }, + "verbosity disabled": { + text: "you don't see me", + v: 11, + }, + "vmodule": { + text: "v=11: you see me because of -vmodule output=11", + v: 11, + vmodule: "output=11", + }, + "other vmodule": { + text: "v=11: you still don't see me because of -vmodule output_helper=11", + v: 11, + vmodule: "output_helper=11", + }, + "log with name and values": { + withNames: []string{"me"}, + text: "test", + values: []interface{}{"akey", "avalue"}, + expectedOutput: `I output.go:] "me: test" akey="avalue" +`, + }, + "log with multiple names and values": { + withNames: []string{"hello", "world"}, + text: "test", + values: []interface{}{"akey", "avalue"}, + expectedOutput: `I output.go:] "hello/world: test" akey="avalue" +`, + }, + "override single value": { + withValues: []interface{}{"akey", "avalue"}, + text: "test", + values: []interface{}{"akey", "avalue2"}, + expectedOutput: `I output.go:] "test" akey="avalue2" +`, + }, + "override WithValues": { + withValues: []interface{}{"duration", time.Hour, "X", "y"}, + text: "test", + values: []interface{}{"duration", time.Minute, "A", "b"}, + expectedOutput: `I output.go:] "test" X="y" duration="1m0s" A="b" +`, + }, + "odd WithValues": { + withValues: []interface{}{"keyWithoutValue"}, + moreValues: []interface{}{"anotherKeyWithoutValue"}, + text: "test", + expectedOutput: `I output.go:] "test" keyWithoutValue="(MISSING)" +I output.go:] "test" keyWithoutValue="(MISSING)" anotherKeyWithoutValue="(MISSING)" +I output.go:] "test" keyWithoutValue="(MISSING)" +`, + }, + "multiple WithValues": { + withValues: []interface{}{"firstKey", 1}, + moreValues: []interface{}{"secondKey", 2}, + evenMoreValues: []interface{}{"secondKey", 3}, + text: "test", + expectedOutput: `I output.go:] "test" firstKey=1 +I output.go:] "test" firstKey=1 secondKey=2 +I output.go:] "test" firstKey=1 +I output.go:] "test" firstKey=1 secondKey=3 +`, + }, + "empty WithValues": { + withValues: []interface{}{}, + text: "test", + expectedOutput: `I output.go:] "test" +`, + }, + // TODO: unify behavior of loggers. + // klog doesn't deduplicate, klogr and textlogger do. We can ensure via static code analysis + // that this doesn't occur, so we shouldn't pay the runtime overhead for deduplication here + // and remove that from klogr and textlogger (https://github.com/kubernetes/klog/issues/286). + // "print duplicate keys in arguments": { + // text: "test", + // values: []interface{}{"akey", "avalue", "akey", "avalue2"}, + // expectedOutput: `I output.go:] "test" akey="avalue" akey="avalue2" + // `, + // }, + "preserve order of key/value pairs": { + withValues: []interface{}{"akey9", "avalue9", "akey8", "avalue8", "akey1", "avalue1"}, + text: "test", + values: []interface{}{"akey5", "avalue5", "akey4", "avalue4"}, + expectedOutput: `I output.go:] "test" akey9="avalue9" akey8="avalue8" akey1="avalue1" akey5="avalue5" akey4="avalue4" +`, + }, + "handle odd-numbers of KVs": { + text: "test", + values: []interface{}{"akey", "avalue", "akey2"}, + expectedOutput: `I output.go:] "test" akey="avalue" akey2="(MISSING)" +`, + }, + "html characters": { + text: "test", + values: []interface{}{"akey", "<&>"}, + expectedOutput: `I output.go:] "test" akey="<&>" +`, + }, + "quotation": { + text: `"quoted"`, + values: []interface{}{"key", `"quoted value"`}, + expectedOutput: `I output.go:] "\"quoted\"" key="\"quoted value\"" +`, + }, + "handle odd-numbers of KVs in both log values and Info args": { + withValues: []interface{}{"basekey1", "basevar1", "basekey2"}, + text: "test", + values: []interface{}{"akey", "avalue", "akey2"}, + expectedOutput: `I output.go:] "test" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)" +`, + }, + "KObj": { + text: "test", + values: []interface{}{"pod", klog.KObj(&kmeta{Name: "pod-1", Namespace: "kube-system"})}, + expectedOutput: `I output.go:] "test" pod="kube-system/pod-1" +`, + }, + "KObjs": { + text: "test", + values: []interface{}{"pods", + klog.KObjs([]interface{}{ + &kmeta{Name: "pod-1", Namespace: "kube-system"}, + &kmeta{Name: "pod-2", Namespace: "kube-system"}, + })}, + expectedOutput: `I output.go:] "test" pods=[kube-system/pod-1 kube-system/pod-2] +`, + }, + "regular error types as value": { + text: "test", + values: []interface{}{"err", errors.New("whoops")}, + expectedOutput: `I output.go:] "test" err="whoops" +`, + }, + "ignore MarshalJSON": { + text: "test", + values: []interface{}{"err", &customErrorJSON{"whoops"}}, + expectedOutput: `I output.go:] "test" err="whoops" +`, + }, + "regular error types when using logr.Error": { + text: "test", + err: errors.New("whoops"), + expectedOutput: `E output.go:] "test" err="whoops" +`, + }, + } + for n, test := range tests { + t.Run(n, func(t *testing.T) { + printWithLogger := func(logger logr.Logger) { + for _, name := range test.withNames { + logger = logger.WithName(name) + } + // When we have multiple WithValues calls, we test + // first with the initial set of additional values, then + // the combination, then again the original logger. + // It must not have been modified. This produces + // three log entries. + logger = logger.WithValues(test.withValues...) + loggers := []logr.Logger{logger} + if test.moreValues != nil { + loggers = append(loggers, logger.WithValues(test.moreValues...), logger) + } + if test.evenMoreValues != nil { + loggers = append(loggers, logger.WithValues(test.evenMoreValues...)) + } + for _, logger := range loggers { + if test.withHelper { + loggerHelper(logger, test.text, test.values) + } else if test.err != nil { + logger.Error(test.err, test.text, test.values...) + } else { + logger.V(test.v).Info(test.text, test.values...) + } + } + } + _, _, printWithLoggerLine, _ := runtime.Caller(0) + + printWithKlog := func() { + kv := []interface{}{} + haveKeyInValues := func(key interface{}) bool { + for i := 0; i < len(test.values); i += 2 { + if key == test.values[i] { + return true + } + } + return false + } + appendKV := func(withValues []interface{}) { + if len(withValues)%2 != 0 { + withValues = append(withValues, "(MISSING)") + } + for i := 0; i < len(withValues); i += 2 { + if !haveKeyInValues(withValues[i]) { + kv = append(kv, withValues[i], withValues[i+1]) + } + } + } + // Here we need to emulate the handling of WithValues above. + appendKV(test.withValues) + kvs := [][]interface{}{copySlice(kv)} + if test.moreValues != nil { + appendKV(test.moreValues) + kvs = append(kvs, copySlice(kv), copySlice(kvs[0])) + } + if test.evenMoreValues != nil { + kv = copySlice(kvs[0]) + appendKV(test.evenMoreValues) + kvs = append(kvs, copySlice(kv)) + } + for _, kv := range kvs { + if len(test.values) > 0 { + kv = append(kv, test.values...) + } + text := test.text + if len(test.withNames) > 0 { + text = strings.Join(test.withNames, "/") + ": " + text + } + if test.withHelper { + klogHelper(text, kv) + } else if test.err != nil { + klog.ErrorS(test.err, text, kv...) + } else { + klog.V(klog.Level(test.v)).InfoS(text, kv...) + } + } + } + _, _, printWithKlogLine, _ := runtime.Caller(0) + + testOutput := func(t *testing.T, expectedLine int, print func(buffer *bytes.Buffer)) { + var tmpWriteBuffer bytes.Buffer + klog.SetOutput(&tmpWriteBuffer) + print(&tmpWriteBuffer) + klog.Flush() + + actual := tmpWriteBuffer.String() + // Strip varying header. + re := `(?m)^(.).... ..:..:......... ....... output.go` + actual = regexp.MustCompile(re).ReplaceAllString(actual, `${1} output.go`) + + // Inject expected line. This matches the if checks above, which are + // the same for both printWithKlog and printWithLogger. + callLine := expectedLine + if test.withHelper { + callLine -= 8 + } else if test.err != nil { + callLine -= 6 + } else { + callLine -= 4 + } + expected := test.expectedOutput + if repl, ok := config.ExpectedOutputMapping[expected]; ok { + expected = repl + } + expected = strings.ReplaceAll(expected, "", fmt.Sprintf("%d", callLine)) + expected = strings.ReplaceAll(expected, "", fmt.Sprintf("%d", expectedLine-18)) + expected = strings.ReplaceAll(expected, "", fmt.Sprintf("%d", expectedLine-15)) + expected = strings.ReplaceAll(expected, "", fmt.Sprintf("%d", expectedLine-12)) + if actual != expected { + t.Errorf("Output mismatch. Expected:\n%s\nActual:\n%s\n", expected, actual) + } + } + + if config.NewLogger == nil { + // Test klog. + testOutput(t, printWithKlogLine, func(buffer *bytes.Buffer) { + printWithKlog() + }) + return + } + + if config.AsBackend { + testOutput(t, printWithKlogLine, func(buffer *bytes.Buffer) { + klog.SetLogger(config.NewLogger(buffer, 10, "")) + defer klog.ClearLogger() + printWithKlog() + }) + return + } + + if test.vmodule != "" && !config.SupportsVModule { + t.Skip("vmodule not supported") + } + + testOutput(t, printWithLoggerLine, func(buffer *bytes.Buffer) { + printWithLogger(config.NewLogger(buffer, 10, test.vmodule)) + }) + }) + } +} + +func copySlice(in []interface{}) []interface{} { + return append([]interface{}{}, in...) +} + +type kmeta struct { + Name, Namespace string +} + +func (k kmeta) GetName() string { + return k.Name +} + +func (k kmeta) GetNamespace() string { + return k.Namespace +} + +var _ klog.KMetadata = kmeta{} + +type customErrorJSON struct { + s string +} + +var _ error = &customErrorJSON{} +var _ json.Marshaler = &customErrorJSON{} + +func (e *customErrorJSON) Error() string { + return e.s +} + +func (e *customErrorJSON) MarshalJSON() ([]byte, error) { + return json.Marshal(strings.ToUpper(e.s)) +} diff --git a/test/output_helper.go b/test/output_helper.go new file mode 100644 index 00000000..499395e3 --- /dev/null +++ b/test/output_helper.go @@ -0,0 +1,32 @@ +/* +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 test + +import ( + "github.com/go-logr/logr" + + "k8s.io/klog/v2" +) + +func loggerHelper(logger logr.Logger, msg string, kv []interface{}) { + logger = logger.WithCallDepth(1) + logger.Info(msg, kv...) +} + +func klogHelper(msg string, kv []interface{}) { + klog.InfoSDepth(1, msg, kv...) +} diff --git a/test/output_test.go b/test/output_test.go new file mode 100644 index 00000000..9b316176 --- /dev/null +++ b/test/output_test.go @@ -0,0 +1,62 @@ +/* +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 test + +import ( + "io" + "testing" + + "github.com/go-logr/logr" + + "k8s.io/klog/v2/klogr" +) + +func init() { + InitKlog() +} + +// TestKlogOutput tests klog output without a logger. +func TestKlogOutput(t *testing.T) { + Output(t, OutputConfig{}) +} + +// TestKlogrOutput tests klogr output via klog. +func TestKlogrOutput(t *testing.T) { + // klogr currently doesn't produce exactly the same output as klog. + // TODO: fix that. + mapping := map[string]string{ + `I output.go:] "test" keyWithoutValue="(MISSING)" +I output.go:] "test" keyWithoutValue="(MISSING)" anotherKeyWithoutValue="(MISSING)" +I output.go:] "test" keyWithoutValue="(MISSING)" +`: `I output.go:] "test" keyWithoutValue= +I output.go:] "test" keyWithoutValue="anotherKeyWithoutValue" +I output.go:] "test" keyWithoutValue= +`, + `I output.go:] "test" akey="avalue" akey2="(MISSING)" +`: `I output.go:] "test" akey="avalue" akey2= +`, + `I output.go:] "test" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)" +`: `I output.go:] "test" basekey1="basevar1" basekey2= akey="avalue" akey2= +`, + } + Output(t, OutputConfig{ + NewLogger: func(out io.Writer, v int, vmodule string) logr.Logger { + return klogr.NewWithOptions(klogr.WithFormat(klogr.FormatKlog)) + }, + ExpectedOutputMapping: mapping, + }) +} From 5a670a2897664c9d5e93645a462b5beff76e7565 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Thu, 10 Feb 2022 18:24:23 +0100 Subject: [PATCH 03/12] test: add systematic testing of all klog functions klog has a lot of functions, but not all of them are covered with unit tests. Only a few check stack unwinding. This new test is designed to: - check stack unwinding for all functions - check the difference between fmt.Print and fmt.Println (only the latter inserts spaces between strings) - check the output with and without a Logger This therefore covers bugs in https://github.com/kubernetes/klog/pull/280: - depth was not passed on to Logger - ErrorlnDepth and WarninglnDepth used fmt.Print instead of fmt.Println --- test/output.go | 224 +++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 224 insertions(+) diff --git a/test/output.go b/test/output.go index f0a883eb..0448bea2 100644 --- a/test/output.go +++ b/test/output.go @@ -31,6 +31,7 @@ import ( "io" "regexp" "runtime" + "strconv" "strings" "testing" "time" @@ -428,6 +429,229 @@ I output.go:] "test" firstKey=1 secondKey=3 }) }) } + + if config.NewLogger == nil || config.AsBackend { + // Test all klog output functions. + // + // Each test case must be defined with the same number of + // lines, then the source code location of the call itself + // can be computed below. + tests := []struct { + name string + logFunc func() + output string + }{ + { + name: "Info", + logFunc: func() { klog.Info("hello", "world") }, + output: "I output.go:] helloworld\n", // This looks odd, but simply is how klog works. + }, + { + name: "InfoDepth", + logFunc: func() { klog.InfoDepth(0, "hello", "world") }, + output: "I output.go:] helloworld\n", + }, + { + name: "Infoln", + logFunc: func() { klog.Infoln("hello", "world") }, + output: "I output.go:] hello world\n", + }, + { + name: "InfolnDepth", + logFunc: func() { klog.InfolnDepth(0, "hello", "world") }, + output: "I output.go:] hello world\n", + }, + { + name: "Infof", + logFunc: func() { klog.Infof("hello %s", "world") }, + output: "I output.go:] hello world\n", + }, + { + name: "InfofDepth", + logFunc: func() { klog.InfofDepth(0, "hello %s", "world") }, + output: "I output.go:] hello world\n", + }, + { + name: "InfoS", + logFunc: func() { klog.InfoS("hello", "what", "world") }, + output: "I output.go:] \"hello\" what=\"world\"\n", + }, + { + name: "InfoSDepth", + logFunc: func() { klog.InfoSDepth(0, "hello", "what", "world") }, + output: "I output.go:] \"hello\" what=\"world\"\n", + }, + { + name: "Warning", + logFunc: func() { klog.Warning("hello", "world") }, + output: "W output.go:] helloworld\n", + }, + { + name: "WarningDepth", + logFunc: func() { klog.WarningDepth(0, "hello", "world") }, + output: "W output.go:] helloworld\n", + }, + { + name: "Warningln", + logFunc: func() { klog.Warningln("hello", "world") }, + output: "W output.go:] hello world\n", + }, + { + name: "WarninglnDepth", + logFunc: func() { klog.WarninglnDepth(0, "hello", "world") }, + output: "W output.go:] helloworld\n", // BUG + }, + { + name: "Warningf", + logFunc: func() { klog.Warningf("hello %s", "world") }, + output: "W output.go:] hello world\n", + }, + { + name: "WarningfDepth", + logFunc: func() { klog.WarningfDepth(0, "hello %s", "world") }, + output: "W output.go:] hello world\n", + }, + { + name: "Error", + logFunc: func() { klog.Error("hello", "world") }, + output: "E output.go:] helloworld\n", + }, + { + name: "ErrorDepth", + logFunc: func() { klog.ErrorDepth(0, "hello", "world") }, + output: "E output.go:] helloworld\n", + }, + { + name: "Errorln", + logFunc: func() { klog.Errorln("hello", "world") }, + output: "E output.go:] hello world\n", + }, + { + name: "ErrorlnDepth", + logFunc: func() { klog.ErrorlnDepth(0, "hello", "world") }, + output: "E output.go:] helloworld\n", // BUG + }, + { + name: "Errorf", + logFunc: func() { klog.Errorf("hello %s", "world") }, + output: "E output.go:] hello world\n", + }, + { + name: "ErrorfDepth", + logFunc: func() { klog.ErrorfDepth(0, "hello %s", "world") }, + output: "E output.go:] hello world\n", + }, + { + name: "ErrorS", + logFunc: func() { klog.ErrorS(errors.New("hello"), "world") }, + output: "E output.go:] \"world\" err=\"hello\"\n", + }, + { + name: "ErrorSDepth", + logFunc: func() { klog.ErrorSDepth(0, errors.New("hello"), "world") }, + output: "E output.go:] \"world\" err=\"hello\"\n", + }, + { + name: "V().Info", + logFunc: func() { klog.V(1).Info("hello", "one", "world") }, + output: "I output.go:] hellooneworld\n", + }, + { + name: "V().InfoDepth", + logFunc: func() { klog.V(1).InfoDepth(0, "hello", "one", "world") }, + output: "I output.go:] hellooneworld\n", + }, + { + name: "V().Infoln", + logFunc: func() { klog.V(1).Infoln("hello", "one", "world") }, + output: "I output.go:] hello one world\n", + }, + { + name: "V().InfolnDepth", + logFunc: func() { klog.V(1).InfolnDepth(0, "hello", "one", "world") }, + output: "I output.go:] hello one world\n", + }, + { + name: "V().Infof", + logFunc: func() { klog.V(1).Infof("hello %s %s", "one", "world") }, + output: "I output.go:] hello one world\n", + }, + { + name: "V().InfofDepth", + logFunc: func() { klog.V(1).InfofDepth(0, "hello %s %s", "one", "world") }, + output: "I output.go:] hello one world\n", + }, + { + name: "V().InfoS", + logFunc: func() { klog.V(1).InfoS("hello", "what", "one world") }, + output: "I output.go:] \"hello\" what=\"one world\"\n", + }, + { + name: "V().InfoSDepth", + logFunc: func() { klog.V(1).InfoSDepth(0, "hello", "what", "one world") }, + output: "I output.go:] \"hello\" what=\"one world\"\n", + }, + { + name: "V().ErrorS", + logFunc: func() { klog.V(1).ErrorS(errors.New("hello"), "one world") }, + output: "E output.go:] \"one world\" err=\"hello\"\n", + }, + } + _, _, line, _ := runtime.Caller(0) + + for i, test := range tests { + t.Run(test.name, func(t *testing.T) { + var buffer bytes.Buffer + if config.NewLogger == nil { + klog.SetOutput(&buffer) + } else { + klog.SetLogger(config.NewLogger(&buffer, 10, "")) + defer klog.ClearLogger() + } + test.logFunc() + klog.Flush() + + actual := buffer.String() + // Strip varying header. + re := `(?m)^(.).... ..:..:......... ....... output.go` + actual = regexp.MustCompile(re).ReplaceAllString(actual, `${1} output.go`) + + // Inject expected line. This matches the if checks above, which are + // the same for both printWithKlog and printWithLogger. + callLine := line + 1 - (len(tests)-i)*5 + expected := test.output + + // When klog does string formating for + // non-structured calls, it passes the entire + // result, including a trailing newline, to + // Logger.Info. + if config.NewLogger != nil && + !strings.HasSuffix(test.name, "S") && + !strings.HasSuffix(test.name, "SDepth") { + // klog: I output.go:] hello world + // with logger: I output.go:] "hello world\n" + index := strings.Index(expected, "] ") + if index == -1 { + t.Fatalf("did not find ] separator: %s", expected) + } + expected = expected[0:index+2] + strconv.Quote(expected[index+2:]) + "\n" + + // Warnings become info messages. + if strings.HasPrefix(expected, "W") { + expected = "I" + expected[1:] + } + } + + if repl, ok := config.ExpectedOutputMapping[expected]; ok { + expected = repl + } + expected = strings.ReplaceAll(expected, "", fmt.Sprintf("%d", callLine)) + if actual != expected { + t.Errorf("Output mismatch. Expected:\n%s\nActual:\n%s\n", expected, actual) + } + }) + } + } } func copySlice(in []interface{}) []interface{} { From 51711a37e60fb7e141eabe4919ae0031778c5822 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 7 Feb 2022 20:43:52 +0100 Subject: [PATCH 04/12] fix for off-by-one stack unwinding https://github.com/kubernetes/klog/pull/280/ turned println and printf into wrapper functions, but the underlying *Depth functions kept passing the same 0 depth to l.output and thus any logr.Logger. That off-by-one error broke JSON tests in Kubernetes, luckily well before any of the PR went into a release. It would be nice to have regression testing for this in klog, but we cannot depend on a Logger which does stack unwinding in the code, so the only thing that could be done is some kind of GitHub action which combines klog with some external logger. The depth=1 in println is also not covered by unit tests, but seems to be correct based on the JSON tests. --- klog.go | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/klog.go b/klog.go index 7cf60f9e..96086a42 100644 --- a/klog.go +++ b/klog.go @@ -714,7 +714,7 @@ func (l *loggingT) printlnDepth(s severity, logger *logr.Logger, filter LogFilte args = filter.Filter(args) } fmt.Fprintln(buf, args...) - l.output(s, logger, buf, 0 /* depth */, file, line, false) + l.output(s, logger, buf, depth, file, line, false) } func (l *loggingT) print(s severity, logger *logr.Logger, filter LogFilter, args ...interface{}) { @@ -758,7 +758,7 @@ func (l *loggingT) printfDepth(s severity, logger *logr.Logger, filter LogFilter if buf.Bytes()[buf.Len()-1] != '\n' { buf.WriteByte('\n') } - l.output(s, logger, buf, 0 /* depth */, file, line, false) + l.output(s, logger, buf, depth, file, line, false) } // printWithFileLine behaves like print but uses the provided file and line number. If From 5deb0375b928d21265e2818d1b58923552ba1c71 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Thu, 10 Feb 2022 18:22:35 +0100 Subject: [PATCH 05/12] fix new *lnDepth functions https://github.com/kubernetes/klog/pull/280 added several new functions and didn't quite get the print vs println difference right: the corresponding non-Depth functions use fmt.Println and the Depth versions should do the same. --- klog.go | 8 ++++---- test/output.go | 4 ++-- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/klog.go b/klog.go index 96086a42..26c532b5 100644 --- a/klog.go +++ b/klog.go @@ -1615,7 +1615,7 @@ func Warningln(args ...interface{}) { // WarninglnDepth acts as Warningln but uses depth to determine which call frame to log. // WarninglnDepth(0, "msg") is the same as Warningln("msg"). func WarninglnDepth(depth int, args ...interface{}) { - logging.printDepth(warningLog, logging.logr, logging.filter, depth, args...) + logging.printlnDepth(warningLog, logging.logr, logging.filter, depth, args...) } // Warningf logs to the WARNING and INFO logs. @@ -1651,7 +1651,7 @@ func Errorln(args ...interface{}) { // ErrorlnDepth acts as Errorln but uses depth to determine which call frame to log. // ErrorlnDepth(0, "msg") is the same as Errorln("msg"). func ErrorlnDepth(depth int, args ...interface{}) { - logging.printDepth(errorLog, logging.logr, logging.filter, depth, args...) + logging.printlnDepth(errorLog, logging.logr, logging.filter, depth, args...) } // Errorf logs to the ERROR, WARNING, and INFO logs. @@ -1708,7 +1708,7 @@ func Fatalln(args ...interface{}) { // FatallnDepth acts as Fatalln but uses depth to determine which call frame to log. // FatallnDepth(0, "msg") is the same as Fatalln("msg"). func FatallnDepth(depth int, args ...interface{}) { - logging.printDepth(fatalLog, logging.logr, logging.filter, depth, args...) + logging.printlnDepth(fatalLog, logging.logr, logging.filter, depth, args...) } // Fatalf logs to the FATAL, ERROR, WARNING, and INFO logs, @@ -1752,7 +1752,7 @@ func Exitln(args ...interface{}) { // ExitlnDepth(0, "msg") is the same as Exitln("msg"). func ExitlnDepth(depth int, args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) - logging.printDepth(fatalLog, logging.logr, logging.filter, depth, args...) + logging.printlnDepth(fatalLog, logging.logr, logging.filter, depth, args...) } // Exitf logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1). diff --git a/test/output.go b/test/output.go index 0448bea2..a4174914 100644 --- a/test/output.go +++ b/test/output.go @@ -499,7 +499,7 @@ I output.go:] "test" firstKey=1 secondKey=3 { name: "WarninglnDepth", logFunc: func() { klog.WarninglnDepth(0, "hello", "world") }, - output: "W output.go:] helloworld\n", // BUG + output: "W output.go:] hello world\n", }, { name: "Warningf", @@ -529,7 +529,7 @@ I output.go:] "test" firstKey=1 secondKey=3 { name: "ErrorlnDepth", logFunc: func() { klog.ErrorlnDepth(0, "hello", "world") }, - output: "E output.go:] helloworld\n", // BUG + output: "E output.go:] hello world\n", }, { name: "Errorf", From 08936589e47dd79c5d00c358219693e50a46c700 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 9 Feb 2022 09:27:59 +0100 Subject: [PATCH 06/12] test: benchmark for V The implementation of V is performance critical: it may get called frequently on hot code paths and will be responsible for all of the logging overhead when the log messages then do not need to be formatted. --- klog_test.go | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/klog_test.go b/klog_test.go index 17caaf4e..82f23d8a 100644 --- a/klog_test.go +++ b/klog_test.go @@ -623,6 +623,15 @@ func BenchmarkHeaderWithDir(b *testing.B) { // Ensure that benchmarks have side effects to avoid compiler optimization var result ObjectRef +var enabled bool + +func BenchmarkV(b *testing.B) { + var v Verbose + for i := 0; i < b.N; i++ { + v = V(10) + } + enabled = v.Enabled() +} func BenchmarkKRef(b *testing.B) { var r ObjectRef From ec9f867305d3a6ed08e47cf5d4d4e503f06fc1e5 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 9 Feb 2022 09:31:26 +0100 Subject: [PATCH 07/12] internal: stand-alone implementation of -v and -verbose This will be needed for Logger implementations that want to emulate the traditional verbosity check in klog. The original code in klog.go intentionally doesn't get modified, for two reasons: - avoid the risk of regressions - an attempt to do so showed that V became slower (extra calls, more parameters, etc.) --- internal/verbosity/helper_test.go | 21 ++ internal/verbosity/verbosity.go | 305 +++++++++++++++++++++++++++ internal/verbosity/verbosity_test.go | 97 +++++++++ 3 files changed, 423 insertions(+) create mode 100644 internal/verbosity/helper_test.go create mode 100644 internal/verbosity/verbosity.go create mode 100644 internal/verbosity/verbosity_test.go diff --git a/internal/verbosity/helper_test.go b/internal/verbosity/helper_test.go new file mode 100644 index 00000000..9ec70c76 --- /dev/null +++ b/internal/verbosity/helper_test.go @@ -0,0 +1,21 @@ +/* +Copyright 2022 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 verbosity + +func enabledInHelper(vs *VState, l Level) bool { + return vs.Enabled(l, 0) +} diff --git a/internal/verbosity/verbosity.go b/internal/verbosity/verbosity.go new file mode 100644 index 00000000..309cdfaa --- /dev/null +++ b/internal/verbosity/verbosity.go @@ -0,0 +1,305 @@ +/* +Copyright 2013 Google Inc. All Rights Reserved. +Copyright 2022 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 verbosity + +import ( + "bytes" + "errors" + "flag" + "fmt" + "path/filepath" + "runtime" + "strconv" + "strings" + "sync" + "sync/atomic" +) + +// New returns a struct that implements -v and -vmodule support. Changing and +// checking these settings is thread-safe, with all concurrency issues handled +// internally. +func New() *VState { + vs := new(VState) + + // The two fields must have a pointer to the overal struct for their + // implementation of Set. + vs.vmodule.vs = vs + vs.verbosity.vs = vs + + return vs +} + +// Value is an extension that makes it possible to use the values in pflag. +type Value interface { + flag.Value + Type() string +} + +func (vs *VState) V() Value { + return &vs.verbosity +} + +func (vs *VState) VModule() Value { + return &vs.vmodule +} + +// VState contains settings and state. Some of its fields can be accessed +// through atomic read/writes, in other cases a mutex must be held. +type VState struct { + mu sync.Mutex + + // These flags are modified only under lock, although verbosity may be fetched + // safely using atomic.LoadInt32. + vmodule moduleSpec // The state of the -vmodule flag. + verbosity levelSpec // V logging level, the value of the -v flag/ + + // pcs is used in V to avoid an allocation when computing the caller's PC. + pcs [1]uintptr + // vmap is a cache of the V Level for each V() call site, identified by PC. + // It is wiped whenever the vmodule flag changes state. + vmap map[uintptr]Level + // filterLength stores the length of the vmodule filter chain. If greater + // than zero, it means vmodule is enabled. It may be read safely + // using sync.LoadInt32, but is only modified under mu. + filterLength int32 +} + +// Level must be an int32 to support atomic read/writes. +type Level int32 + +type levelSpec struct { + vs *VState + l Level +} + +// get returns the value of the level. +func (l *levelSpec) get() Level { + return Level(atomic.LoadInt32((*int32)(&l.l))) +} + +// set sets the value of the level. +func (l *levelSpec) set(val Level) { + atomic.StoreInt32((*int32)(&l.l), int32(val)) +} + +// String is part of the flag.Value interface. +func (l *levelSpec) String() string { + return strconv.FormatInt(int64(l.l), 10) +} + +// Get is part of the flag.Getter interface. It returns the +// verbosity level as int32. +func (l *levelSpec) Get() interface{} { + return int32(l.l) +} + +// Type is part of pflag.Value. +func (l *levelSpec) Type() string { + return "Level" +} + +// Set is part of the flag.Value interface. +func (l *levelSpec) Set(value string) error { + v, err := strconv.ParseInt(value, 10, 32) + if err != nil { + return err + } + l.vs.mu.Lock() + defer l.vs.mu.Unlock() + l.vs.set(Level(v), l.vs.vmodule.filter, false) + return nil +} + +// moduleSpec represents the setting of the -vmodule flag. +type moduleSpec struct { + vs *VState + filter []modulePat +} + +// modulePat contains a filter for the -vmodule flag. +// It holds a verbosity level and a file pattern to match. +type modulePat struct { + pattern string + literal bool // The pattern is a literal string + level Level +} + +// match reports whether the file matches the pattern. It uses a string +// comparison if the pattern contains no metacharacters. +func (m *modulePat) match(file string) bool { + if m.literal { + return file == m.pattern + } + match, _ := filepath.Match(m.pattern, file) + return match +} + +func (m *moduleSpec) String() string { + // Lock because the type is not atomic. TODO: clean this up. + // Empty instances don't have and don't need a lock (can + // happen when flag uses introspection). + if m.vs != nil { + m.vs.mu.Lock() + defer m.vs.mu.Unlock() + } + var b bytes.Buffer + for i, f := range m.filter { + if i > 0 { + b.WriteRune(',') + } + fmt.Fprintf(&b, "%s=%d", f.pattern, f.level) + } + return b.String() +} + +// Get is part of the (Go 1.2) flag.Getter interface. It always returns nil for this flag type since the +// struct is not exported. +func (m *moduleSpec) Get() interface{} { + return nil +} + +// Type is part of pflag.Value +func (m *moduleSpec) Type() string { + return "pattern=N,..." +} + +var errVmoduleSyntax = errors.New("syntax error: expect comma-separated list of filename=N") + +// Set will sets module value +// Syntax: -vmodule=recordio=2,file=1,gfs*=3 +func (m *moduleSpec) Set(value string) error { + var filter []modulePat + for _, pat := range strings.Split(value, ",") { + if len(pat) == 0 { + // Empty strings such as from a trailing comma can be ignored. + continue + } + patLev := strings.Split(pat, "=") + if len(patLev) != 2 || len(patLev[0]) == 0 || len(patLev[1]) == 0 { + return errVmoduleSyntax + } + pattern := patLev[0] + v, err := strconv.ParseInt(patLev[1], 10, 32) + if err != nil { + return errors.New("syntax error: expect comma-separated list of filename=N") + } + if v < 0 { + return errors.New("negative value for vmodule level") + } + if v == 0 { + continue // Ignore. It's harmless but no point in paying the overhead. + } + // TODO: check syntax of filter? + filter = append(filter, modulePat{pattern, isLiteral(pattern), Level(v)}) + } + m.vs.mu.Lock() + defer m.vs.mu.Unlock() + m.vs.set(m.vs.verbosity.l, filter, true) + return nil +} + +// isLiteral reports whether the pattern is a literal string, that is, has no metacharacters +// that require filepath.Match to be called to match the pattern. +func isLiteral(pattern string) bool { + return !strings.ContainsAny(pattern, `\*?[]`) +} + +// set sets a consistent state for V logging. +// The mutex must be held. +func (vs *VState) set(l Level, filter []modulePat, setFilter bool) { + // Turn verbosity off so V will not fire while we are in transition. + vs.verbosity.set(0) + // Ditto for filter length. + atomic.StoreInt32(&vs.filterLength, 0) + + // Set the new filters and wipe the pc->Level map if the filter has changed. + if setFilter { + vs.vmodule.filter = filter + vs.vmap = make(map[uintptr]Level) + } + + // Things are consistent now, so enable filtering and verbosity. + // They are enabled in order opposite to that in V. + atomic.StoreInt32(&vs.filterLength, int32(len(filter))) + vs.verbosity.set(l) +} + +// Enabled checks whether logging is enabled at the given level. This must be +// called with depth=0 when the caller of enabled will do the logging and +// higher values when more stack levels need to be skipped. +// +// The mutex will be locked only if needed. +func (vs *VState) Enabled(level Level, depth int) bool { + // This function tries hard to be cheap unless there's work to do. + // The fast path is two atomic loads and compares. + + // Here is a cheap but safe test to see if V logging is enabled globally. + if vs.verbosity.get() >= level { + return true + } + + // It's off globally but vmodule may still be set. + // Here is another cheap but safe test to see if vmodule is enabled. + if atomic.LoadInt32(&vs.filterLength) > 0 { + // Now we need a proper lock to use the logging structure. The pcs field + // is shared so we must lock before accessing it. This is fairly expensive, + // but if V logging is enabled we're slow anyway. + vs.mu.Lock() + defer vs.mu.Unlock() + if runtime.Callers(depth+2, vs.pcs[:]) == 0 { + return false + } + // runtime.Callers returns "return PCs", but we want + // to look up the symbolic information for the call, + // so subtract 1 from the PC. runtime.CallersFrames + // would be cleaner, but allocates. + pc := vs.pcs[0] - 1 + v, ok := vs.vmap[pc] + if !ok { + v = vs.setV(pc) + } + return v >= level + } + return false +} + +// setV computes and remembers the V level for a given PC +// when vmodule is enabled. +// File pattern matching takes the basename of the file, stripped +// of its .go suffix, and uses filepath.Match, which is a little more +// general than the *? matching used in C++. +// Mutex is held. +func (vs *VState) setV(pc uintptr) Level { + fn := runtime.FuncForPC(pc) + file, _ := fn.FileLine(pc) + // The file is something like /a/b/c/d.go. We want just the d. + if strings.HasSuffix(file, ".go") { + file = file[:len(file)-3] + } + if slash := strings.LastIndex(file, "/"); slash >= 0 { + file = file[slash+1:] + } + for _, filter := range vs.vmodule.filter { + if filter.match(file) { + vs.vmap[pc] = filter.level + return filter.level + } + } + vs.vmap[pc] = 0 + return 0 +} diff --git a/internal/verbosity/verbosity_test.go b/internal/verbosity/verbosity_test.go new file mode 100644 index 00000000..766147b2 --- /dev/null +++ b/internal/verbosity/verbosity_test.go @@ -0,0 +1,97 @@ +/* +Copyright 2013 Google Inc. All Rights Reserved. +Copyright 2022 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 verbosity + +import ( + "testing" +) + +func TestV(t *testing.T) { + vs := New() + vs.verbosity.Set("2") + depth := 0 + if !vs.Enabled(1, depth) { + t.Error("not enabled for 1") + } + if !vs.Enabled(2, depth) { + t.Error("not enabled for 2") + } + if vs.Enabled(3, depth) { + t.Error("enabled for 3") + } +} + +func TestVmoduleOn(t *testing.T) { + vs := New() + vs.vmodule.Set("verbosity_test=2") + depth := 0 + if !vs.Enabled(1, depth) { + t.Error("not enabled for 1") + } + if !vs.Enabled(2, depth) { + t.Error("not enabled for 2") + } + if vs.Enabled(3, depth) { + t.Error("enabled for 3") + } + if enabledInHelper(vs, 1) { + t.Error("enabled for helper at 1") + } + if enabledInHelper(vs, 2) { + t.Error("enabled for helper at 2") + } + if enabledInHelper(vs, 3) { + t.Error("enabled for helper at 3") + } +} + +// vGlobs are patterns that match/don't match this file at V=2. +var vGlobs = map[string]bool{ + // Easy to test the numeric match here. + "verbosity_test=1": false, // If -vmodule sets V to 1, V(2) will fail. + "verbosity_test=2": true, + "verbosity_test=3": true, // If -vmodule sets V to 1, V(3) will succeed. + // These all use 2 and check the patterns. All are true. + "*=2": true, + "?e*=2": true, + "?????????_*=2": true, + "??[arx]??????_*t=2": true, + // These all use 2 and check the patterns. All are false. + "*x=2": false, + "m*=2": false, + "??_*=2": false, + "?[abc]?_*t=2": false, +} + +// Test that vmodule globbing works as advertised. +func testVmoduleGlob(pat string, match bool, t *testing.T) { + vs := New() + vs.vmodule.Set(pat) + depth := 0 + actual := vs.Enabled(2, depth) + if actual != match { + t.Errorf("incorrect match for %q: got %#v expected %#v", pat, actual, match) + } +} + +// Test that a vmodule globbing works as advertised. +func TestVmoduleGlob(t *testing.T) { + for glob, match := range vGlobs { + testVmoduleGlob(glob, match, t) + } +} From 69f61114bd90486903459b6892e4985d2e24b0bc Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 9 Feb 2022 09:37:51 +0100 Subject: [PATCH 08/12] internal: move key/value handling into stand-alone package This makes it possible to reuse the klog output formatting in logr.Logger implementations. --- internal/serialize/keyvalues.go | 185 +++++++++++++++++++++++++++ internal/serialize/keyvalues_test.go | 151 ++++++++++++++++++++++ internal/test/mock.go | 40 ++++++ klog.go | 121 +----------------- klog_test.go | 175 +++---------------------- klogr/klogr.go | 60 ++------- 6 files changed, 405 insertions(+), 327 deletions(-) create mode 100644 internal/serialize/keyvalues.go create mode 100644 internal/serialize/keyvalues_test.go create mode 100644 internal/test/mock.go diff --git a/internal/serialize/keyvalues.go b/internal/serialize/keyvalues.go new file mode 100644 index 00000000..479a3735 --- /dev/null +++ b/internal/serialize/keyvalues.go @@ -0,0 +1,185 @@ +/* +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 serialize + +import ( + "bytes" + "fmt" + "strconv" +) + +// TrimDuplicates deduplicates elements provided in multiple key/value tuple +// slices, whilst maintaining the distinction between where the items are +// contained. +func TrimDuplicates(kvLists ...[]interface{}) [][]interface{} { + // maintain a map of all seen keys + seenKeys := map[interface{}]struct{}{} + // build the same number of output slices as inputs + outs := make([][]interface{}, len(kvLists)) + // iterate over the input slices backwards, as 'later' kv specifications + // of the same key will take precedence over earlier ones + for i := len(kvLists) - 1; i >= 0; i-- { + // initialise this output slice + outs[i] = []interface{}{} + // obtain a reference to the kvList we are processing + kvList := kvLists[i] + + // start iterating at len(kvList) - 2 (i.e. the 2nd last item) for + // slices that have an even number of elements. + // We add (len(kvList) % 2) here to handle the case where there is an + // odd number of elements in a kvList. + // If there is an odd number, then the last element in the slice will + // have the value 'null'. + for i2 := len(kvList) - 2 + (len(kvList) % 2); i2 >= 0; i2 -= 2 { + k := kvList[i2] + // if we have already seen this key, do not include it again + if _, ok := seenKeys[k]; ok { + continue + } + // make a note that we've observed a new key + seenKeys[k] = struct{}{} + // attempt to obtain the value of the key + var v interface{} + // i2+1 should only ever be out of bounds if we handling the first + // iteration over a slice with an odd number of elements + if i2+1 < len(kvList) { + v = kvList[i2+1] + } + // add this KV tuple to the *start* of the output list to maintain + // the original order as we are iterating over the slice backwards + outs[i] = append([]interface{}{k, v}, outs[i]...) + } + } + return outs +} + +const missingValue = "(MISSING)" + +// KVListFormat serializes all key/value pairs into the provided buffer. +// A space gets inserted before the first pair and between each pair. +func KVListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { + for i := 0; i < len(keysAndValues); i += 2 { + var v interface{} + k := keysAndValues[i] + if i+1 < len(keysAndValues) { + v = keysAndValues[i+1] + } else { + v = missingValue + } + b.WriteByte(' ') + // Keys are assumed to be well-formed according to + // https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#name-arguments + // for the sake of performance. Keys with spaces, + // special characters, etc. will break parsing. + if k, ok := k.(string); ok { + // Avoid one allocation when the key is a string, which + // normally it should be. + b.WriteString(k) + } else { + b.WriteString(fmt.Sprintf("%s", k)) + } + + // The type checks are sorted so that more frequently used ones + // come first because that is then faster in the common + // cases. In Kubernetes, ObjectRef (a Stringer) is more common + // than plain strings + // (https://github.com/kubernetes/kubernetes/pull/106594#issuecomment-975526235). + switch v := v.(type) { + case fmt.Stringer: + writeStringValue(b, true, stringerToString(v)) + case string: + writeStringValue(b, true, v) + case error: + writeStringValue(b, true, v.Error()) + case []byte: + // In https://github.com/kubernetes/klog/pull/237 it was decided + // to format byte slices with "%+q". The advantages of that are: + // - readable output if the bytes happen to be printable + // - non-printable bytes get represented as unicode escape + // sequences (\uxxxx) + // + // The downsides are that we cannot use the faster + // strconv.Quote here and that multi-line output is not + // supported. If developers know that a byte array is + // printable and they want multi-line output, they can + // convert the value to string before logging it. + b.WriteByte('=') + b.WriteString(fmt.Sprintf("%+q", v)) + default: + writeStringValue(b, false, fmt.Sprintf("%+v", v)) + } + } +} + +func stringerToString(s fmt.Stringer) (ret string) { + defer func() { + if err := recover(); err != nil { + ret = "nil" + } + }() + ret = s.String() + return +} + +func writeStringValue(b *bytes.Buffer, quote bool, v string) { + data := []byte(v) + index := bytes.IndexByte(data, '\n') + if index == -1 { + b.WriteByte('=') + if quote { + // Simple string, quote quotation marks and non-printable characters. + b.WriteString(strconv.Quote(v)) + return + } + // Non-string with no line breaks. + b.WriteString(v) + return + } + + // Complex multi-line string, show as-is with indention like this: + // I... "hello world" key=< + // line 1 + // line 2 + // > + // + // Tabs indent the lines of the value while the end of string delimiter + // is indented with a space. That has two purposes: + // - visual difference between the two for a human reader because indention + // will be different + // - no ambiguity when some value line starts with the end delimiter + // + // One downside is that the output cannot distinguish between strings that + // end with a line break and those that don't because the end delimiter + // will always be on the next line. + b.WriteString("=<\n") + for index != -1 { + b.WriteByte('\t') + b.Write(data[0 : index+1]) + data = data[index+1:] + index = bytes.IndexByte(data, '\n') + } + if len(data) == 0 { + // String ended with line break, don't add another. + b.WriteString(" >") + } else { + // No line break at end of last line, write rest of string and + // add one. + b.WriteByte('\t') + b.Write(data) + b.WriteString("\n >") + } +} diff --git a/internal/serialize/keyvalues_test.go b/internal/serialize/keyvalues_test.go new file mode 100644 index 00000000..f7fdaba3 --- /dev/null +++ b/internal/serialize/keyvalues_test.go @@ -0,0 +1,151 @@ +/* +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 serialize_test + +import ( + "bytes" + "fmt" + "testing" + "time" + + "k8s.io/klog/v2" + "k8s.io/klog/v2/internal/serialize" + "k8s.io/klog/v2/internal/test" +) + +// point conforms to fmt.Stringer interface as it implements the String() method +type point struct { + x int + y int +} + +// we now have a value receiver +func (p point) String() string { + return fmt.Sprintf("x=%d, y=%d", p.x, p.y) +} + +// Test that kvListFormat works as advertised. +func TestKvListFormat(t *testing.T) { + var emptyPoint *point + var testKVList = []struct { + keysValues []interface{} + want string + }{ + { + keysValues: []interface{}{"pod", "kubedns"}, + want: " pod=\"kubedns\"", + }, + { + keysValues: []interface{}{"pod", "kubedns", "update", true}, + want: " pod=\"kubedns\" update=true", + }, + { + keysValues: []interface{}{"pod", "kubedns", "spec", struct { + X int + Y string + N time.Time + }{X: 76, Y: "strval", N: time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.UTC)}}, + want: " pod=\"kubedns\" spec={X:76 Y:strval N:2006-01-02 15:04:05.06789 +0000 UTC}", + }, + { + keysValues: []interface{}{"pod", "kubedns", "values", []int{8, 6, 7, 5, 3, 0, 9}}, + want: " pod=\"kubedns\" values=[8 6 7 5 3 0 9]", + }, + { + keysValues: []interface{}{"pod", "kubedns", "values", []string{"deployment", "svc", "configmap"}}, + want: " pod=\"kubedns\" values=[deployment svc configmap]", + }, + { + keysValues: []interface{}{"pod", "kubedns", "bytes", []byte("test case for byte array")}, + want: " pod=\"kubedns\" bytes=\"test case for byte array\"", + }, + { + keysValues: []interface{}{"pod", "kubedns", "bytes", []byte("��=� ⌘")}, + want: " pod=\"kubedns\" bytes=\"\\ufffd\\ufffd=\\ufffd \\u2318\"", + }, + { + keysValues: []interface{}{"multiLineString", `Hello world! + Starts with tab. + Starts with spaces. +No whitespace.`, + "pod", "kubedns", + }, + want: ` multiLineString=< + Hello world! + Starts with tab. + Starts with spaces. + No whitespace. + > pod="kubedns"`, + }, + { + keysValues: []interface{}{"pod", "kubedns", "maps", map[string]int{"three": 4}}, + want: " pod=\"kubedns\" maps=map[three:4]", + }, + { + keysValues: []interface{}{"pod", klog.KRef("kube-system", "kubedns"), "status", "ready"}, + want: " pod=\"kube-system/kubedns\" status=\"ready\"", + }, + { + keysValues: []interface{}{"pod", klog.KRef("", "kubedns"), "status", "ready"}, + want: " pod=\"kubedns\" status=\"ready\"", + }, + { + keysValues: []interface{}{"pod", klog.KObj(test.KMetadataMock{Name: "test-name", NS: "test-ns"}), "status", "ready"}, + want: " pod=\"test-ns/test-name\" status=\"ready\"", + }, + { + keysValues: []interface{}{"pod", klog.KObj(test.KMetadataMock{Name: "test-name", NS: ""}), "status", "ready"}, + want: " pod=\"test-name\" status=\"ready\"", + }, + { + keysValues: []interface{}{"pod", klog.KObj(nil), "status", "ready"}, + want: " pod=\"\" status=\"ready\"", + }, + { + keysValues: []interface{}{"pod", klog.KObj((*test.PtrKMetadataMock)(nil)), "status", "ready"}, + want: " pod=\"\" status=\"ready\"", + }, + { + keysValues: []interface{}{"pod", klog.KObj((*test.KMetadataMock)(nil)), "status", "ready"}, + want: " pod=\"\" status=\"ready\"", + }, + { + keysValues: []interface{}{"pods", klog.KObjs([]test.KMetadataMock{ + { + Name: "kube-dns", + NS: "kube-system", + }, + { + Name: "mi-conf", + }, + })}, + want: " pods=[kube-system/kube-dns mi-conf]", + }, + { + keysValues: []interface{}{"point-1", point{100, 200}, "point-2", emptyPoint}, + want: " point-1=\"x=100, y=200\" point-2=\"nil\"", + }, + } + + for _, d := range testKVList { + b := &bytes.Buffer{} + serialize.KVListFormat(b, d.keysValues...) + if b.String() != d.want { + t.Errorf("KVListFormat error:\n got:\n\t%s\nwant:\t%s", b.String(), d.want) + } + } +} diff --git a/internal/test/mock.go b/internal/test/mock.go new file mode 100644 index 00000000..3f5a6eaa --- /dev/null +++ b/internal/test/mock.go @@ -0,0 +1,40 @@ +/* +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 test contains common code for klog tests. +package test + +type KMetadataMock struct { + Name, NS string +} + +func (m KMetadataMock) GetName() string { + return m.Name +} +func (m KMetadataMock) GetNamespace() string { + return m.NS +} + +type PtrKMetadataMock struct { + Name, NS string +} + +func (m *PtrKMetadataMock) GetName() string { + return m.Name +} +func (m *PtrKMetadataMock) GetNamespace() string { + return m.NS +} diff --git a/klog.go b/klog.go index 26c532b5..7e786574 100644 --- a/klog.go +++ b/klog.go @@ -90,6 +90,8 @@ import ( "time" "github.com/go-logr/logr" + + "k8s.io/klog/v2/internal/serialize" ) // severity identifies the sort of log: info, warning etc. It also implements @@ -816,129 +818,14 @@ func (l *loggingT) printS(err error, s severity, depth int, msg string, keysAndV // message and put the multi-line output into a value. b.WriteString(strconv.Quote(msg)) if err != nil { - kvListFormat(&b.Buffer, "err", err) + serialize.KVListFormat(&b.Buffer, "err", err) } - kvListFormat(&b.Buffer, keysAndValues...) + serialize.KVListFormat(&b.Buffer, keysAndValues...) l.printDepth(s, logging.logr, nil, depth+1, &b.Buffer) // Make the buffer available for reuse. l.putBuffer(b) } -const missingValue = "(MISSING)" - -func kvListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { - for i := 0; i < len(keysAndValues); i += 2 { - var v interface{} - k := keysAndValues[i] - if i+1 < len(keysAndValues) { - v = keysAndValues[i+1] - } else { - v = missingValue - } - b.WriteByte(' ') - // Keys are assumed to be well-formed according to - // https://github.com/kubernetes/community/blob/master/contributors/devel/sig-instrumentation/migration-to-structured-logging.md#name-arguments - // for the sake of performance. Keys with spaces, - // special characters, etc. will break parsing. - if k, ok := k.(string); ok { - // Avoid one allocation when the key is a string, which - // normally it should be. - b.WriteString(k) - } else { - b.WriteString(fmt.Sprintf("%s", k)) - } - - // The type checks are sorted so that more frequently used ones - // come first because that is then faster in the common - // cases. In Kubernetes, ObjectRef (a Stringer) is more common - // than plain strings - // (https://github.com/kubernetes/kubernetes/pull/106594#issuecomment-975526235). - switch v := v.(type) { - case fmt.Stringer: - writeStringValue(b, true, stringerToString(v)) - case string: - writeStringValue(b, true, v) - case error: - writeStringValue(b, true, v.Error()) - case []byte: - // In https://github.com/kubernetes/klog/pull/237 it was decided - // to format byte slices with "%+q". The advantages of that are: - // - readable output if the bytes happen to be printable - // - non-printable bytes get represented as unicode escape - // sequences (\uxxxx) - // - // The downsides are that we cannot use the faster - // strconv.Quote here and that multi-line output is not - // supported. If developers know that a byte array is - // printable and they want multi-line output, they can - // convert the value to string before logging it. - b.WriteByte('=') - b.WriteString(fmt.Sprintf("%+q", v)) - default: - writeStringValue(b, false, fmt.Sprintf("%+v", v)) - } - } -} - -func stringerToString(s fmt.Stringer) (ret string) { - defer func() { - if err := recover(); err != nil { - ret = "nil" - } - }() - ret = s.String() - return -} - -func writeStringValue(b *bytes.Buffer, quote bool, v string) { - data := []byte(v) - index := bytes.IndexByte(data, '\n') - if index == -1 { - b.WriteByte('=') - if quote { - // Simple string, quote quotation marks and non-printable characters. - b.WriteString(strconv.Quote(v)) - return - } - // Non-string with no line breaks. - b.WriteString(v) - return - } - - // Complex multi-line string, show as-is with indention like this: - // I... "hello world" key=< - // line 1 - // line 2 - // > - // - // Tabs indent the lines of the value while the end of string delimiter - // is indented with a space. That has two purposes: - // - visual difference between the two for a human reader because indention - // will be different - // - no ambiguity when some value line starts with the end delimiter - // - // One downside is that the output cannot distinguish between strings that - // end with a line break and those that don't because the end delimiter - // will always be on the next line. - b.WriteString("=<\n") - for index != -1 { - b.WriteByte('\t') - b.Write(data[0 : index+1]) - data = data[index+1:] - index = bytes.IndexByte(data, '\n') - } - if len(data) == 0 { - // String ended with line break, don't add another. - b.WriteString(" >") - } else { - // No line break at end of last line, write rest of string and - // add one. - b.WriteByte('\t') - b.Write(data) - b.WriteString("\n >") - } -} - // redirectBuffer is used to set an alternate destination for the logs type redirectBuffer struct { w io.Writer diff --git a/klog_test.go b/klog_test.go index 82f23d8a..f4bcc776 100644 --- a/klog_test.go +++ b/klog_test.go @@ -35,6 +35,8 @@ import ( "time" "github.com/go-logr/logr" + + "k8s.io/klog/v2/internal/test" ) // TODO: This test package should be refactored so that tests cannot @@ -642,7 +644,7 @@ func BenchmarkKRef(b *testing.B) { } func BenchmarkKObj(b *testing.B) { - a := kMetadataMock{name: "a", ns: "a"} + a := test.KMetadataMock{Name: "a", NS: "a"} var r ObjectRef for i := 0; i < b.N; i++ { r = KObj(&a) @@ -780,28 +782,6 @@ func TestInfoObjectRef(t *testing.T) { } } -type kMetadataMock struct { - name, ns string -} - -func (m kMetadataMock) GetName() string { - return m.name -} -func (m kMetadataMock) GetNamespace() string { - return m.ns -} - -type ptrKMetadataMock struct { - name, ns string -} - -func (m *ptrKMetadataMock) GetName() string { - return m.name -} -func (m *ptrKMetadataMock) GetNamespace() string { - return m.ns -} - func TestKObj(t *testing.T) { tests := []struct { name string @@ -810,17 +790,17 @@ func TestKObj(t *testing.T) { }{ { name: "nil passed as pointer KMetadata implementation", - obj: (*ptrKMetadataMock)(nil), + obj: (*test.PtrKMetadataMock)(nil), want: ObjectRef{}, }, { name: "empty struct passed as non-pointer KMetadata implementation", - obj: kMetadataMock{}, + obj: test.KMetadataMock{}, want: ObjectRef{}, }, { name: "nil pointer passed to non-pointer KMetadata implementation", - obj: (*kMetadataMock)(nil), + obj: (*test.KMetadataMock)(nil), want: ObjectRef{}, }, { @@ -830,7 +810,7 @@ func TestKObj(t *testing.T) { }, { name: "with ns", - obj: &kMetadataMock{"test-name", "test-ns"}, + obj: &test.KMetadataMock{Name: "test-name", NS: "test-ns"}, want: ObjectRef{ Name: "test-name", Namespace: "test-ns", @@ -838,7 +818,7 @@ func TestKObj(t *testing.T) { }, { name: "without ns", - obj: &kMetadataMock{"test-name", ""}, + obj: &test.KMetadataMock{Name: "test-name", NS: ""}, want: ObjectRef{ Name: "test-name", }, @@ -1072,129 +1052,6 @@ func TestErrorS(t *testing.T) { } } -// point conforms to fmt.Stringer interface as it implements the String() method -type point struct { - x int - y int -} - -// we now have a value receiver -func (p point) String() string { - return fmt.Sprintf("x=%d, y=%d", p.x, p.y) -} - -// Test that kvListFormat works as advertised. -func TestKvListFormat(t *testing.T) { - var emptyPoint *point - var testKVList = []struct { - keysValues []interface{} - want string - }{ - { - keysValues: []interface{}{"pod", "kubedns"}, - want: " pod=\"kubedns\"", - }, - { - keysValues: []interface{}{"pod", "kubedns", "update", true}, - want: " pod=\"kubedns\" update=true", - }, - { - keysValues: []interface{}{"pod", "kubedns", "spec", struct { - X int - Y string - N time.Time - }{X: 76, Y: "strval", N: time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.UTC)}}, - want: " pod=\"kubedns\" spec={X:76 Y:strval N:2006-01-02 15:04:05.06789 +0000 UTC}", - }, - { - keysValues: []interface{}{"pod", "kubedns", "values", []int{8, 6, 7, 5, 3, 0, 9}}, - want: " pod=\"kubedns\" values=[8 6 7 5 3 0 9]", - }, - { - keysValues: []interface{}{"pod", "kubedns", "values", []string{"deployment", "svc", "configmap"}}, - want: " pod=\"kubedns\" values=[deployment svc configmap]", - }, - { - keysValues: []interface{}{"pod", "kubedns", "bytes", []byte("test case for byte array")}, - want: " pod=\"kubedns\" bytes=\"test case for byte array\"", - }, - { - keysValues: []interface{}{"pod", "kubedns", "bytes", []byte("��=� ⌘")}, - want: " pod=\"kubedns\" bytes=\"\\ufffd\\ufffd=\\ufffd \\u2318\"", - }, - { - keysValues: []interface{}{"multiLineString", `Hello world! - Starts with tab. - Starts with spaces. -No whitespace.`, - "pod", "kubedns", - }, - want: ` multiLineString=< - Hello world! - Starts with tab. - Starts with spaces. - No whitespace. - > pod="kubedns"`, - }, - { - keysValues: []interface{}{"pod", "kubedns", "maps", map[string]int{"three": 4}}, - want: " pod=\"kubedns\" maps=map[three:4]", - }, - { - keysValues: []interface{}{"pod", KRef("kube-system", "kubedns"), "status", "ready"}, - want: " pod=\"kube-system/kubedns\" status=\"ready\"", - }, - { - keysValues: []interface{}{"pod", KRef("", "kubedns"), "status", "ready"}, - want: " pod=\"kubedns\" status=\"ready\"", - }, - { - keysValues: []interface{}{"pod", KObj(kMetadataMock{"test-name", "test-ns"}), "status", "ready"}, - want: " pod=\"test-ns/test-name\" status=\"ready\"", - }, - { - keysValues: []interface{}{"pod", KObj(kMetadataMock{"test-name", ""}), "status", "ready"}, - want: " pod=\"test-name\" status=\"ready\"", - }, - { - keysValues: []interface{}{"pod", KObj(nil), "status", "ready"}, - want: " pod=\"\" status=\"ready\"", - }, - { - keysValues: []interface{}{"pod", KObj((*ptrKMetadataMock)(nil)), "status", "ready"}, - want: " pod=\"\" status=\"ready\"", - }, - { - keysValues: []interface{}{"pod", KObj((*kMetadataMock)(nil)), "status", "ready"}, - want: " pod=\"\" status=\"ready\"", - }, - { - keysValues: []interface{}{"pods", KObjs([]kMetadataMock{ - { - name: "kube-dns", - ns: "kube-system", - }, - { - name: "mi-conf", - }, - })}, - want: " pods=[kube-system/kube-dns mi-conf]", - }, - { - keysValues: []interface{}{"point-1", point{100, 200}, "point-2", emptyPoint}, - want: " point-1=\"x=100, y=200\" point-2=\"nil\"", - }, - } - - for _, d := range testKVList { - b := &bytes.Buffer{} - kvListFormat(b, d.keysValues...) - if b.String() != d.want { - t.Errorf("kvlist format error:\ngot:\n%s\nwant:\n%s\n", b.String(), d.want) - } - } -} - func createTestValueOfLoggingT() *loggingT { l := new(loggingT) l.toStderr = true @@ -1888,13 +1745,13 @@ func TestKObjs(t *testing.T) { }{ { name: "test for KObjs function with KMetadata slice", - obj: []kMetadataMock{ + obj: []test.KMetadataMock{ { - name: "kube-dns", - ns: "kube-system", + Name: "kube-dns", + NS: "kube-system", }, { - name: "mi-conf", + Name: "mi-conf", }, {}, }, @@ -1911,13 +1768,13 @@ func TestKObjs(t *testing.T) { }, { name: "test for KObjs function with KMetadata pointer slice", - obj: []*kMetadataMock{ + obj: []*test.KMetadataMock{ { - name: "kube-dns", - ns: "kube-system", + Name: "kube-dns", + NS: "kube-system", }, { - name: "mi-conf", + Name: "mi-conf", }, nil, }, diff --git a/klogr/klogr.go b/klogr/klogr.go index a347a884..d8e660e4 100644 --- a/klogr/klogr.go +++ b/klogr/klogr.go @@ -6,10 +6,13 @@ import ( "bytes" "encoding/json" "fmt" - "github.com/go-logr/logr" - "k8s.io/klog/v2" "sort" "strings" + + "github.com/go-logr/logr" + + "k8s.io/klog/v2" + "k8s.io/klog/v2/internal/serialize" ) // Option is a functional option that reconfigures the logger created with New. @@ -70,51 +73,6 @@ func (l *klogger) Init(info logr.RuntimeInfo) { l.callDepth += info.CallDepth } -// trimDuplicates will deduplicate elements provided in multiple KV tuple -// slices, whilst maintaining the distinction between where the items are -// contained. -func trimDuplicates(kvLists ...[]interface{}) [][]interface{} { - // maintain a map of all seen keys - seenKeys := map[interface{}]struct{}{} - // build the same number of output slices as inputs - outs := make([][]interface{}, len(kvLists)) - // iterate over the input slices backwards, as 'later' kv specifications - // of the same key will take precedence over earlier ones - for i := len(kvLists) - 1; i >= 0; i-- { - // initialise this output slice - outs[i] = []interface{}{} - // obtain a reference to the kvList we are processing - kvList := kvLists[i] - - // start iterating at len(kvList) - 2 (i.e. the 2nd last item) for - // slices that have an even number of elements. - // We add (len(kvList) % 2) here to handle the case where there is an - // odd number of elements in a kvList. - // If there is an odd number, then the last element in the slice will - // have the value 'null'. - for i2 := len(kvList) - 2 + (len(kvList) % 2); i2 >= 0; i2 -= 2 { - k := kvList[i2] - // if we have already seen this key, do not include it again - if _, ok := seenKeys[k]; ok { - continue - } - // make a note that we've observed a new key - seenKeys[k] = struct{}{} - // attempt to obtain the value of the key - var v interface{} - // i2+1 should only ever be out of bounds if we handling the first - // iteration over a slice with an odd number of elements - if i2+1 < len(kvList) { - v = kvList[i2+1] - } - // add this KV tuple to the *start* of the output list to maintain - // the original order as we are iterating over the slice backwards - outs[i] = append([]interface{}{k, v}, outs[i]...) - } - } - return outs -} - func flatten(kvList ...interface{}) string { keys := make([]string, 0, len(kvList)) vals := make(map[string]interface{}, len(kvList)) @@ -161,12 +119,12 @@ func (l klogger) Info(level int, msg string, kvList ...interface{}) { switch l.format { case FormatSerialize: msgStr := flatten("msg", msg) - trimmed := trimDuplicates(l.values, kvList) + trimmed := serialize.TrimDuplicates(l.values, kvList) fixedStr := flatten(trimmed[0]...) userStr := flatten(trimmed[1]...) klog.InfoDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", fixedStr, " ", userStr) case FormatKlog: - trimmed := trimDuplicates(l.values, kvList) + trimmed := serialize.TrimDuplicates(l.values, kvList) if l.prefix != "" { msg = l.prefix + ": " + msg } @@ -187,12 +145,12 @@ func (l klogger) Error(err error, msg string, kvList ...interface{}) { switch l.format { case FormatSerialize: errStr := flatten("error", loggableErr) - trimmed := trimDuplicates(l.values, kvList) + trimmed := serialize.TrimDuplicates(l.values, kvList) fixedStr := flatten(trimmed[0]...) userStr := flatten(trimmed[1]...) klog.ErrorDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", errStr, " ", fixedStr, " ", userStr) case FormatKlog: - trimmed := trimDuplicates(l.values, kvList) + trimmed := serialize.TrimDuplicates(l.values, kvList) if l.prefix != "" { msg = l.prefix + ": " + msg } From c734dc7685cf34c8e3dad5ddaf7d3cc48c80d49e Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 9 Feb 2022 16:50:10 +0100 Subject: [PATCH 09/12] split out buffer helpers and severity definition This will enable writing Logger implementations which reproduce the traditional klog header. --- internal/buffer/buffer.go | 159 +++++++++++++++ internal/severity/severity.go | 58 ++++++ klog.go | 367 +++++++++++----------------------- klog_test.go | 226 +++++++++++---------- 4 files changed, 449 insertions(+), 361 deletions(-) create mode 100644 internal/buffer/buffer.go create mode 100644 internal/severity/severity.go diff --git a/internal/buffer/buffer.go b/internal/buffer/buffer.go new file mode 100644 index 00000000..ac88682a --- /dev/null +++ b/internal/buffer/buffer.go @@ -0,0 +1,159 @@ +// Copyright 2013 Google Inc. All Rights Reserved. +// Copyright 2022 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 buffer provides a cache for byte.Buffer instances that can be reused +// to avoid frequent allocation and deallocation. It also has utility code +// for log header formatting that use these buffers. +package buffer + +import ( + "bytes" + "os" + "sync" + "time" + + "k8s.io/klog/v2/internal/severity" +) + +var ( + // Pid is inserted into log headers. Can be overridden for tests. + Pid = os.Getpid() +) + +// Buffer holds a single byte.Buffer for reuse. The zero value is ready for +// use. It also provides some helper methods for output formatting. +type Buffer struct { + bytes.Buffer + Tmp [64]byte // temporary byte array for creating headers. + next *Buffer +} + +// Buffers manages the reuse of individual buffer instances. It is thread-safe. +type Buffers struct { + // mu protects the free list. It is separate from the main mutex + // so buffers can be grabbed and printed to without holding the main lock, + // for better parallelization. + mu sync.Mutex + + // freeList is a list of byte buffers, maintained under mu. + freeList *Buffer +} + +// GetBuffer returns a new, ready-to-use buffer. +func (bl *Buffers) GetBuffer() *Buffer { + bl.mu.Lock() + b := bl.freeList + if b != nil { + bl.freeList = b.next + } + bl.mu.Unlock() + if b == nil { + b = new(Buffer) + } else { + b.next = nil + b.Reset() + } + return b +} + +// PutBuffer returns a buffer to the free list. +func (bl *Buffers) PutBuffer(b *Buffer) { + if b.Len() >= 256 { + // Let big buffers die a natural death. + return + } + bl.mu.Lock() + b.next = bl.freeList + bl.freeList = b + bl.mu.Unlock() +} + +// Some custom tiny helper functions to print the log header efficiently. + +const digits = "0123456789" + +// twoDigits formats a zero-prefixed two-digit integer at buf.Tmp[i]. +func (buf *Buffer) twoDigits(i, d int) { + buf.Tmp[i+1] = digits[d%10] + d /= 10 + buf.Tmp[i] = digits[d%10] +} + +// nDigits formats an n-digit integer at buf.Tmp[i], +// padding with pad on the left. +// It assumes d >= 0. +func (buf *Buffer) nDigits(n, i, d int, pad byte) { + j := n - 1 + for ; j >= 0 && d > 0; j-- { + buf.Tmp[i+j] = digits[d%10] + d /= 10 + } + for ; j >= 0; j-- { + buf.Tmp[i+j] = pad + } +} + +// someDigits formats a zero-prefixed variable-width integer at buf.Tmp[i]. +func (buf *Buffer) someDigits(i, d int) int { + // Print into the top, then copy down. We know there's space for at least + // a 10-digit number. + j := len(buf.Tmp) + for { + j-- + buf.Tmp[j] = digits[d%10] + d /= 10 + if d == 0 { + break + } + } + return copy(buf.Tmp[i:], buf.Tmp[j:]) +} + +// FormatHeader formats a log header using the provided file name and line number. +func (buf *Buffer) FormatHeader(s severity.Severity, file string, line int, now time.Time) { + if line < 0 { + line = 0 // not a real line number, but acceptable to someDigits + } + if s > severity.FatalLog { + s = severity.InfoLog // for safety. + } + + // Avoid Fprintf, for speed. The format is so simple that we can do it quickly by hand. + // It's worth about 3X. Fprintf is hard. + _, month, day := now.Date() + hour, minute, second := now.Clock() + // Lmmdd hh:mm:ss.uuuuuu threadid file:line] + buf.Tmp[0] = severity.Char[s] + buf.twoDigits(1, int(month)) + buf.twoDigits(3, day) + buf.Tmp[5] = ' ' + buf.twoDigits(6, hour) + buf.Tmp[8] = ':' + buf.twoDigits(9, minute) + buf.Tmp[11] = ':' + buf.twoDigits(12, second) + buf.Tmp[14] = '.' + buf.nDigits(6, 15, now.Nanosecond()/1000, '0') + buf.Tmp[21] = ' ' + buf.nDigits(7, 22, Pid, ' ') // TODO: should be TID + buf.Tmp[29] = ' ' + buf.Write(buf.Tmp[:30]) + buf.WriteString(file) + buf.Tmp[0] = ':' + n := buf.someDigits(1, line) + buf.Tmp[n+1] = ']' + buf.Tmp[n+2] = ' ' + buf.Write(buf.Tmp[:n+3]) +} diff --git a/internal/severity/severity.go b/internal/severity/severity.go new file mode 100644 index 00000000..30fa1834 --- /dev/null +++ b/internal/severity/severity.go @@ -0,0 +1,58 @@ +// Copyright 2013 Google Inc. All Rights Reserved. +// Copyright 2022 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 severity provides definitions for klog severity (info, warning, ...) +package severity + +import ( + "strings" +) + +// severity identifies the sort of log: info, warning etc. The binding to flag.Value +// is handled in klog.go +type Severity int32 // sync/atomic int32 + +// These constants identify the log levels in order of increasing severity. +// A message written to a high-severity log file is also written to each +// lower-severity log file. +const ( + InfoLog Severity = iota + WarningLog + ErrorLog + FatalLog + NumSeverity = 4 +) + +// Char contains one shortcut letter per severity level. +const Char = "IWEF" + +// Name contains one name per severity level. +var Name = []string{ + InfoLog: "INFO", + WarningLog: "WARNING", + ErrorLog: "ERROR", + FatalLog: "FATAL", +} + +// ByName looks up a severity level by name. +func ByName(s string) (Severity, bool) { + s = strings.ToUpper(s) + for i, name := range Name { + if name == s { + return Severity(i), true + } + } + return 0, false +} diff --git a/klog.go b/klog.go index 7e786574..3435461d 100644 --- a/klog.go +++ b/klog.go @@ -91,82 +91,56 @@ import ( "github.com/go-logr/logr" + "k8s.io/klog/v2/internal/buffer" "k8s.io/klog/v2/internal/serialize" + "k8s.io/klog/v2/internal/severity" ) -// severity identifies the sort of log: info, warning etc. It also implements +// severityValue identifies the sort of log: info, warning etc. It also implements // the flag.Value interface. The -stderrthreshold flag is of type severity and // should be modified only through the flag.Value interface. The values match // the corresponding constants in C++. -type severity int32 // sync/atomic int32 - -// These constants identify the log levels in order of increasing severity. -// A message written to a high-severity log file is also written to each -// lower-severity log file. -const ( - infoLog severity = iota - warningLog - errorLog - fatalLog - numSeverity = 4 -) - -const severityChar = "IWEF" - -var severityName = []string{ - infoLog: "INFO", - warningLog: "WARNING", - errorLog: "ERROR", - fatalLog: "FATAL", +type severityValue struct { + severity.Severity } // get returns the value of the severity. -func (s *severity) get() severity { - return severity(atomic.LoadInt32((*int32)(s))) +func (s *severityValue) get() severity.Severity { + return severity.Severity(atomic.LoadInt32((*int32)(&s.Severity))) } // set sets the value of the severity. -func (s *severity) set(val severity) { - atomic.StoreInt32((*int32)(s), int32(val)) +func (s *severityValue) set(val severity.Severity) { + atomic.StoreInt32((*int32)(&s.Severity), int32(val)) } // String is part of the flag.Value interface. -func (s *severity) String() string { - return strconv.FormatInt(int64(*s), 10) +func (s *severityValue) String() string { + return strconv.FormatInt(int64(s.Severity), 10) } // Get is part of the flag.Getter interface. -func (s *severity) Get() interface{} { - return *s +func (s *severityValue) Get() interface{} { + return s.Severity } // Set is part of the flag.Value interface. -func (s *severity) Set(value string) error { - var threshold severity +func (s *severityValue) Set(value string) error { + var threshold severity.Severity // Is it a known name? - if v, ok := severityByName(value); ok { + if v, ok := severity.ByName(value); ok { threshold = v } else { v, err := strconv.ParseInt(value, 10, 32) if err != nil { return err } - threshold = severity(v) + threshold = severity.Severity(v) } logging.stderrThreshold.set(threshold) return nil } -func severityByName(s string) (severity, bool) { - s = strings.ToUpper(s) - for i, name := range severityName { - if name == s { - return severity(i), true - } - } - return 0, false -} - // OutputStats tracks the number of output lines and bytes written. type OutputStats struct { lines int64 @@ -189,10 +163,10 @@ var Stats struct { Info, Warning, Error OutputStats } -var severityStats = [numSeverity]*OutputStats{ - infoLog: &Stats.Info, - warningLog: &Stats.Warning, - errorLog: &Stats.Error, +var severityStats = [severity.NumSeverity]*OutputStats{ + severity.InfoLog: &Stats.Info, + severity.WarningLog: &Stats.Warning, + severity.ErrorLog: &Stats.Error, } // Level is exported because it appears in the arguments to V and is @@ -408,7 +382,9 @@ type flushSyncWriter interface { // init sets up the defaults and runs flushDaemon. func init() { - logging.stderrThreshold = errorLog // Default stderrThreshold is ERROR. + logging.stderrThreshold = severityValue{ + Severity: severity.ErrorLog, // Default stderrThreshold is ERROR. + } logging.setVState(0, nil, false) logging.logDir = "" logging.logFile = "" @@ -459,20 +435,18 @@ type loggingT struct { alsoToStderr bool // The -alsologtostderr flag. // Level flag. Handled atomically. - stderrThreshold severity // The -stderrthreshold flag. + stderrThreshold severityValue // The -stderrthreshold flag. - // freeList is a list of byte buffers, maintained under freeListMu. - freeList *buffer - // freeListMu maintains the free list. It is separate from the main mutex + // bufferCache maintains the free list. It uses its own mutex // so buffers can be grabbed and printed to without holding the main lock, // for better parallelization. - freeListMu sync.Mutex + bufferCache buffer.Buffers // mu protects the remaining elements of this structure and is // used to synchronize logging. mu sync.Mutex // file holds writer for each of the log types. - file [numSeverity]flushSyncWriter + file [severity.NumSeverity]flushSyncWriter // pcs is used in V to avoid an allocation when computing the caller's PC. pcs [1]uintptr // vmap is a cache of the V Level for each V() call site, identified by PC. @@ -520,13 +494,6 @@ type loggingT struct { filter LogFilter } -// buffer holds a byte Buffer for reuse. The zero value is ready for use. -type buffer struct { - bytes.Buffer - tmp [64]byte // temporary byte array for creating headers. - next *buffer -} - var logging loggingT // setVState sets a consistent state for V logging. @@ -549,35 +516,6 @@ func (l *loggingT) setVState(verbosity Level, filter []modulePat, setFilter bool l.verbosity.set(verbosity) } -// getBuffer returns a new, ready-to-use buffer. -func (l *loggingT) getBuffer() *buffer { - l.freeListMu.Lock() - b := l.freeList - if b != nil { - l.freeList = b.next - } - l.freeListMu.Unlock() - if b == nil { - b = new(buffer) - } else { - b.next = nil - b.Reset() - } - return b -} - -// putBuffer returns a buffer to the free list. -func (l *loggingT) putBuffer(b *buffer) { - if b.Len() >= 256 { - // Let big buffers die a natural death. - return - } - l.freeListMu.Lock() - b.next = l.freeList - l.freeList = b - l.freeListMu.Unlock() -} - var timeNow = time.Now // Stubbed out for testing. /* @@ -597,7 +535,7 @@ where the fields are defined as follows: line The line number msg The user-supplied message */ -func (l *loggingT) header(s severity, depth int) (*buffer, string, int) { +func (l *loggingT) header(s severity.Severity, depth int) (*buffer.Buffer, string, int) { _, file, line, ok := runtime.Caller(3 + depth) if !ok { file = "???" @@ -617,100 +555,27 @@ func (l *loggingT) header(s severity, depth int) (*buffer, string, int) { } // formatHeader formats a log header using the provided file name and line number. -func (l *loggingT) formatHeader(s severity, file string, line int) *buffer { - now := timeNow() - if line < 0 { - line = 0 // not a real line number, but acceptable to someDigits - } - if s > fatalLog { - s = infoLog // for safety. - } - buf := l.getBuffer() +func (l *loggingT) formatHeader(s severity.Severity, file string, line int) *buffer.Buffer { + buf := l.bufferCache.GetBuffer() if l.skipHeaders { return buf } - - // Avoid Fprintf, for speed. The format is so simple that we can do it quickly by hand. - // It's worth about 3X. Fprintf is hard. - _, month, day := now.Date() - hour, minute, second := now.Clock() - // Lmmdd hh:mm:ss.uuuuuu threadid file:line] - buf.tmp[0] = severityChar[s] - buf.twoDigits(1, int(month)) - buf.twoDigits(3, day) - buf.tmp[5] = ' ' - buf.twoDigits(6, hour) - buf.tmp[8] = ':' - buf.twoDigits(9, minute) - buf.tmp[11] = ':' - buf.twoDigits(12, second) - buf.tmp[14] = '.' - buf.nDigits(6, 15, now.Nanosecond()/1000, '0') - buf.tmp[21] = ' ' - buf.nDigits(7, 22, pid, ' ') // TODO: should be TID - buf.tmp[29] = ' ' - buf.Write(buf.tmp[:30]) - buf.WriteString(file) - buf.tmp[0] = ':' - n := buf.someDigits(1, line) - buf.tmp[n+1] = ']' - buf.tmp[n+2] = ' ' - buf.Write(buf.tmp[:n+3]) + now := timeNow() + buf.FormatHeader(s, file, line, now) return buf } -// Some custom tiny helper functions to print the log header efficiently. - -const digits = "0123456789" - -// twoDigits formats a zero-prefixed two-digit integer at buf.tmp[i]. -func (buf *buffer) twoDigits(i, d int) { - buf.tmp[i+1] = digits[d%10] - d /= 10 - buf.tmp[i] = digits[d%10] -} - -// nDigits formats an n-digit integer at buf.tmp[i], -// padding with pad on the left. -// It assumes d >= 0. -func (buf *buffer) nDigits(n, i, d int, pad byte) { - j := n - 1 - for ; j >= 0 && d > 0; j-- { - buf.tmp[i+j] = digits[d%10] - d /= 10 - } - for ; j >= 0; j-- { - buf.tmp[i+j] = pad - } -} - -// someDigits formats a zero-prefixed variable-width integer at buf.tmp[i]. -func (buf *buffer) someDigits(i, d int) int { - // Print into the top, then copy down. We know there's space for at least - // a 10-digit number. - j := len(buf.tmp) - for { - j-- - buf.tmp[j] = digits[d%10] - d /= 10 - if d == 0 { - break - } - } - return copy(buf.tmp[i:], buf.tmp[j:]) -} - -func (l *loggingT) println(s severity, logger *logr.Logger, filter LogFilter, args ...interface{}) { +func (l *loggingT) println(s severity.Severity, logger *logr.Logger, filter LogFilter, args ...interface{}) { l.printlnDepth(s, logger, filter, 1, args...) } -func (l *loggingT) printlnDepth(s severity, logger *logr.Logger, filter LogFilter, depth int, args ...interface{}) { +func (l *loggingT) printlnDepth(s severity.Severity, logger *logr.Logger, filter LogFilter, depth int, args ...interface{}) { buf, file, line := l.header(s, depth) // if logger is set, we clear the generated header as we rely on the backing // logger implementation to print headers if logger != nil { - l.putBuffer(buf) - buf = l.getBuffer() + l.bufferCache.PutBuffer(buf) + buf = l.bufferCache.GetBuffer() } if filter != nil { args = filter.Filter(args) @@ -719,17 +584,17 @@ func (l *loggingT) printlnDepth(s severity, logger *logr.Logger, filter LogFilte l.output(s, logger, buf, depth, file, line, false) } -func (l *loggingT) print(s severity, logger *logr.Logger, filter LogFilter, args ...interface{}) { +func (l *loggingT) print(s severity.Severity, logger *logr.Logger, filter LogFilter, args ...interface{}) { l.printDepth(s, logger, filter, 1, args...) } -func (l *loggingT) printDepth(s severity, logger *logr.Logger, filter LogFilter, depth int, args ...interface{}) { +func (l *loggingT) printDepth(s severity.Severity, logger *logr.Logger, filter LogFilter, depth int, args ...interface{}) { buf, file, line := l.header(s, depth) // if logr is set, we clear the generated header as we rely on the backing // logr implementation to print headers if logger != nil { - l.putBuffer(buf) - buf = l.getBuffer() + l.bufferCache.PutBuffer(buf) + buf = l.bufferCache.GetBuffer() } if filter != nil { args = filter.Filter(args) @@ -741,17 +606,17 @@ func (l *loggingT) printDepth(s severity, logger *logr.Logger, filter LogFilter, l.output(s, logger, buf, depth, file, line, false) } -func (l *loggingT) printf(s severity, logger *logr.Logger, filter LogFilter, format string, args ...interface{}) { +func (l *loggingT) printf(s severity.Severity, logger *logr.Logger, filter LogFilter, format string, args ...interface{}) { l.printfDepth(s, logger, filter, 1, format, args...) } -func (l *loggingT) printfDepth(s severity, logger *logr.Logger, filter LogFilter, depth int, format string, args ...interface{}) { +func (l *loggingT) printfDepth(s severity.Severity, logger *logr.Logger, filter LogFilter, depth int, format string, args ...interface{}) { buf, file, line := l.header(s, depth) // if logr is set, we clear the generated header as we rely on the backing // logr implementation to print headers if logger != nil { - l.putBuffer(buf) - buf = l.getBuffer() + l.bufferCache.PutBuffer(buf) + buf = l.bufferCache.GetBuffer() } if filter != nil { format, args = filter.FilterF(format, args) @@ -766,13 +631,13 @@ func (l *loggingT) printfDepth(s severity, logger *logr.Logger, filter LogFilter // printWithFileLine behaves like print but uses the provided file and line number. If // alsoLogToStderr is true, the log message always appears on standard error; it // will also appear in the log file unless --logtostderr is set. -func (l *loggingT) printWithFileLine(s severity, logger *logr.Logger, filter LogFilter, file string, line int, alsoToStderr bool, args ...interface{}) { +func (l *loggingT) printWithFileLine(s severity.Severity, logger *logr.Logger, filter LogFilter, file string, line int, alsoToStderr bool, args ...interface{}) { buf := l.formatHeader(s, file, line) // if logr is set, we clear the generated header as we rely on the backing // logr implementation to print headers if logger != nil { - l.putBuffer(buf) - buf = l.getBuffer() + l.bufferCache.PutBuffer(buf) + buf = l.bufferCache.GetBuffer() } if filter != nil { args = filter.Filter(args) @@ -793,7 +658,7 @@ func (l *loggingT) errorS(err error, logger *logr.Logger, filter LogFilter, dept logger.WithCallDepth(depth+2).Error(err, msg, keysAndValues...) return } - l.printS(err, errorLog, depth+1, msg, keysAndValues...) + l.printS(err, severity.ErrorLog, depth+1, msg, keysAndValues...) } // if loggr is specified, will call loggr.Info, otherwise output with logging module. @@ -805,14 +670,14 @@ func (l *loggingT) infoS(logger *logr.Logger, filter LogFilter, depth int, msg s logger.WithCallDepth(depth+2).Info(msg, keysAndValues...) return } - l.printS(nil, infoLog, depth+1, msg, keysAndValues...) + l.printS(nil, severity.InfoLog, depth+1, msg, keysAndValues...) } // printS is called from infoS and errorS if loggr is not specified. // set log severity by s -func (l *loggingT) printS(err error, s severity, depth int, msg string, keysAndValues ...interface{}) { +func (l *loggingT) printS(err error, s severity.Severity, depth int, msg string, keysAndValues ...interface{}) { // Only create a new buffer if we don't have one cached. - b := l.getBuffer() + b := l.bufferCache.GetBuffer() // The message is always quoted, even if it contains line breaks. // If developers want multi-line output, they should use a small, fixed // message and put the multi-line output into a value. @@ -823,7 +688,7 @@ func (l *loggingT) printS(err error, s severity, depth int, msg string, keysAndV serialize.KVListFormat(&b.Buffer, keysAndValues...) l.printDepth(s, logging.logr, nil, depth+1, &b.Buffer) // Make the buffer available for reuse. - l.putBuffer(b) + l.bufferCache.PutBuffer(b) } // redirectBuffer is used to set an alternate destination for the logs @@ -875,7 +740,7 @@ func ClearLogger() { func SetOutput(w io.Writer) { logging.mu.Lock() defer logging.mu.Unlock() - for s := fatalLog; s >= infoLog; s-- { + for s := severity.FatalLog; s >= severity.InfoLog; s-- { rb := &redirectBuffer{ w: w, } @@ -887,7 +752,7 @@ func SetOutput(w io.Writer) { func SetOutputBySeverity(name string, w io.Writer) { logging.mu.Lock() defer logging.mu.Unlock() - sev, ok := severityByName(name) + sev, ok := severity.ByName(name) if !ok { panic(fmt.Sprintf("SetOutputBySeverity(%q): unrecognized severity name", name)) } @@ -906,7 +771,7 @@ func LogToStderr(stderr bool) { } // output writes the data to the log files and releases the buffer. -func (l *loggingT) output(s severity, log *logr.Logger, buf *buffer, depth int, file string, line int, alsoToStderr bool) { +func (l *loggingT) output(s severity.Severity, log *logr.Logger, buf *buffer.Buffer, depth int, file string, line int, alsoToStderr bool) { var isLocked = true l.mu.Lock() defer func() { @@ -925,8 +790,8 @@ func (l *loggingT) output(s severity, log *logr.Logger, buf *buffer, depth int, if log != nil { // TODO: set 'severity' and caller information as structured log info // keysAndValues := []interface{}{"severity", severityName[s], "file", file, "line", line} - if s == errorLog { - l.logr.WithCallDepth(depth+3).Error(nil, string(data)) + if s == severity.ErrorLog { + logging.logr.WithCallDepth(depth+3).Error(nil, string(data)) } else { log.WithCallDepth(depth + 3).Info(string(data)) } @@ -940,13 +805,13 @@ func (l *loggingT) output(s severity, log *logr.Logger, buf *buffer, depth int, if logging.logFile != "" { // Since we are using a single log file, all of the items in l.file array // will point to the same file, so just use one of them to write data. - if l.file[infoLog] == nil { - if err := l.createFiles(infoLog); err != nil { + if l.file[severity.InfoLog] == nil { + if err := l.createFiles(severity.InfoLog); err != nil { os.Stderr.Write(data) // Make sure the message appears somewhere. l.exit(err) } } - l.file[infoLog].Write(data) + l.file[severity.InfoLog].Write(data) } else { if l.file[s] == nil { if err := l.createFiles(s); err != nil { @@ -959,22 +824,22 @@ func (l *loggingT) output(s severity, log *logr.Logger, buf *buffer, depth int, l.file[s].Write(data) } else { switch s { - case fatalLog: - l.file[fatalLog].Write(data) + case severity.FatalLog: + l.file[severity.FatalLog].Write(data) fallthrough - case errorLog: - l.file[errorLog].Write(data) + case severity.ErrorLog: + l.file[severity.ErrorLog].Write(data) fallthrough - case warningLog: - l.file[warningLog].Write(data) + case severity.WarningLog: + l.file[severity.WarningLog].Write(data) fallthrough - case infoLog: - l.file[infoLog].Write(data) + case severity.InfoLog: + l.file[severity.InfoLog].Write(data) } } } } - if s == fatalLog { + if s == severity.FatalLog { // If we got here via Exit rather than Fatal, print no stacks. if atomic.LoadUint32(&fatalNoStacks) > 0 { l.mu.Unlock() @@ -990,7 +855,7 @@ func (l *loggingT) output(s severity, log *logr.Logger, buf *buffer, depth int, } // Write the stack trace for all goroutines to the files. logExitFunc = func(error) {} // If we get a write error, we'll still exit below. - for log := fatalLog; log >= infoLog; log-- { + for log := severity.FatalLog; log >= severity.InfoLog; log-- { if f := l.file[log]; f != nil { // Can be nil if -logtostderr is set. f.Write(trace) } @@ -1000,7 +865,7 @@ func (l *loggingT) output(s severity, log *logr.Logger, buf *buffer, depth int, timeoutFlush(10 * time.Second) os.Exit(255) // C++ uses -1, which is silly because it's anded(&) with 255 anyway. } - l.putBuffer(buf) + l.bufferCache.PutBuffer(buf) if stats := severityStats[s]; stats != nil { atomic.AddInt64(&stats.lines, 1) @@ -1072,7 +937,7 @@ type syncBuffer struct { logger *loggingT *bufio.Writer file *os.File - sev severity + sev severity.Severity nbytes uint64 // The number of bytes written to this file maxbytes uint64 // The max number of bytes this syncBuffer.file can hold before cleaning up. } @@ -1118,7 +983,7 @@ func (sb *syncBuffer) rotateFile(now time.Time, startup bool) error { sb.file.Close() } var err error - sb.file, _, err = create(severityName[sb.sev], now, startup) + sb.file, _, err = create(severity.Name[sb.sev], now, startup) if err != nil { return err } @@ -1156,11 +1021,11 @@ const bufferSize = 256 * 1024 // createFiles creates all the log files for severity from sev down to infoLog. // l.mu is held. -func (l *loggingT) createFiles(sev severity) error { +func (l *loggingT) createFiles(sev severity.Severity) error { now := time.Now() // Files are created in decreasing severity order, so as soon as we find one // has already been created, we can stop. - for s := sev; s >= infoLog && l.file[s] == nil; s-- { + for s := sev; s >= severity.InfoLog && l.file[s] == nil; s-- { sb := &syncBuffer{ logger: l, sev: s, @@ -1194,7 +1059,7 @@ func (l *loggingT) lockAndFlushAll() { // l.mu is held. func (l *loggingT) flushAll() { // Flush from fatal down, in case there's trouble flushing. - for s := fatalLog; s >= infoLog; s-- { + for s := severity.FatalLog; s >= severity.InfoLog; s-- { file := l.file[s] if file != nil { file.Flush() // ignore error @@ -1211,7 +1076,7 @@ func (l *loggingT) flushAll() { // Valid names are "INFO", "WARNING", "ERROR", and "FATAL". If the name is not // recognized, CopyStandardLogTo panics. func CopyStandardLogTo(name string) { - sev, ok := severityByName(name) + sev, ok := severity.ByName(name) if !ok { panic(fmt.Sprintf("log.CopyStandardLogTo(%q): unrecognized severity name", name)) } @@ -1223,7 +1088,7 @@ func CopyStandardLogTo(name string) { // logBridge provides the Write method that enables CopyStandardLogTo to connect // Go's standard logs to the logs provided by this package. -type logBridge severity +type logBridge severity.Severity // Write parses the standard logging line and passes its components to the // logger for severity(lb). @@ -1247,7 +1112,7 @@ func (lb logBridge) Write(b []byte) (n int, err error) { } // printWithFileLine with alsoToStderr=true, so standard log messages // always appear on standard error. - logging.printWithFileLine(severity(lb), logging.logr, logging.filter, file, line, true, text) + logging.printWithFileLine(severity.Severity(lb), logging.logr, logging.filter, file, line, true, text) return len(b), nil } @@ -1352,7 +1217,7 @@ func (v Verbose) Enabled() bool { // See the documentation of V for usage. func (v Verbose) Info(args ...interface{}) { if v.enabled { - logging.print(infoLog, v.logr, logging.filter, args...) + logging.print(severity.InfoLog, v.logr, logging.filter, args...) } } @@ -1360,7 +1225,7 @@ func (v Verbose) Info(args ...interface{}) { // See the documentation of V for usage. func (v Verbose) InfoDepth(depth int, args ...interface{}) { if v.enabled { - logging.printDepth(infoLog, v.logr, logging.filter, depth, args...) + logging.printDepth(severity.InfoLog, v.logr, logging.filter, depth, args...) } } @@ -1368,7 +1233,7 @@ func (v Verbose) InfoDepth(depth int, args ...interface{}) { // See the documentation of V for usage. func (v Verbose) Infoln(args ...interface{}) { if v.enabled { - logging.println(infoLog, v.logr, logging.filter, args...) + logging.println(severity.InfoLog, v.logr, logging.filter, args...) } } @@ -1376,7 +1241,7 @@ func (v Verbose) Infoln(args ...interface{}) { // See the documentation of V for usage. func (v Verbose) InfolnDepth(depth int, args ...interface{}) { if v.enabled { - logging.printlnDepth(infoLog, v.logr, logging.filter, depth, args...) + logging.printlnDepth(severity.InfoLog, v.logr, logging.filter, depth, args...) } } @@ -1384,7 +1249,7 @@ func (v Verbose) InfolnDepth(depth int, args ...interface{}) { // See the documentation of V for usage. func (v Verbose) Infof(format string, args ...interface{}) { if v.enabled { - logging.printf(infoLog, v.logr, logging.filter, format, args...) + logging.printf(severity.InfoLog, v.logr, logging.filter, format, args...) } } @@ -1392,7 +1257,7 @@ func (v Verbose) Infof(format string, args ...interface{}) { // See the documentation of V for usage. func (v Verbose) InfofDepth(depth int, format string, args ...interface{}) { if v.enabled { - logging.printfDepth(infoLog, v.logr, logging.filter, depth, format, args...) + logging.printfDepth(severity.InfoLog, v.logr, logging.filter, depth, format, args...) } } @@ -1436,37 +1301,37 @@ func (v Verbose) ErrorS(err error, msg string, keysAndValues ...interface{}) { // Info logs to the INFO log. // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Info(args ...interface{}) { - logging.print(infoLog, logging.logr, logging.filter, args...) + logging.print(severity.InfoLog, logging.logr, logging.filter, args...) } // InfoDepth acts as Info but uses depth to determine which call frame to log. // InfoDepth(0, "msg") is the same as Info("msg"). func InfoDepth(depth int, args ...interface{}) { - logging.printDepth(infoLog, logging.logr, logging.filter, depth, args...) + logging.printDepth(severity.InfoLog, logging.logr, logging.filter, depth, args...) } // Infoln logs to the INFO log. // Arguments are handled in the manner of fmt.Println; a newline is always appended. func Infoln(args ...interface{}) { - logging.println(infoLog, logging.logr, logging.filter, args...) + logging.println(severity.InfoLog, logging.logr, logging.filter, args...) } // InfolnDepth acts as Infoln but uses depth to determine which call frame to log. // InfolnDepth(0, "msg") is the same as Infoln("msg"). func InfolnDepth(depth int, args ...interface{}) { - logging.printlnDepth(infoLog, logging.logr, logging.filter, depth, args...) + logging.printlnDepth(severity.InfoLog, logging.logr, logging.filter, depth, args...) } // Infof logs to the INFO log. // Arguments are handled in the manner of fmt.Printf; a newline is appended if missing. func Infof(format string, args ...interface{}) { - logging.printf(infoLog, logging.logr, logging.filter, format, args...) + logging.printf(severity.InfoLog, logging.logr, logging.filter, format, args...) } // InfofDepth acts as Infof but uses depth to determine which call frame to log. // InfofDepth(0, "msg", args...) is the same as Infof("msg", args...). func InfofDepth(depth int, format string, args ...interface{}) { - logging.printfDepth(infoLog, logging.logr, logging.filter, depth, format, args...) + logging.printfDepth(severity.InfoLog, logging.logr, logging.filter, depth, format, args...) } // InfoS structured logs to the INFO log. @@ -1484,73 +1349,73 @@ func InfoS(msg string, keysAndValues ...interface{}) { // Warning logs to the WARNING and INFO logs. // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Warning(args ...interface{}) { - logging.print(warningLog, logging.logr, logging.filter, args...) + logging.print(severity.WarningLog, logging.logr, logging.filter, args...) } // WarningDepth acts as Warning but uses depth to determine which call frame to log. // WarningDepth(0, "msg") is the same as Warning("msg"). func WarningDepth(depth int, args ...interface{}) { - logging.printDepth(warningLog, logging.logr, logging.filter, depth, args...) + logging.printDepth(severity.WarningLog, logging.logr, logging.filter, depth, args...) } // Warningln logs to the WARNING and INFO logs. // Arguments are handled in the manner of fmt.Println; a newline is always appended. func Warningln(args ...interface{}) { - logging.println(warningLog, logging.logr, logging.filter, args...) + logging.println(severity.WarningLog, logging.logr, logging.filter, args...) } // WarninglnDepth acts as Warningln but uses depth to determine which call frame to log. // WarninglnDepth(0, "msg") is the same as Warningln("msg"). func WarninglnDepth(depth int, args ...interface{}) { - logging.printlnDepth(warningLog, logging.logr, logging.filter, depth, args...) + logging.printlnDepth(severity.WarningLog, logging.logr, logging.filter, depth, args...) } // Warningf logs to the WARNING and INFO logs. // Arguments are handled in the manner of fmt.Printf; a newline is appended if missing. func Warningf(format string, args ...interface{}) { - logging.printf(warningLog, logging.logr, logging.filter, format, args...) + logging.printf(severity.WarningLog, logging.logr, logging.filter, format, args...) } // WarningfDepth acts as Warningf but uses depth to determine which call frame to log. // WarningfDepth(0, "msg", args...) is the same as Warningf("msg", args...). func WarningfDepth(depth int, format string, args ...interface{}) { - logging.printfDepth(warningLog, logging.logr, logging.filter, depth, format, args...) + logging.printfDepth(severity.WarningLog, logging.logr, logging.filter, depth, format, args...) } // Error logs to the ERROR, WARNING, and INFO logs. // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Error(args ...interface{}) { - logging.print(errorLog, logging.logr, logging.filter, args...) + logging.print(severity.ErrorLog, logging.logr, logging.filter, args...) } // ErrorDepth acts as Error but uses depth to determine which call frame to log. // ErrorDepth(0, "msg") is the same as Error("msg"). func ErrorDepth(depth int, args ...interface{}) { - logging.printDepth(errorLog, logging.logr, logging.filter, depth, args...) + logging.printDepth(severity.ErrorLog, logging.logr, logging.filter, depth, args...) } // Errorln logs to the ERROR, WARNING, and INFO logs. // Arguments are handled in the manner of fmt.Println; a newline is always appended. func Errorln(args ...interface{}) { - logging.println(errorLog, logging.logr, logging.filter, args...) + logging.println(severity.ErrorLog, logging.logr, logging.filter, args...) } // ErrorlnDepth acts as Errorln but uses depth to determine which call frame to log. // ErrorlnDepth(0, "msg") is the same as Errorln("msg"). func ErrorlnDepth(depth int, args ...interface{}) { - logging.printlnDepth(errorLog, logging.logr, logging.filter, depth, args...) + logging.printlnDepth(severity.ErrorLog, logging.logr, logging.filter, depth, args...) } // Errorf logs to the ERROR, WARNING, and INFO logs. // Arguments are handled in the manner of fmt.Printf; a newline is appended if missing. func Errorf(format string, args ...interface{}) { - logging.printf(errorLog, logging.logr, logging.filter, format, args...) + logging.printf(severity.ErrorLog, logging.logr, logging.filter, format, args...) } // ErrorfDepth acts as Errorf but uses depth to determine which call frame to log. // ErrorfDepth(0, "msg", args...) is the same as Errorf("msg", args...). func ErrorfDepth(depth int, format string, args ...interface{}) { - logging.printfDepth(errorLog, logging.logr, logging.filter, depth, format, args...) + logging.printfDepth(severity.ErrorLog, logging.logr, logging.filter, depth, format, args...) } // ErrorS structured logs to the ERROR, WARNING, and INFO logs. @@ -1576,39 +1441,39 @@ func ErrorSDepth(depth int, err error, msg string, keysAndValues ...interface{}) // including a stack trace of all running goroutines, then calls os.Exit(255). // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Fatal(args ...interface{}) { - logging.print(fatalLog, logging.logr, logging.filter, args...) + logging.print(severity.FatalLog, logging.logr, logging.filter, args...) } // FatalDepth acts as Fatal but uses depth to determine which call frame to log. // FatalDepth(0, "msg") is the same as Fatal("msg"). func FatalDepth(depth int, args ...interface{}) { - logging.printDepth(fatalLog, logging.logr, logging.filter, depth, args...) + logging.printDepth(severity.FatalLog, logging.logr, logging.filter, depth, args...) } // Fatalln logs to the FATAL, ERROR, WARNING, and INFO logs, // including a stack trace of all running goroutines, then calls os.Exit(255). // Arguments are handled in the manner of fmt.Println; a newline is always appended. func Fatalln(args ...interface{}) { - logging.println(fatalLog, logging.logr, logging.filter, args...) + logging.println(severity.FatalLog, logging.logr, logging.filter, args...) } // FatallnDepth acts as Fatalln but uses depth to determine which call frame to log. // FatallnDepth(0, "msg") is the same as Fatalln("msg"). func FatallnDepth(depth int, args ...interface{}) { - logging.printlnDepth(fatalLog, logging.logr, logging.filter, depth, args...) + logging.printlnDepth(severity.FatalLog, logging.logr, logging.filter, depth, args...) } // Fatalf logs to the FATAL, ERROR, WARNING, and INFO logs, // including a stack trace of all running goroutines, then calls os.Exit(255). // Arguments are handled in the manner of fmt.Printf; a newline is appended if missing. func Fatalf(format string, args ...interface{}) { - logging.printf(fatalLog, logging.logr, logging.filter, format, args...) + logging.printf(severity.FatalLog, logging.logr, logging.filter, format, args...) } // FatalfDepth acts as Fatalf but uses depth to determine which call frame to log. // FatalfDepth(0, "msg", args...) is the same as Fatalf("msg", args...). func FatalfDepth(depth int, format string, args ...interface{}) { - logging.printfDepth(fatalLog, logging.logr, logging.filter, depth, format, args...) + logging.printfDepth(severity.FatalLog, logging.logr, logging.filter, depth, format, args...) } // fatalNoStacks is non-zero if we are to exit without dumping goroutine stacks. @@ -1619,41 +1484,41 @@ var fatalNoStacks uint32 // Arguments are handled in the manner of fmt.Print; a newline is appended if missing. func Exit(args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) - logging.print(fatalLog, logging.logr, logging.filter, args...) + logging.print(severity.FatalLog, logging.logr, logging.filter, args...) } // ExitDepth acts as Exit but uses depth to determine which call frame to log. // ExitDepth(0, "msg") is the same as Exit("msg"). func ExitDepth(depth int, args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) - logging.printDepth(fatalLog, logging.logr, logging.filter, depth, args...) + logging.printDepth(severity.FatalLog, logging.logr, logging.filter, depth, args...) } // Exitln logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1). func Exitln(args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) - logging.println(fatalLog, logging.logr, logging.filter, args...) + logging.println(severity.FatalLog, logging.logr, logging.filter, args...) } // ExitlnDepth acts as Exitln but uses depth to determine which call frame to log. // ExitlnDepth(0, "msg") is the same as Exitln("msg"). func ExitlnDepth(depth int, args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) - logging.printlnDepth(fatalLog, logging.logr, logging.filter, depth, args...) + logging.printlnDepth(severity.FatalLog, logging.logr, logging.filter, depth, args...) } // Exitf logs to the FATAL, ERROR, WARNING, and INFO logs, then calls os.Exit(1). // Arguments are handled in the manner of fmt.Printf; a newline is appended if missing. func Exitf(format string, args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) - logging.printf(fatalLog, logging.logr, logging.filter, format, args...) + logging.printf(severity.FatalLog, logging.logr, logging.filter, format, args...) } // ExitfDepth acts as Exitf but uses depth to determine which call frame to log. // ExitfDepth(0, "msg", args...) is the same as Exitf("msg", args...). func ExitfDepth(depth int, format string, args ...interface{}) { atomic.StoreUint32(&fatalNoStacks, 1) - logging.printfDepth(fatalLog, logging.logr, logging.filter, depth, format, args...) + logging.printfDepth(severity.FatalLog, logging.logr, logging.filter, depth, format, args...) } // LogFilter is a collection of functions that can filter all logging calls, diff --git a/klog_test.go b/klog_test.go index f4bcc776..6e166763 100644 --- a/klog_test.go +++ b/klog_test.go @@ -36,6 +36,8 @@ import ( "github.com/go-logr/logr" + "k8s.io/klog/v2/internal/buffer" + "k8s.io/klog/v2/internal/severity" "k8s.io/klog/v2/internal/test" ) @@ -69,7 +71,7 @@ func (f *flushBuffer) Sync() error { } // swap sets the log writers and returns the old array. -func (l *loggingT) swap(writers [numSeverity]flushSyncWriter) (old [numSeverity]flushSyncWriter) { +func (l *loggingT) swap(writers [severity.NumSeverity]flushSyncWriter) (old [severity.NumSeverity]flushSyncWriter) { l.mu.Lock() defer l.mu.Unlock() old = l.file @@ -80,17 +82,17 @@ func (l *loggingT) swap(writers [numSeverity]flushSyncWriter) (old [numSeverity] } // newBuffers sets the log writers to all new byte buffers and returns the old array. -func (l *loggingT) newBuffers() [numSeverity]flushSyncWriter { - return l.swap([numSeverity]flushSyncWriter{new(flushBuffer), new(flushBuffer), new(flushBuffer), new(flushBuffer)}) +func (l *loggingT) newBuffers() [severity.NumSeverity]flushSyncWriter { + return l.swap([severity.NumSeverity]flushSyncWriter{new(flushBuffer), new(flushBuffer), new(flushBuffer), new(flushBuffer)}) } // contents returns the specified log value as a string. -func contents(s severity) string { +func contents(s severity.Severity) string { return logging.file[s].(*flushBuffer).String() } // contains reports whether the string is contained in the log. -func contains(s severity, str string, t *testing.T) bool { +func contains(s severity.Severity, str string, t *testing.T) bool { return strings.Contains(contents(s), str) } @@ -105,10 +107,10 @@ func TestInfo(t *testing.T) { setFlags() defer logging.swap(logging.newBuffers()) Info("test") - if !contains(infoLog, "I", t) { - t.Errorf("Info has wrong character: %q", contents(infoLog)) + if !contains(severity.InfoLog, "I", t) { + t.Errorf("Info has wrong character: %q", contents(severity.InfoLog)) } - if !contains(infoLog, "test", t) { + if !contains(severity.InfoLog, "test", t) { t.Error("Info failed") } } @@ -124,7 +126,7 @@ func TestInfoDepth(t *testing.T) { InfoDepth(0, "depth-test0") f() - msgs := strings.Split(strings.TrimSuffix(contents(infoLog), "\n"), "\n") + msgs := strings.Split(strings.TrimSuffix(contents(severity.InfoLog), "\n"), "\n") if len(msgs) != 2 { t.Fatalf("Got %d lines, expected 2", len(msgs)) } @@ -176,10 +178,10 @@ func TestStandardLog(t *testing.T) { setFlags() defer logging.swap(logging.newBuffers()) stdLog.Print("test") - if !contains(infoLog, "I", t) { - t.Errorf("Info has wrong character: %q", contents(infoLog)) + if !contains(severity.InfoLog, "I", t) { + t.Errorf("Info has wrong character: %q", contents(severity.InfoLog)) } - if !contains(infoLog, "test", t) { + if !contains(severity.InfoLog, "test", t) { t.Error("Info failed") } } @@ -192,19 +194,19 @@ func TestHeader(t *testing.T) { timeNow = func() time.Time { return time.Date(2006, 1, 2, 15, 4, 5, .067890e9, time.Local) } - pid = 1234 + buffer.Pid = 1234 Info("test") var line int format := "I0102 15:04:05.067890 1234 klog_test.go:%d] test\n" - n, err := fmt.Sscanf(contents(infoLog), format, &line) + n, err := fmt.Sscanf(contents(severity.InfoLog), format, &line) if n != 1 || err != nil { - t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(infoLog)) + t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(severity.InfoLog)) } // Scanf treats multiple spaces as equivalent to a single space, // so check for correct space-padding also. want := fmt.Sprintf(format, line) - if contents(infoLog) != want { - t.Errorf("log format error: got:\n\t%q\nwant:\t%q", contents(infoLog), want) + if contents(severity.InfoLog) != want { + t.Errorf("log format error: got:\n\t%q\nwant:\t%q", contents(severity.InfoLog), want) } } @@ -219,8 +221,8 @@ func TestHeaderWithDir(t *testing.T) { pid = 1234 Info("test") re := regexp.MustCompile(`I0102 15:04:05.067890 1234 (klog|v2)/klog_test.go:(\d+)] test\n`) - if !re.MatchString(contents(infoLog)) { - t.Errorf("log format error: line does not match regex:\n\t%q\n", contents(infoLog)) + if !re.MatchString(contents(severity.InfoLog)) { + t.Errorf("log format error: line does not match regex:\n\t%q\n", contents(severity.InfoLog)) } } @@ -231,17 +233,17 @@ func TestError(t *testing.T) { setFlags() defer logging.swap(logging.newBuffers()) Error("test") - if !contains(errorLog, "E", t) { - t.Errorf("Error has wrong character: %q", contents(errorLog)) + if !contains(severity.ErrorLog, "E", t) { + t.Errorf("Error has wrong character: %q", contents(severity.ErrorLog)) } - if !contains(errorLog, "test", t) { + if !contains(severity.ErrorLog, "test", t) { t.Error("Error failed") } - str := contents(errorLog) - if !contains(warningLog, str, t) { + str := contents(severity.ErrorLog) + if !contains(severity.WarningLog, str, t) { t.Error("Warning failed") } - if !contains(infoLog, str, t) { + if !contains(severity.InfoLog, str, t) { t.Error("Info failed") } } @@ -258,17 +260,17 @@ func TestErrorWithOneOutput(t *testing.T) { logging.oneOutput = false }() Error("test") - if !contains(errorLog, "E", t) { - t.Errorf("Error has wrong character: %q", contents(errorLog)) + if !contains(severity.ErrorLog, "E", t) { + t.Errorf("Error has wrong character: %q", contents(severity.ErrorLog)) } - if !contains(errorLog, "test", t) { + if !contains(severity.ErrorLog, "test", t) { t.Error("Error failed") } - str := contents(errorLog) - if contains(warningLog, str, t) { + str := contents(severity.ErrorLog) + if contains(severity.WarningLog, str, t) { t.Error("Warning failed") } - if contains(infoLog, str, t) { + if contains(severity.InfoLog, str, t) { t.Error("Info failed") } } @@ -280,14 +282,14 @@ func TestWarning(t *testing.T) { setFlags() defer logging.swap(logging.newBuffers()) Warning("test") - if !contains(warningLog, "W", t) { - t.Errorf("Warning has wrong character: %q", contents(warningLog)) + if !contains(severity.WarningLog, "W", t) { + t.Errorf("Warning has wrong character: %q", contents(severity.WarningLog)) } - if !contains(warningLog, "test", t) { + if !contains(severity.WarningLog, "test", t) { t.Error("Warning failed") } - str := contents(warningLog) - if !contains(infoLog, str, t) { + str := contents(severity.WarningLog) + if !contains(severity.InfoLog, str, t) { t.Error("Info failed") } } @@ -304,14 +306,14 @@ func TestWarningWithOneOutput(t *testing.T) { logging.oneOutput = false }() Warning("test") - if !contains(warningLog, "W", t) { - t.Errorf("Warning has wrong character: %q", contents(warningLog)) + if !contains(severity.WarningLog, "W", t) { + t.Errorf("Warning has wrong character: %q", contents(severity.WarningLog)) } - if !contains(warningLog, "test", t) { + if !contains(severity.WarningLog, "test", t) { t.Error("Warning failed") } - str := contents(warningLog) - if contains(infoLog, str, t) { + str := contents(severity.WarningLog) + if contains(severity.InfoLog, str, t) { t.Error("Info failed") } } @@ -323,10 +325,10 @@ func TestV(t *testing.T) { logging.verbosity.Set("2") defer logging.verbosity.Set("0") V(2).Info("test") - if !contains(infoLog, "I", t) { - t.Errorf("Info has wrong character: %q", contents(infoLog)) + if !contains(severity.InfoLog, "I", t) { + t.Errorf("Info has wrong character: %q", contents(severity.InfoLog)) } - if !contains(infoLog, "test", t) { + if !contains(severity.InfoLog, "test", t) { t.Error("Info failed") } } @@ -347,10 +349,10 @@ func TestVmoduleOn(t *testing.T) { t.Error("V enabled for 3") } V(2).Info("test") - if !contains(infoLog, "I", t) { - t.Errorf("Info has wrong character: %q", contents(infoLog)) + if !contains(severity.InfoLog, "I", t) { + t.Errorf("Info has wrong character: %q", contents(severity.InfoLog)) } - if !contains(infoLog, "test", t) { + if !contains(severity.InfoLog, "test", t) { t.Error("Info failed") } } @@ -367,7 +369,7 @@ func TestVmoduleOff(t *testing.T) { } } V(2).Info("test") - if contents(infoLog) != "" { + if contents(severity.InfoLog) != "" { t.Error("V logged incorrectly") } } @@ -469,7 +471,7 @@ func TestRollover(t *testing.T) { defer func(previous uint64) { MaxSize = previous }(MaxSize) MaxSize = 512 Info("x") // Be sure we have a file. - info, ok := logging.file[infoLog].(*syncBuffer) + info, ok := logging.file[severity.InfoLog].(*syncBuffer) if !ok { t.Fatal("info wasn't created") } @@ -530,7 +532,7 @@ func TestOpenAppendOnStart(t *testing.T) { // Logging creates the file Info(x) - _, ok := logging.file[infoLog].(*syncBuffer) + _, ok := logging.file[severity.InfoLog].(*syncBuffer) if !ok { t.Fatal("info wasn't created") } @@ -595,7 +597,7 @@ func TestLogBacktraceAt(t *testing.T) { setTraceLocation(file, line, ok, +2) // Two lines between Caller and Info calls. Info("we want a stack trace here") } - numAppearances := strings.Count(contents(infoLog), infoLine) + numAppearances := strings.Count(contents(severity.InfoLog), infoLine) if numAppearances < 2 { // Need 2 appearances, one in the log header and one in the trace: // log_test.go:281: I0511 16:36:06.952398 02238 log_test.go:280] we want a stack trace here @@ -604,22 +606,22 @@ func TestLogBacktraceAt(t *testing.T) { // ... // We could be more precise but that would require knowing the details // of the traceback format, which may not be dependable. - t.Fatal("got no trace back; log is ", contents(infoLog)) + t.Fatal("got no trace back; log is ", contents(severity.InfoLog)) } } func BenchmarkHeader(b *testing.B) { for i := 0; i < b.N; i++ { - buf, _, _ := logging.header(infoLog, 0) - logging.putBuffer(buf) + buf, _, _ := logging.header(severity.InfoLog, 0) + logging.bufferCache.PutBuffer(buf) } } func BenchmarkHeaderWithDir(b *testing.B) { logging.addDirHeader = true for i := 0; i < b.N; i++ { - buf, _, _ := logging.header(infoLog, 0) - logging.putBuffer(buf) + buf, _, _ := logging.header(severity.InfoLog, 0) + logging.bufferCache.PutBuffer(buf) } } @@ -665,9 +667,11 @@ func BenchmarkLogs(b *testing.B) { logging.verbosity.Set("0") logging.toStderr = false logging.alsoToStderr = false - logging.stderrThreshold = fatalLog + logging.stderrThreshold = severityValue{ + Severity: severity.FatalLog, + } logging.logFile = testFile.Name() - logging.swap([numSeverity]flushSyncWriter{nil, nil, nil, nil}) + logging.swap([severity.NumSeverity]flushSyncWriter{nil, nil, nil, nil}) for i := 0; i < b.N; i++ { Error("error") @@ -775,8 +779,8 @@ func TestInfoObjectRef(t *testing.T) { for _, tt := range tests { t.Run(tt.name, func(t *testing.T) { Info(tt.ref) - if !contains(infoLog, tt.want, t) { - t.Errorf("expected %v, got %v", tt.want, contents(infoLog)) + if !contains(severity.InfoLog, tt.want, t) { + t.Errorf("expected %v, got %v", tt.want, contents(severity.InfoLog)) } }) } @@ -909,16 +913,16 @@ func TestInfoS(t *testing.T) { } for _, f := range functions { for _, data := range testDataInfo { - logging.file[infoLog] = &flushBuffer{} + logging.file[severity.InfoLog] = &flushBuffer{} f(data.msg, data.keysValues...) var line int - n, err := fmt.Sscanf(contents(infoLog), data.format, &line) + n, err := fmt.Sscanf(contents(severity.InfoLog), data.format, &line) if n != 1 || err != nil { - t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(infoLog)) + t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(severity.InfoLog)) } want := fmt.Sprintf(data.format, line) - if contents(infoLog) != want { - t.Errorf("InfoS has wrong format: \n got:\t%s\nwant:\t%s", contents(infoLog), want) + if contents(severity.InfoLog) != want { + t.Errorf("InfoS has wrong format: \n got:\t%s\nwant:\t%s", contents(severity.InfoLog), want) } } } @@ -985,24 +989,24 @@ second value line`}, for l := Level(0); l < Level(4); l++ { for _, data := range testDataInfo { - logging.file[infoLog] = &flushBuffer{} + logging.file[severity.InfoLog] = &flushBuffer{} V(l).InfoS(data.msg, data.keysValues...) var want string var line int if l <= 2 { - n, err := fmt.Sscanf(contents(infoLog), data.format, &line) + n, err := fmt.Sscanf(contents(severity.InfoLog), data.format, &line) if n != 1 || err != nil { - t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(infoLog)) + t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(severity.InfoLog)) } want = fmt.Sprintf(data.format, line) } else { want = "" } - if contents(infoLog) != want { - t.Errorf("V(%d).InfoS has unexpected output:\ngot:\n%s\nwant:\n%s\n", l, contents(infoLog), want) + if contents(severity.InfoLog) != want { + t.Errorf("V(%d).InfoS has unexpected output:\ngot:\n%s\nwant:\n%s\n", l, contents(severity.InfoLog), want) } } } @@ -1037,16 +1041,16 @@ func TestErrorS(t *testing.T) { }, } for _, e := range errorList { - logging.file[errorLog] = &flushBuffer{} + logging.file[severity.ErrorLog] = &flushBuffer{} f(e.err, "Failed to update pod status", "pod", "kubedns") var line int - n, err := fmt.Sscanf(contents(errorLog), e.format, &line) + n, err := fmt.Sscanf(contents(severity.ErrorLog), e.format, &line) if n != 1 || err != nil { - t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(errorLog)) + t.Errorf("log format error: %d elements, error %s:\n%s", n, err, contents(severity.ErrorLog)) } want := fmt.Sprintf(e.format, line) - if contents(errorLog) != want { - t.Errorf("ErrorS has wrong format:\ngot:\n%s\nwant:\n%s\n", contents(errorLog), want) + if contents(severity.ErrorLog) != want { + t.Errorf("ErrorS has wrong format:\ngot:\n%s\nwant:\n%s\n", contents(severity.ErrorLog), want) } } } @@ -1056,7 +1060,9 @@ func createTestValueOfLoggingT() *loggingT { l := new(loggingT) l.toStderr = true l.alsoToStderr = false - l.stderrThreshold = errorLog + l.stderrThreshold = severityValue{ + Severity: severity.ErrorLog, + } l.verbosity = Level(0) l.skipHeaders = false l.skipLogHeaders = false @@ -1143,116 +1149,116 @@ func TestLogFilter(t *testing.T) { funcs := []struct { name string logFunc func(args ...interface{}) - severity severity + severity severity.Severity }{{ name: "Info", logFunc: Info, - severity: infoLog, + severity: severity.InfoLog, }, { name: "InfoDepth", logFunc: func(args ...interface{}) { InfoDepth(1, args...) }, - severity: infoLog, + severity: severity.InfoLog, }, { name: "Infoln", logFunc: Infoln, - severity: infoLog, + severity: severity.InfoLog, }, { name: "Infof", logFunc: func(args ...interface{}) { Infof(args[0].(string), args[1:]...) }, - severity: infoLog, + severity: severity.InfoLog, }, { name: "InfoS", logFunc: func(args ...interface{}) { InfoS(args[0].(string), args[1:]...) }, - severity: infoLog, + severity: severity.InfoLog, }, { name: "Warning", logFunc: Warning, - severity: warningLog, + severity: severity.WarningLog, }, { name: "WarningDepth", logFunc: func(args ...interface{}) { WarningDepth(1, args...) }, - severity: warningLog, + severity: severity.WarningLog, }, { name: "Warningln", logFunc: Warningln, - severity: warningLog, + severity: severity.WarningLog, }, { name: "Warningf", logFunc: func(args ...interface{}) { Warningf(args[0].(string), args[1:]...) }, - severity: warningLog, + severity: severity.WarningLog, }, { name: "Error", logFunc: Error, - severity: errorLog, + severity: severity.ErrorLog, }, { name: "ErrorDepth", logFunc: func(args ...interface{}) { ErrorDepth(1, args...) }, - severity: errorLog, + severity: severity.ErrorLog, }, { name: "Errorln", logFunc: Errorln, - severity: errorLog, + severity: severity.ErrorLog, }, { name: "Errorf", logFunc: func(args ...interface{}) { Errorf(args[0].(string), args[1:]...) }, - severity: errorLog, + severity: severity.ErrorLog, }, { name: "ErrorS", logFunc: func(args ...interface{}) { ErrorS(errors.New("testerror"), args[0].(string), args[1:]...) }, - severity: errorLog, + severity: severity.ErrorLog, }, { name: "V().Info", logFunc: func(args ...interface{}) { V(0).Info(args...) }, - severity: infoLog, + severity: severity.InfoLog, }, { name: "V().Infoln", logFunc: func(args ...interface{}) { V(0).Infoln(args...) }, - severity: infoLog, + severity: severity.InfoLog, }, { name: "V().Infof", logFunc: func(args ...interface{}) { V(0).Infof(args[0].(string), args[1:]...) }, - severity: infoLog, + severity: severity.InfoLog, }, { name: "V().InfoS", logFunc: func(args ...interface{}) { V(0).InfoS(args[0].(string), args[1:]...) }, - severity: infoLog, + severity: severity.InfoLog, }, { name: "V().Error", logFunc: func(args ...interface{}) { V(0).Error(errors.New("test error"), args[0].(string), args[1:]...) }, - severity: errorLog, + severity: severity.ErrorLog, }, { name: "V().ErrorS", logFunc: func(args ...interface{}) { V(0).ErrorS(errors.New("test error"), args[0].(string), args[1:]...) }, - severity: errorLog, + severity: severity.ErrorLog, }} testcases := []struct { @@ -1291,13 +1297,13 @@ func TestInfoWithLogr(t *testing.T) { }{{ msg: "foo", expected: testLogrEntry{ - severity: infoLog, + severity: severity.InfoLog, msg: "foo\n", }, }, { msg: "", expected: testLogrEntry{ - severity: infoLog, + severity: severity.InfoLog, msg: "\n", }, }} @@ -1329,7 +1335,7 @@ func TestInfoSWithLogr(t *testing.T) { msg: "foo", keysValues: []interface{}{}, expected: testLogrEntry{ - severity: infoLog, + severity: severity.InfoLog, msg: "foo", keysAndValues: []interface{}{}, }, @@ -1337,7 +1343,7 @@ func TestInfoSWithLogr(t *testing.T) { msg: "bar", keysValues: []interface{}{"a", 1}, expected: testLogrEntry{ - severity: infoLog, + severity: severity.InfoLog, msg: "bar", keysAndValues: []interface{}{"a", 1}, }, @@ -1374,7 +1380,7 @@ func TestErrorSWithLogr(t *testing.T) { msg: "foo1", keysValues: []interface{}{}, expected: testLogrEntry{ - severity: errorLog, + severity: severity.ErrorLog, msg: "foo1", keysAndValues: []interface{}{}, err: testError, @@ -1384,7 +1390,7 @@ func TestErrorSWithLogr(t *testing.T) { msg: "bar1", keysValues: []interface{}{"a", 1}, expected: testLogrEntry{ - severity: errorLog, + severity: severity.ErrorLog, msg: "bar1", keysAndValues: []interface{}{"a", 1}, err: testError, @@ -1394,7 +1400,7 @@ func TestErrorSWithLogr(t *testing.T) { msg: "foo2", keysValues: []interface{}{}, expected: testLogrEntry{ - severity: errorLog, + severity: severity.ErrorLog, msg: "foo2", keysAndValues: []interface{}{}, err: nil, @@ -1404,7 +1410,7 @@ func TestErrorSWithLogr(t *testing.T) { msg: "bar2", keysValues: []interface{}{"a", 1}, expected: testLogrEntry{ - severity: errorLog, + severity: severity.ErrorLog, msg: "bar2", keysAndValues: []interface{}{"a", 1}, err: nil, @@ -1598,7 +1604,7 @@ type testLogr struct { } type testLogrEntry struct { - severity severity + severity severity.Severity msg string keysAndValues []interface{} err error @@ -1614,7 +1620,7 @@ func (l *testLogr) Info(level int, msg string, keysAndValues ...interface{}) { l.mutex.Lock() defer l.mutex.Unlock() l.entries = append(l.entries, testLogrEntry{ - severity: infoLog, + severity: severity.InfoLog, msg: msg, keysAndValues: keysAndValues, }) @@ -1624,7 +1630,7 @@ func (l *testLogr) Error(err error, msg string, keysAndValues ...interface{}) { l.mutex.Lock() defer l.mutex.Unlock() l.entries = append(l.entries, testLogrEntry{ - severity: errorLog, + severity: severity.ErrorLog, msg: msg, keysAndValues: keysAndValues, err: err, @@ -1669,7 +1675,7 @@ func (l *callDepthTestLogr) Info(level int, msg string, keysAndValues ...interfa // test case. _, file, line, _ := runtime.Caller(l.callDepth + 2) l.entries = append(l.entries, testLogrEntry{ - severity: infoLog, + severity: severity.InfoLog, msg: msg, keysAndValues: append([]interface{}{file, line}, keysAndValues...), }) @@ -1682,7 +1688,7 @@ func (l *callDepthTestLogr) Error(err error, msg string, keysAndValues ...interf // test case. _, file, line, _ := runtime.Caller(l.callDepth + 2) l.entries = append(l.entries, testLogrEntry{ - severity: errorLog, + severity: severity.ErrorLog, msg: msg, keysAndValues: append([]interface{}{file, line}, keysAndValues...), err: err, From cda3be772d092b380a509229d775a5a1d337f436 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 9 Feb 2022 16:53:28 +0100 Subject: [PATCH 10/12] klogr: report missing values with "(MISSING)" klogr had a special value for a missing value in a key/value pair, so the intention probably was to use that as replacement, the same way as klog does it. But because of a bug in the code which removed duplicates, it treated a missing value like nil. Now the behavior is consistent with klog. --- internal/serialize/keyvalues.go | 4 ++++ klogr/klogr_test.go | 8 ++++---- test/output_test.go | 10 ++-------- 3 files changed, 10 insertions(+), 12 deletions(-) diff --git a/internal/serialize/keyvalues.go b/internal/serialize/keyvalues.go index 479a3735..c3211ec5 100644 --- a/internal/serialize/keyvalues.go +++ b/internal/serialize/keyvalues.go @@ -36,7 +36,11 @@ func TrimDuplicates(kvLists ...[]interface{}) [][]interface{} { // initialise this output slice outs[i] = []interface{}{} // obtain a reference to the kvList we are processing + // and make sure it has an even number of entries kvList := kvLists[i] + if len(kvList)%2 != 0 { + kvList = append(kvList, missingValue) + } // start iterating at len(kvList) - 2 (i.e. the 2nd last item) for // slices that have an even number of elements. diff --git a/klogr/klogr_test.go b/klogr/klogr_test.go index 7775b436..45565b27 100644 --- a/klogr/klogr_test.go +++ b/klogr/klogr_test.go @@ -113,9 +113,9 @@ func testOutput(t *testing.T, format string) { klogr: new(), text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey2"}, - expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"=null + expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"="(MISSING)" `, - expectedKlogOutput: `"test" akey="avalue" akey2= + expectedKlogOutput: `"test" akey="avalue" akey2="(MISSING)" `, }, "should correctly html characters": { @@ -131,9 +131,9 @@ func testOutput(t *testing.T, format string) { klogr: new().WithValues("basekey1", "basevar1", "basekey2"), text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey2"}, - expectedOutput: ` "msg"="test" "basekey1"="basevar1" "basekey2"=null "akey"="avalue" "akey2"=null + expectedOutput: ` "msg"="test" "basekey1"="basevar1" "basekey2"="(MISSING)" "akey"="avalue" "akey2"="(MISSING)" `, - expectedKlogOutput: `"test" basekey1="basevar1" basekey2= akey="avalue" akey2= + expectedKlogOutput: `"test" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)" `, }, "should correctly print regular error types": { diff --git a/test/output_test.go b/test/output_test.go index 9b316176..ddb47044 100644 --- a/test/output_test.go +++ b/test/output_test.go @@ -42,15 +42,9 @@ func TestKlogrOutput(t *testing.T) { `I output.go:] "test" keyWithoutValue="(MISSING)" I output.go:] "test" keyWithoutValue="(MISSING)" anotherKeyWithoutValue="(MISSING)" I output.go:] "test" keyWithoutValue="(MISSING)" -`: `I output.go:] "test" keyWithoutValue= +`: `I output.go:] "test" keyWithoutValue="(MISSING)" I output.go:] "test" keyWithoutValue="anotherKeyWithoutValue" -I output.go:] "test" keyWithoutValue= -`, - `I output.go:] "test" akey="avalue" akey2="(MISSING)" -`: `I output.go:] "test" akey="avalue" akey2= -`, - `I output.go:] "test" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)" -`: `I output.go:] "test" basekey1="basevar1" basekey2= akey="avalue" akey2= +I output.go:] "test" keyWithoutValue="(MISSING)" `, } Output(t, OutputConfig{ From 5938b0a28c269b21250bc8ae5ff6740f29286f7c Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 9 Feb 2022 20:01:11 +0100 Subject: [PATCH 11/12] klogr: improve handling of missing value in WithValues This is invalid: logger.WithValue("keyWithoutValue").WithValue("anotherKeyWithoutValue") Because it concatenated key/values without checking, klogr treated this like: logger.WithValue("keyWithoutValue", "anotherKeyWithoutValue") Now the parameters are checked and a "(MISSING)" is appended as in the other cases where a missing value is detected. --- internal/serialize/keyvalues.go | 22 ++++++++++++++++++++++ klogr/klogr.go | 4 +--- klogr/klogr_test.go | 9 +++++++++ test/output_test.go | 12 ------------ 4 files changed, 32 insertions(+), 15 deletions(-) diff --git a/internal/serialize/keyvalues.go b/internal/serialize/keyvalues.go index c3211ec5..4f583912 100644 --- a/internal/serialize/keyvalues.go +++ b/internal/serialize/keyvalues.go @@ -22,6 +22,28 @@ import ( "strconv" ) +// WithValues implements LogSink.WithValues. The old key/value pairs are +// assumed to be well-formed, the new ones are checked and padded if +// necessary. It returns a new slice. +func WithValues(oldKV, newKV []interface{}) []interface{} { + if len(newKV) == 0 { + return oldKV + } + newLen := len(oldKV) + len(newKV) + hasMissingValue := newLen%2 != 0 + if hasMissingValue { + newLen++ + } + // The new LogSink must have its own slice. + kv := make([]interface{}, 0, newLen) + kv = append(kv, oldKV...) + kv = append(kv, newKV...) + if hasMissingValue { + kv = append(kv, missingValue) + } + return kv +} + // TrimDuplicates deduplicates elements provided in multiple key/value tuple // slices, whilst maintaining the distinction between where the items are // contained. diff --git a/klogr/klogr.go b/klogr/klogr.go index d8e660e4..02433e84 100644 --- a/klogr/klogr.go +++ b/klogr/klogr.go @@ -170,9 +170,7 @@ func (l klogger) WithName(name string) logr.LogSink { } func (l klogger) WithValues(kvList ...interface{}) logr.LogSink { - // Three slice args forces a copy. - n := len(l.values) - l.values = append(l.values[:n:n], kvList...) + l.values = serialize.WithValues(l.values, kvList) return &l } diff --git a/klogr/klogr_test.go b/klogr/klogr_test.go index 45565b27..ab3a525a 100644 --- a/klogr/klogr_test.go +++ b/klogr/klogr_test.go @@ -116,6 +116,15 @@ func testOutput(t *testing.T, format string) { expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"="(MISSING)" `, expectedKlogOutput: `"test" akey="avalue" akey2="(MISSING)" +`, + }, + "should correctly handle odd-numbers of KVs in WithValue": { + klogr: new().WithValues("keyWithoutValue"), + text: "test", + keysAndValues: []interface{}{"akey", "avalue", "akey2"}, + expectedOutput: ` "msg"="test" "keyWithoutValue"="(MISSING)" "akey"="avalue" "akey2"="(MISSING)" +`, + expectedKlogOutput: `"test" keyWithoutValue="(MISSING)" akey="avalue" akey2="(MISSING)" `, }, "should correctly html characters": { diff --git a/test/output_test.go b/test/output_test.go index ddb47044..8dad50b6 100644 --- a/test/output_test.go +++ b/test/output_test.go @@ -36,21 +36,9 @@ func TestKlogOutput(t *testing.T) { // TestKlogrOutput tests klogr output via klog. func TestKlogrOutput(t *testing.T) { - // klogr currently doesn't produce exactly the same output as klog. - // TODO: fix that. - mapping := map[string]string{ - `I output.go:] "test" keyWithoutValue="(MISSING)" -I output.go:] "test" keyWithoutValue="(MISSING)" anotherKeyWithoutValue="(MISSING)" -I output.go:] "test" keyWithoutValue="(MISSING)" -`: `I output.go:] "test" keyWithoutValue="(MISSING)" -I output.go:] "test" keyWithoutValue="anotherKeyWithoutValue" -I output.go:] "test" keyWithoutValue="(MISSING)" -`, - } Output(t, OutputConfig{ NewLogger: func(out io.Writer, v int, vmodule string) logr.Logger { return klogr.NewWithOptions(klogr.WithFormat(klogr.FormatKlog)) }, - ExpectedOutputMapping: mapping, }) } From 71ac98f1c83165bf1b83b8be5f2a5911f077a18a Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 9 Feb 2022 11:58:09 +0100 Subject: [PATCH 12/12] textlogger: add logger which emulates the traditional output In contrast to klogr, the formatting and printing is handled entirely by this logger without depending on klog.go. The intention is to use this in two ways: - for testing of SetLogger - as simpler text logger in Kubernetes for contextual logging --- test/output_test.go | 21 +++++ textlogger/options.go | 139 +++++++++++++++++++++++++++++++++ textlogger/textlogger.go | 163 +++++++++++++++++++++++++++++++++++++++ 3 files changed, 323 insertions(+) create mode 100644 textlogger/options.go create mode 100644 textlogger/textlogger.go diff --git a/test/output_test.go b/test/output_test.go index 8dad50b6..5a43a1ce 100644 --- a/test/output_test.go +++ b/test/output_test.go @@ -23,6 +23,7 @@ import ( "github.com/go-logr/logr" "k8s.io/klog/v2/klogr" + "k8s.io/klog/v2/textlogger" ) func init() { @@ -34,6 +35,26 @@ func TestKlogOutput(t *testing.T) { Output(t, OutputConfig{}) } +// TestTextloggerOutput tests the textlogger, directly and as backend. +func TestTextloggerOutput(t *testing.T) { + newLogger := func(out io.Writer, v int, vmodule string) logr.Logger { + config := textlogger.NewConfig( + textlogger.Verbosity(v), + textlogger.Output(out), + ) + if err := config.VModule().Set(vmodule); err != nil { + panic(err) + } + return textlogger.NewLogger(config) + } + t.Run("direct", func(t *testing.T) { + Output(t, OutputConfig{NewLogger: newLogger, SupportsVModule: true}) + }) + t.Run("klog-backend", func(t *testing.T) { + Output(t, OutputConfig{NewLogger: newLogger, AsBackend: true}) + }) +} + // TestKlogrOutput tests klogr output via klog. func TestKlogrOutput(t *testing.T) { Output(t, OutputConfig{ diff --git a/textlogger/options.go b/textlogger/options.go new file mode 100644 index 00000000..28188ddf --- /dev/null +++ b/textlogger/options.go @@ -0,0 +1,139 @@ +/* +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 textlogger + +import ( + "flag" + "io" + "os" + "strconv" + + "k8s.io/klog/v2/internal/verbosity" +) + +// Config influences logging in a text logger. To make this configurable via +// command line flags, instantiate this once per program and use AddFlags to +// bind command line flags to the instance before passing it to NewTestContext. +// +// Must be constructed with NewConfig. +// +// Experimental +// +// Notice: This type is EXPERIMENTAL and may be changed or removed in a +// later release. +type Config struct { + *verbosity.VState + co configOptions +} + +// ConfigOption implements functional parameters for NewConfig. +// +// Experimental +// +// Notice: This type is EXPERIMENTAL and may be changed or removed in a +// later release. +type ConfigOption func(co *configOptions) + +type configOptions struct { + verbosityFlagName string + vmoduleFlagName string + verbosityDefault int + output io.Writer +} + +// VerbosityFlagName overrides the default -v for the verbosity level. +func VerbosityFlagName(name string) ConfigOption { + return func(co *configOptions) { + + co.verbosityFlagName = name + } +} + +// VModulFlagName overrides the default -vmodule for the per-module +// verbosity levels. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func VModuleFlagName(name string) ConfigOption { + return func(co *configOptions) { + co.vmoduleFlagName = name + } +} + +// Verbosity overrides the default verbosity level of 0. +// See https://github.com/kubernetes/community/blob/9406b4352fe2d5810cb21cc3cb059ce5886de157/contributors/devel/sig-instrumentation/logging.md#logging-conventions +// for log level conventions in Kubernetes. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func Verbosity(level int) ConfigOption { + return func(co *configOptions) { + co.verbosityDefault = level + } +} + +// Output overrides stderr as the output stream. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func Output(output io.Writer) ConfigOption { + return func(co *configOptions) { + co.output = output + } +} + +// NewConfig returns a configuration with recommended defaults and optional +// modifications. Command line flags are not bound to any FlagSet yet. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func NewConfig(opts ...ConfigOption) *Config { + c := &Config{ + VState: verbosity.New(), + co: configOptions{ + verbosityFlagName: "v", + vmoduleFlagName: "vmodule", + verbosityDefault: 0, + output: os.Stderr, + }, + } + for _, opt := range opts { + opt(&c.co) + } + + c.V().Set(strconv.FormatInt(int64(c.co.verbosityDefault), 10)) + return c +} + +// AddFlags registers the command line flags that control the configuration. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. +func (c *Config) AddFlags(fs *flag.FlagSet) { + fs.Var(c.V(), c.co.verbosityFlagName, "number for the log level verbosity of the testing logger") + fs.Var(c.VModule(), c.co.vmoduleFlagName, "comma-separated list of pattern=N log level settings for files matching the patterns") +} diff --git a/textlogger/textlogger.go b/textlogger/textlogger.go new file mode 100644 index 00000000..2c0ec88f --- /dev/null +++ b/textlogger/textlogger.go @@ -0,0 +1,163 @@ +/* +Copyright 2019 The Kubernetes Authors. +Copyright 2020 Intel Coporation. + +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 textlogger contains an implementation of the logr interface +// which is producing the exact same output as klog. +// +// Experimental +// +// Notice: This package is EXPERIMENTAL and may be changed or removed in a +// later release. +package textlogger + +import ( + "runtime" + "strconv" + "strings" + "time" + + "github.com/go-logr/logr" + + "k8s.io/klog/v2/internal/buffer" + "k8s.io/klog/v2/internal/serialize" + "k8s.io/klog/v2/internal/severity" + "k8s.io/klog/v2/internal/verbosity" +) + +var ( + // TimeNow is used to retrieve the current time. May be changed for testing. + // + // Experimental + // + // Notice: This variable is EXPERIMENTAL and may be changed or removed in a + // later release. + TimeNow = time.Now +) + +// NewLogger constructs a new logger. +// +// Experimental +// +// Notice: This function is EXPERIMENTAL and may be changed or removed in a +// later release. The behavior of the returned Logger may change. +func NewLogger(c *Config) logr.Logger { + return logr.New(&tlogger{ + prefix: "", + values: nil, + config: c, + bufferCache: &buffer.Buffers{}, + }) +} + +type tlogger struct { + callDepth int + prefix string + values []interface{} + config *Config + bufferCache *buffer.Buffers +} + +func copySlice(in []interface{}) []interface{} { + out := make([]interface{}, len(in)) + copy(out, in) + return out +} + +func (l *tlogger) Init(info logr.RuntimeInfo) { + l.callDepth = info.CallDepth +} + +func (l *tlogger) WithCallDepth(depth int) logr.LogSink { + newLogger := *l + newLogger.callDepth += depth + return &newLogger +} + +func (l *tlogger) Enabled(level int) bool { + return l.config.Enabled(verbosity.Level(level), 1) +} + +func (l *tlogger) Info(level int, msg string, kvList ...interface{}) { + l.print(nil, severity.InfoLog, msg, kvList) +} + +func (l *tlogger) Error(err error, msg string, kvList ...interface{}) { + l.print(err, severity.ErrorLog, msg, kvList) +} + +func (l *tlogger) print(err error, s severity.Severity, msg string, kvList []interface{}) { + // Only create a new buffer if we don't have one cached. + b := l.bufferCache.GetBuffer() + + // Determine caller. + // +1 for this frame, +1 for Info/Error. + _, file, line, ok := runtime.Caller(l.callDepth + 2) + if !ok { + file = "???" + line = 1 + } else { + if slash := strings.LastIndex(file, "/"); slash >= 0 { + path := file + file = path[slash+1:] + } + } + + // Format header. + now := TimeNow() + b.FormatHeader(s, file, line, now) + + // Inject WithName names into message. + if l.prefix != "" { + msg = l.prefix + ": " + msg + } + + // The message is always quoted, even if it contains line breaks. + // If developers want multi-line output, they should use a small, fixed + // message and put the multi-line output into a value. + b.WriteString(strconv.Quote(msg)) + if err != nil { + serialize.KVListFormat(&b.Buffer, "err", err) + } + trimmed := serialize.TrimDuplicates(l.values, kvList) + serialize.KVListFormat(&b.Buffer, trimmed[0]...) + serialize.KVListFormat(&b.Buffer, trimmed[1]...) + if b.Len() == 0 || b.Bytes()[b.Len()-1] != '\n' { + b.WriteByte('\n') + } + l.config.co.output.Write(b.Bytes()) +} + +// WithName returns a new logr.Logger with the specified name appended. klogr +// uses '/' characters to separate name elements. Callers should not pass '/' +// in the provided name string, but this library does not actually enforce that. +func (l *tlogger) WithName(name string) logr.LogSink { + new := *l + if len(l.prefix) > 0 { + new.prefix = l.prefix + "/" + } + new.prefix += name + return &new +} + +func (l *tlogger) WithValues(kvList ...interface{}) logr.LogSink { + new := *l + new.values = serialize.WithValues(l.values, kvList) + return &new +} + +var _ logr.LogSink = &tlogger{} +var _ logr.CallDepthLogSink = &tlogger{}