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 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/serialize/keyvalues.go b/internal/serialize/keyvalues.go new file mode 100644 index 00000000..4f583912 --- /dev/null +++ b/internal/serialize/keyvalues.go @@ -0,0 +1,211 @@ +/* +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" +) + +// 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. +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 + // 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. + // 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/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/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/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) + } +} diff --git a/klog.go b/klog.go index 7cf60f9e..3435461d 100644 --- a/klog.go +++ b/klog.go @@ -90,81 +90,57 @@ import ( "time" "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 @@ -187,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 @@ -406,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 = "" @@ -457,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. @@ -518,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. @@ -547,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. /* @@ -595,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 = "???" @@ -615,119 +555,46 @@ 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) } 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{}) { +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) @@ -739,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) @@ -758,19 +625,19 @@ 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 // 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) @@ -791,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. @@ -803,140 +670,25 @@ 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. 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 >") - } + l.bufferCache.PutBuffer(b) } // redirectBuffer is used to set an alternate destination for the logs @@ -988,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, } @@ -1000,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)) } @@ -1019,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() { @@ -1038,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)) } @@ -1053,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 { @@ -1072,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() @@ -1103,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) } @@ -1113,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) @@ -1185,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. } @@ -1231,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 } @@ -1269,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, @@ -1307,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 @@ -1324,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)) } @@ -1336,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). @@ -1360,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 } @@ -1465,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...) } } @@ -1473,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...) } } @@ -1481,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...) } } @@ -1489,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...) } } @@ -1497,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...) } } @@ -1505,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...) } } @@ -1549,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. @@ -1597,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.printDepth(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.printDepth(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. @@ -1689,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.printDepth(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. @@ -1732,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.printDepth(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 17caaf4e..6e166763 100644 --- a/klog_test.go +++ b/klog_test.go @@ -35,6 +35,10 @@ import ( "time" "github.com/go-logr/logr" + + "k8s.io/klog/v2/internal/buffer" + "k8s.io/klog/v2/internal/severity" + "k8s.io/klog/v2/internal/test" ) // TODO: This test package should be refactored so that tests cannot @@ -67,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 @@ -78,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) } @@ -103,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") } } @@ -122,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)) } @@ -174,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") } } @@ -190,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) } } @@ -217,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)) } } @@ -229,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") } } @@ -256,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") } } @@ -278,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") } } @@ -302,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") } } @@ -321,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") } } @@ -345,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") } } @@ -365,7 +369,7 @@ func TestVmoduleOff(t *testing.T) { } } V(2).Info("test") - if contents(infoLog) != "" { + if contents(severity.InfoLog) != "" { t.Error("V logged incorrectly") } } @@ -467,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") } @@ -528,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") } @@ -593,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 @@ -602,27 +606,36 @@ 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) } } // 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 @@ -633,7 +646,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) @@ -654,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") @@ -764,35 +779,13 @@ 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)) } }) } } -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 @@ -801,17 +794,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{}, }, { @@ -821,7 +814,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", @@ -829,7 +822,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", }, @@ -920,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) } } } @@ -996,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) } } } @@ -1048,149 +1041,28 @@ 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) } } } } -// 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 l.alsoToStderr = false - l.stderrThreshold = errorLog + l.stderrThreshold = severityValue{ + Severity: severity.ErrorLog, + } l.verbosity = Level(0) l.skipHeaders = false l.skipLogHeaders = false @@ -1277,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 { @@ -1425,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", }, }} @@ -1463,7 +1335,7 @@ func TestInfoSWithLogr(t *testing.T) { msg: "foo", keysValues: []interface{}{}, expected: testLogrEntry{ - severity: infoLog, + severity: severity.InfoLog, msg: "foo", keysAndValues: []interface{}{}, }, @@ -1471,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}, }, @@ -1508,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, @@ -1518,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, @@ -1528,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, @@ -1538,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, @@ -1732,7 +1604,7 @@ type testLogr struct { } type testLogrEntry struct { - severity severity + severity severity.Severity msg string keysAndValues []interface{} err error @@ -1748,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, }) @@ -1758,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, @@ -1803,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...), }) @@ -1816,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, @@ -1879,13 +1751,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", }, {}, }, @@ -1902,13 +1774,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..02433e84 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 } @@ -212,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 7775b436..ab3a525a 100644 --- a/klogr/klogr_test.go +++ b/klogr/klogr_test.go @@ -113,9 +113,18 @@ 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 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": { @@ -131,9 +140,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.go b/test/output.go new file mode 100644 index 00000000..a4174914 --- /dev/null +++ b/test/output.go @@ -0,0 +1,688 @@ +/* +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" + "strconv" + "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)) + }) + }) + } + + 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:] hello world\n", + }, + { + 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:] hello world\n", + }, + { + 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{} { + 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..5a43a1ce --- /dev/null +++ b/test/output_test.go @@ -0,0 +1,65 @@ +/* +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" + "k8s.io/klog/v2/textlogger" +) + +func init() { + InitKlog() +} + +// TestKlogOutput tests klog output without a logger. +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{ + NewLogger: func(out io.Writer, v int, vmodule string) logr.Logger { + return klogr.NewWithOptions(klogr.WithFormat(klogr.FormatKlog)) + }, + }) +} 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{}