From e6d69a51e74ab0a27dbcc00758de6b5a2a45eea0 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 9 May 2022 17:16:47 +0200 Subject: [PATCH 1/4] serialize: benchmark and test TrimDuplicates This is in preparation for enhancing performance of that function. --- internal/serialize/keyvalues_test.go | 155 +++++++++++++++++++++++++++ 1 file changed, 155 insertions(+) diff --git a/internal/serialize/keyvalues_test.go b/internal/serialize/keyvalues_test.go index affb887e..dab2da1c 100644 --- a/internal/serialize/keyvalues_test.go +++ b/internal/serialize/keyvalues_test.go @@ -19,6 +19,7 @@ package serialize_test import ( "bytes" "fmt" + "reflect" "testing" "time" @@ -149,3 +150,157 @@ No whitespace.`, } } } + +func TestDuplicates(t *testing.T) { + for name, test := range map[string]struct { + first, second []interface{} + expectedTrimmed [][]interface{} + }{ + "empty": { + expectedTrimmed: [][]interface{}{{}, {}}, + }, + "no-duplicates": { + first: makeKV("a", 3), + second: makeKV("b", 3), + expectedTrimmed: [][]interface{}{ + makeKV("a", 3), + makeKV("b", 3), + }, + }, + "all-duplicates": { + first: makeKV("a", 3), + second: makeKV("a", 3), + expectedTrimmed: [][]interface{}{ + {}, + makeKV("a", 3), + }, + }, + "start-duplicate": { + first: append([]interface{}{"x", 1}, makeKV("a", 3)...), + second: append([]interface{}{"x", 2}, makeKV("b", 3)...), + expectedTrimmed: [][]interface{}{ + makeKV("a", 3), + append([]interface{}{"x", 2}, makeKV("b", 3)...), + }, + }, + "subset-first": { + first: append([]interface{}{"x", 1}, makeKV("a", 3)...), + second: append([]interface{}{"x", 2}, makeKV("a", 3)...), + expectedTrimmed: [][]interface{}{ + {}, + append([]interface{}{"x", 2}, makeKV("a", 3)...), + }, + }, + "subset-second": { + first: append([]interface{}{"x", 1}, makeKV("a", 1)...), + second: append([]interface{}{"x", 2}, makeKV("b", 2)...), + expectedTrimmed: [][]interface{}{ + makeKV("a", 1), + append([]interface{}{"x", 2}, makeKV("b", 2)...), + }, + }, + "end-duplicate": { + first: append(makeKV("a", 3), "x", 1), + second: append(makeKV("b", 3), "x", 2), + expectedTrimmed: [][]interface{}{ + makeKV("a", 3), + append(makeKV("b", 3), "x", 2), + }, + }, + "middle-duplicate": { + first: []interface{}{"a-0", 0, "x", 1, "a-1", 2}, + second: []interface{}{"b-0", 0, "x", 2, "b-1", 2}, + expectedTrimmed: [][]interface{}{ + {"a-0", 0, "a-1", 2}, + {"b-0", 0, "x", 2, "b-1", 2}, + }, + }, + "internal-duplicates": { + first: []interface{}{"a", 0, "x", 1, "a", 2}, + second: []interface{}{"b", 0, "x", 2, "b", 2}, + expectedTrimmed: [][]interface{}{ + {"a", 2}, + {"x", 2, "b", 2}, + }, + }, + } { + t.Run(name, func(t *testing.T) { + actual := serialize.TrimDuplicates(test.first, test.second) + expectEqual(t, "trimmed key/value pairs", test.expectedTrimmed, actual) + }) + } +} + +// BenchmarkTrimDuplicates checks performance when TrimDuplicates is called with two slices. +// In practice that is how the function is used. +func BenchmarkTrimDuplicates(b *testing.B) { + for firstLength := 0; firstLength < 10; firstLength++ { + firstA := makeKV("a", firstLength) + for secondLength := 0; secondLength < 10; secondLength++ { + secondA := makeKV("a", secondLength) + secondB := makeKV("b", secondLength) + b.Run(fmt.Sprintf("%dx%d", firstLength, secondLength), func(b *testing.B) { + // This is the most common case: all key/value pairs are kept. + b.Run("no-duplicates", func(b *testing.B) { + expected := [][]interface{}{firstA, secondB} + benchTrimDuplicates(b, expected, firstA, secondB) + }) + + // Fairly unlikely... + b.Run("all-duplicates", func(b *testing.B) { + expected := [][]interface{}{{}, secondA} + if firstLength > secondLength { + expected[0] = append(expected[0], firstA[secondLength*2:]...) + } + benchTrimDuplicates(b, expected, firstA, secondA) + }) + + // First entry is the same. + b.Run("start-duplicate", func(b *testing.B) { + first := []interface{}{"x", 1} + first = append(first, firstA...) + second := []interface{}{"x", 1} + second = append(second, secondB...) + expected := [][]interface{}{firstA, second} + benchTrimDuplicates(b, expected, first, second) + }) + + // Last entry is the same. + b.Run("end-duplicate", func(b *testing.B) { + first := firstA[:] + first = append(first, "x", 1) + second := secondB[:] + second = append(second, "x", 1) + expected := [][]interface{}{firstA, second} + benchTrimDuplicates(b, expected, first, second) + }) + }) + } + } +} + +func makeKV(prefix string, length int) []interface{} { + if length == 0 { + return []interface{}{} + } + kv := make([]interface{}, 0, length*2) + for i := 0; i < length; i++ { + kv = append(kv, fmt.Sprintf("%s-%d", prefix, i), i) + } + return kv +} + +func benchTrimDuplicates(b *testing.B, expected interface{}, first, second []interface{}) { + actual := serialize.TrimDuplicates(first, second) + expectEqual(b, "trimmed key/value pairs", expected, actual) + b.ResetTimer() + for i := 0; i < b.N; i++ { + serialize.TrimDuplicates(first, second) + } +} + +func expectEqual(tb testing.TB, what string, expected, actual interface{}) { + if !reflect.DeepEqual(expected, actual) { + tb.Fatalf("Did not get correct %s. Expected:\n %v\nActual:\n %v", what, expected, actual) + } +} From e2432e8fa93f2873f99ab7fb741dbf855e5fb274 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Tue, 10 May 2022 08:09:46 +0200 Subject: [PATCH 2/4] serialize: add MergeKVs as faster TrimDuplicates alternative MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit TrimDuplicates is unnecessarily complex: it takes and returns a variable number of slices when in practice it is always called with a pair of slices and the result is always merged into a single slice. It is also slow and does a lot of allocations. MergeKVs is a simpler implementation that is good enough for merging the WithValues key/value slice with the key/value parameters. It intentionally skips some unnecessary error checking (the WithValues key/value slice was already sanitized), does not handle individual slices that themselves contain duplicates (because that can be avoided through code review and/or static code analysis), and does not handle all potential duplicates (in practice, all keys are string constants). Because of this, it is considerably faster: name old time/op new time/op delta TrimDuplicates/0x0/no-duplicates-36 177ns ± 3% 2ns ± 0% -98.76% (p=0.008 n=5+5) ... TrimDuplicates/9x9/end-duplicate-36 14.1µs ± 1% 3.0µs ± 1% -78.39% (p=0.008 n=5+5) name old alloc/op new alloc/op delta TrimDuplicates/0x0/no-duplicates-36 48.0B ± 0% 0.0B -100.00% (p=0.008 n=5+5) ... TrimDuplicates/9x9/no-duplicates-36 4.35kB ± 0% 0.90kB ± 0% -79.42% (p=0.008 n=5+5) TrimDuplicates/9x9/all-duplicates-36 2.03kB ± 0% 0.90kB ± 0% -55.91% (p=0.008 n=5+5) TrimDuplicates/9x9/start-duplicate-36 4.71kB ± 0% 0.96kB ± 0% -79.56% (p=0.008 n=5+5) TrimDuplicates/9x9/end-duplicate-36 4.71kB ± 0% 0.96kB ± 0% ~ (p=0.079 n=4+5) name old allocs/op new allocs/op delta TrimDuplicates/0x0/no-duplicates-36 1.00 ± 0% 0.00 -100.00% (p=0.008 n=5+5) ... TrimDuplicates/9x9/end-duplicate-36 39.0 ± 0% 2.0 ± 0% -94.87% (p=0.008 n=5+5) --- internal/serialize/keyvalues.go | 45 ++++++++++++++++++++++++++++ internal/serialize/keyvalues_test.go | 43 +++++++++++++++++++------- 2 files changed, 78 insertions(+), 10 deletions(-) diff --git a/internal/serialize/keyvalues.go b/internal/serialize/keyvalues.go index d8973136..e64dab36 100644 --- a/internal/serialize/keyvalues.go +++ b/internal/serialize/keyvalues.go @@ -93,6 +93,51 @@ func TrimDuplicates(kvLists ...[]interface{}) [][]interface{} { return outs } +// MergeKVs deduplicates elements provided in two key/value slices. +// +// Keys in each slice are expected to be unique, so duplicates can only occur +// when the first and second slice contain the same key. When that happens, the +// key/value pair from the second slice is used. The first slice must be well-formed +// (= even key/value pairs). The second one may have a missing value, in which +// case the special "missing value" is added to the result. +func MergeKVs(first, second []interface{}) []interface{} { + maxLength := len(first) + (len(second)+1)/2*2 + if maxLength == 0 { + // Nothing to do at all. + return nil + } + + if len(first) == 0 && len(second)%2 == 0 { + // Nothing to be overridden, second slice is well-formed + // and can be used directly. + return second + } + + // Determine which keys are in the second slice so that we can skip + // them when iterating over the first one. The code intentionally + // favors performance over completeness: we assume that keys are string + // constants and thus compare equal when the string values are equal. A + // string constant being overridden by, for example, a fmt.Stringer is + // not handled. + overrides := map[interface{}]bool{} + for i := 0; i < len(second); i += 2 { + overrides[second[i]] = true + } + merged := make([]interface{}, 0, maxLength) + for i := 0; i+1 < len(first); i += 2 { + key := first[i] + if overrides[key] { + continue + } + merged = append(merged, key, first[i+1]) + } + merged = append(merged, second...) + if len(merged)%2 != 0 { + merged = append(merged, missingValue) + } + return merged +} + const missingValue = "(MISSING)" // KVListFormat serializes all key/value pairs into the provided buffer. diff --git a/internal/serialize/keyvalues_test.go b/internal/serialize/keyvalues_test.go index dab2da1c..7fd95e7e 100644 --- a/internal/serialize/keyvalues_test.go +++ b/internal/serialize/keyvalues_test.go @@ -155,6 +155,7 @@ func TestDuplicates(t *testing.T) { for name, test := range map[string]struct { first, second []interface{} expectedTrimmed [][]interface{} + expectedMerged []interface{} }{ "empty": { expectedTrimmed: [][]interface{}{{}, {}}, @@ -166,6 +167,7 @@ func TestDuplicates(t *testing.T) { makeKV("a", 3), makeKV("b", 3), }, + expectedMerged: append(makeKV("a", 3), makeKV("b", 3)...), }, "all-duplicates": { first: makeKV("a", 3), @@ -174,6 +176,7 @@ func TestDuplicates(t *testing.T) { {}, makeKV("a", 3), }, + expectedMerged: makeKV("a", 3), }, "start-duplicate": { first: append([]interface{}{"x", 1}, makeKV("a", 3)...), @@ -182,6 +185,7 @@ func TestDuplicates(t *testing.T) { makeKV("a", 3), append([]interface{}{"x", 2}, makeKV("b", 3)...), }, + expectedMerged: append(append(makeKV("a", 3), "x", 2), makeKV("b", 3)...), }, "subset-first": { first: append([]interface{}{"x", 1}, makeKV("a", 3)...), @@ -190,6 +194,7 @@ func TestDuplicates(t *testing.T) { {}, append([]interface{}{"x", 2}, makeKV("a", 3)...), }, + expectedMerged: append([]interface{}{"x", 2}, makeKV("a", 3)...), }, "subset-second": { first: append([]interface{}{"x", 1}, makeKV("a", 1)...), @@ -198,6 +203,7 @@ func TestDuplicates(t *testing.T) { makeKV("a", 1), append([]interface{}{"x", 2}, makeKV("b", 2)...), }, + expectedMerged: append(append(makeKV("a", 1), "x", 2), makeKV("b", 2)...), }, "end-duplicate": { first: append(makeKV("a", 3), "x", 1), @@ -206,6 +212,7 @@ func TestDuplicates(t *testing.T) { makeKV("a", 3), append(makeKV("b", 3), "x", 2), }, + expectedMerged: append(makeKV("a", 3), append(makeKV("b", 3), "x", 2)...), }, "middle-duplicate": { first: []interface{}{"a-0", 0, "x", 1, "a-1", 2}, @@ -214,6 +221,7 @@ func TestDuplicates(t *testing.T) { {"a-0", 0, "a-1", 2}, {"b-0", 0, "x", 2, "b-1", 2}, }, + expectedMerged: []interface{}{"a-0", 0, "a-1", 2, "b-0", 0, "x", 2, "b-1", 2}, }, "internal-duplicates": { first: []interface{}{"a", 0, "x", 1, "a", 2}, @@ -222,11 +230,22 @@ func TestDuplicates(t *testing.T) { {"a", 2}, {"x", 2, "b", 2}, }, + // This is the case where Merged keeps key/value pairs + // that were already duplicated inside the slices, for + // performance. + expectedMerged: []interface{}{"a", 0, "a", 2, "b", 0, "x", 2, "b", 2}, }, } { t.Run(name, func(t *testing.T) { - actual := serialize.TrimDuplicates(test.first, test.second) - expectEqual(t, "trimmed key/value pairs", test.expectedTrimmed, actual) + t.Run("TrimDuplicates", func(t *testing.T) { + actual := serialize.TrimDuplicates(test.first, test.second) + expectEqual(t, "trimmed key/value pairs", test.expectedTrimmed, actual) + }) + + t.Run("Merged", func(t *testing.T) { + actual := serialize.MergeKVs(test.first, test.second) + expectEqual(t, "merged key/value pairs", test.expectedMerged, actual) + }) }) } } @@ -242,16 +261,17 @@ func BenchmarkTrimDuplicates(b *testing.B) { b.Run(fmt.Sprintf("%dx%d", firstLength, secondLength), func(b *testing.B) { // This is the most common case: all key/value pairs are kept. b.Run("no-duplicates", func(b *testing.B) { - expected := [][]interface{}{firstA, secondB} + expected := append(firstA, secondB...) benchTrimDuplicates(b, expected, firstA, secondB) }) // Fairly unlikely... b.Run("all-duplicates", func(b *testing.B) { - expected := [][]interface{}{{}, secondA} + var expected []interface{} if firstLength > secondLength { - expected[0] = append(expected[0], firstA[secondLength*2:]...) + expected = firstA[secondLength*2:] } + expected = append(expected, secondA...) benchTrimDuplicates(b, expected, firstA, secondA) }) @@ -261,7 +281,7 @@ func BenchmarkTrimDuplicates(b *testing.B) { first = append(first, firstA...) second := []interface{}{"x", 1} second = append(second, secondB...) - expected := [][]interface{}{firstA, second} + expected := append(firstA, second...) benchTrimDuplicates(b, expected, first, second) }) @@ -271,7 +291,7 @@ func BenchmarkTrimDuplicates(b *testing.B) { first = append(first, "x", 1) second := secondB[:] second = append(second, "x", 1) - expected := [][]interface{}{firstA, second} + expected := append(firstA, second...) benchTrimDuplicates(b, expected, first, second) }) }) @@ -290,12 +310,15 @@ func makeKV(prefix string, length int) []interface{} { return kv } -func benchTrimDuplicates(b *testing.B, expected interface{}, first, second []interface{}) { - actual := serialize.TrimDuplicates(first, second) +func benchTrimDuplicates(b *testing.B, expected []interface{}, first, second []interface{}) { + if len(expected) == 0 { + expected = nil + } + actual := serialize.MergeKVs(first, second) expectEqual(b, "trimmed key/value pairs", expected, actual) b.ResetTimer() for i := 0; i < b.N; i++ { - serialize.TrimDuplicates(first, second) + serialize.MergeKVs(first, second) } } From 6f47a32bc641bf2b345056d841a06831276dfd28 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Tue, 10 May 2022 08:55:49 +0200 Subject: [PATCH 3/4] klogr: simplify test failure message The mismatch is easier to see when the output is printed above each other instead of side-by-side. --- klogr/klogr_test.go | 2 +- ktesting/testinglogger_test.go | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/klogr/klogr_test.go b/klogr/klogr_test.go index ab3a525a..7e95b905 100644 --- a/klogr/klogr_test.go +++ b/klogr/klogr_test.go @@ -200,7 +200,7 @@ func testOutput(t *testing.T, format string) { expectedOutput = test.expectedKlogOutput } if actual != expectedOutput { - t.Errorf("expected %q did not match actual %q", expectedOutput, actual) + t.Errorf("Expected:\n%s\nActual:\n%s\n", expectedOutput, actual) } }) } diff --git a/ktesting/testinglogger_test.go b/ktesting/testinglogger_test.go index 430ece7c..cc19c3b3 100644 --- a/ktesting/testinglogger_test.go +++ b/ktesting/testinglogger_test.go @@ -118,7 +118,7 @@ func TestInfo(t *testing.T) { actual := buffer.String() if actual != test.expectedOutput { - t.Errorf("expected %q did not match actual %q", test.expectedOutput, actual) + t.Errorf("Expected:\n%sActual:\n%s\n", test.expectedOutput, actual) } }) } From 4c3943c51f1386f8ce491a23b070f29f9936a4bc Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Tue, 10 May 2022 09:34:42 +0200 Subject: [PATCH 4/4] use faster MergeKVs Performance is better. This slightly changes the output of the traditional klogr format: - all key/value pairs gets sorted, not just each slice (an improvement?) - a single space is printed where previously two were printed klog no longer de-duplicates when the same key is passed twice in the same call (WithValues, InfoS, etc.). That should not occur in practice and can be prevented via code review and/or static code analysis, so we don't need to pay the price of checking for it at runtime. --- klogr.go | 8 +++---- klogr/klogr.go | 28 ++++++++++++---------- klogr/klogr_test.go | 44 ++++++++++++++++++---------------- ktesting/testinglogger.go | 10 ++++---- ktesting/testinglogger_test.go | 4 ++-- test/output.go | 16 +++++-------- test/zapr.go | 4 ++++ textlogger/textlogger.go | 5 ++-- 8 files changed, 60 insertions(+), 59 deletions(-) diff --git a/klogr.go b/klogr.go index 351d7a74..027a4014 100644 --- a/klogr.go +++ b/klogr.go @@ -43,11 +43,11 @@ func (l *klogger) Init(info logr.RuntimeInfo) { } func (l klogger) Info(level int, msg string, kvList ...interface{}) { - trimmed := serialize.TrimDuplicates(l.values, kvList) + merged := serialize.MergeKVs(l.values, kvList) if l.prefix != "" { msg = l.prefix + ": " + msg } - V(Level(level)).InfoSDepth(l.callDepth+1, msg, append(trimmed[0], trimmed[1]...)...) + V(Level(level)).InfoSDepth(l.callDepth+1, msg, merged...) } func (l klogger) Enabled(level int) bool { @@ -55,11 +55,11 @@ func (l klogger) Enabled(level int) bool { } func (l klogger) Error(err error, msg string, kvList ...interface{}) { - trimmed := serialize.TrimDuplicates(l.values, kvList) + merged := serialize.MergeKVs(l.values, kvList) if l.prefix != "" { msg = l.prefix + ": " + msg } - ErrorSDepth(l.callDepth+1, err, msg, append(trimmed[0], trimmed[1]...)...) + ErrorSDepth(l.callDepth+1, err, msg, merged...) } // WithName returns a new logr.Logger with the specified name appended. klogr diff --git a/klogr/klogr.go b/klogr/klogr.go index 48cb6581..c94e551e 100644 --- a/klogr/klogr.go +++ b/klogr/klogr.go @@ -85,7 +85,11 @@ func flatten(kvList ...interface{}) string { if i+1 < len(kvList) { v = kvList[i+1] } - keys = append(keys, k) + // Only print each key once... + if _, seen := vals[k]; !seen { + keys = append(keys, k) + } + // ... with the latest value. vals[k] = v } sort.Strings(keys) @@ -119,16 +123,15 @@ func (l klogger) Info(level int, msg string, kvList ...interface{}) { switch l.format { case FormatSerialize: msgStr := flatten("msg", msg) - trimmed := serialize.TrimDuplicates(l.values, kvList) - fixedStr := flatten(trimmed[0]...) - userStr := flatten(trimmed[1]...) - klog.V(klog.Level(level)).InfoDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", fixedStr, " ", userStr) + merged := serialize.MergeKVs(l.values, kvList) + kvStr := flatten(merged...) + klog.V(klog.Level(level)).InfoDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", kvStr) case FormatKlog: - trimmed := serialize.TrimDuplicates(l.values, kvList) + merged := serialize.MergeKVs(l.values, kvList) if l.prefix != "" { msg = l.prefix + ": " + msg } - klog.V(klog.Level(level)).InfoSDepth(l.callDepth+1, msg, append(trimmed[0], trimmed[1]...)...) + klog.V(klog.Level(level)).InfoSDepth(l.callDepth+1, msg, merged...) } } @@ -145,16 +148,15 @@ func (l klogger) Error(err error, msg string, kvList ...interface{}) { switch l.format { case FormatSerialize: errStr := flatten("error", loggableErr) - 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) + merged := serialize.MergeKVs(l.values, kvList) + kvStr := flatten(merged...) + klog.ErrorDepth(l.callDepth+1, l.prefix, " ", msgStr, " ", errStr, " ", kvStr) case FormatKlog: - trimmed := serialize.TrimDuplicates(l.values, kvList) + merged := serialize.MergeKVs(l.values, kvList) if l.prefix != "" { msg = l.prefix + ": " + msg } - klog.ErrorSDepth(l.callDepth+1, err, msg, append(trimmed[0], trimmed[1]...)...) + klog.ErrorSDepth(l.callDepth+1, err, msg, merged...) } } diff --git a/klogr/klogr_test.go b/klogr/klogr_test.go index 7e95b905..22ec1dc3 100644 --- a/klogr/klogr_test.go +++ b/klogr/klogr_test.go @@ -41,7 +41,7 @@ func testOutput(t *testing.T, format string) { klogr: new().V(0), text: "test", keysAndValues: []interface{}{"akey", "avalue"}, - expectedOutput: ` "msg"="test" "akey"="avalue" + expectedOutput: ` "msg"="test" "akey"="avalue" `, expectedKlogOutput: `"test" akey="avalue" `, @@ -50,7 +50,7 @@ func testOutput(t *testing.T, format string) { klogr: new().V(0).WithName("me"), text: "test", keysAndValues: []interface{}{"akey", "avalue"}, - expectedOutput: `me "msg"="test" "akey"="avalue" + expectedOutput: `me "msg"="test" "akey"="avalue" `, expectedKlogOutput: `"me: test" akey="avalue" `, @@ -59,34 +59,34 @@ func testOutput(t *testing.T, format string) { klogr: new().V(0).WithName("hello").WithName("world"), text: "test", keysAndValues: []interface{}{"akey", "avalue"}, - expectedOutput: `hello/world "msg"="test" "akey"="avalue" + expectedOutput: `hello/world "msg"="test" "akey"="avalue" `, expectedKlogOutput: `"hello/world: test" akey="avalue" `, }, - "should not print duplicate keys with the same value": { + "may print duplicate keys with the same value": { klogr: new().V(0), text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue"}, - expectedOutput: ` "msg"="test" "akey"="avalue" + expectedOutput: ` "msg"="test" "akey"="avalue" `, - expectedKlogOutput: `"test" akey="avalue" + expectedKlogOutput: `"test" akey="avalue" akey="avalue" `, }, - "should only print the last duplicate key when the values are passed to Info": { + "may print duplicate keys when the values are passed to Info": { klogr: new().V(0), text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue2"}, - expectedOutput: ` "msg"="test" "akey"="avalue2" + expectedOutput: ` "msg"="test" "akey"="avalue2" `, - expectedKlogOutput: `"test" akey="avalue2" + expectedKlogOutput: `"test" akey="avalue" akey="avalue2" `, }, "should only print the duplicate key that is passed to Info if one was passed to the logger": { klogr: new().WithValues("akey", "avalue"), text: "test", keysAndValues: []interface{}{"akey", "avalue"}, - expectedOutput: ` "msg"="test" "akey"="avalue" + expectedOutput: ` "msg"="test" "akey"="avalue" `, expectedKlogOutput: `"test" akey="avalue" `, @@ -95,7 +95,7 @@ func testOutput(t *testing.T, format string) { klogr: new().WithValues("akey9", "avalue9", "akey8", "avalue8", "akey1", "avalue1"), text: "test", keysAndValues: []interface{}{"akey5", "avalue5", "akey4", "avalue4"}, - expectedOutput: ` "msg"="test" "akey1"="avalue1" "akey8"="avalue8" "akey9"="avalue9" "akey4"="avalue4" "akey5"="avalue5" + expectedOutput: ` "msg"="test" "akey1"="avalue1" "akey4"="avalue4" "akey5"="avalue5" "akey8"="avalue8" "akey9"="avalue9" `, expectedKlogOutput: `"test" akey9="avalue9" akey8="avalue8" akey1="avalue1" akey5="avalue5" akey4="avalue4" `, @@ -104,7 +104,7 @@ func testOutput(t *testing.T, format string) { klogr: new().WithValues("akey", "avalue"), text: "test", keysAndValues: []interface{}{"akey", "avalue2"}, - expectedOutput: ` "msg"="test" "akey"="avalue2" + expectedOutput: ` "msg"="test" "akey"="avalue2" `, expectedKlogOutput: `"test" akey="avalue2" `, @@ -113,7 +113,7 @@ func testOutput(t *testing.T, format string) { klogr: new(), text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey2"}, - expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"="(MISSING)" + expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"="(MISSING)" `, expectedKlogOutput: `"test" akey="avalue" akey2="(MISSING)" `, @@ -122,7 +122,8 @@ func testOutput(t *testing.T, format string) { klogr: new().WithValues("keyWithoutValue"), text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey2"}, - expectedOutput: ` "msg"="test" "keyWithoutValue"="(MISSING)" "akey"="avalue" "akey2"="(MISSING)" + // klogr format sorts all key/value pairs. + expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"="(MISSING)" "keyWithoutValue"="(MISSING)" `, expectedKlogOutput: `"test" keyWithoutValue="(MISSING)" akey="avalue" akey2="(MISSING)" `, @@ -131,7 +132,7 @@ func testOutput(t *testing.T, format string) { klogr: new(), text: "test", keysAndValues: []interface{}{"akey", "<&>"}, - expectedOutput: ` "msg"="test" "akey"="<&>" + expectedOutput: ` "msg"="test" "akey"="<&>" `, expectedKlogOutput: `"test" akey="<&>" `, @@ -140,7 +141,8 @@ 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"="(MISSING)" "akey"="avalue" "akey2"="(MISSING)" + // klogr format sorts all key/value pairs. + expectedOutput: ` "msg"="test" "akey"="avalue" "akey2"="(MISSING)" "basekey1"="basevar1" "basekey2"="(MISSING)" `, expectedKlogOutput: `"test" basekey1="basevar1" basekey2="(MISSING)" akey="avalue" akey2="(MISSING)" `, @@ -149,7 +151,7 @@ func testOutput(t *testing.T, format string) { klogr: new().V(0), text: "test", keysAndValues: []interface{}{"err", errors.New("whoops")}, - expectedOutput: ` "msg"="test" "err"="whoops" + expectedOutput: ` "msg"="test" "err"="whoops" `, expectedKlogOutput: `"test" err="whoops" `, @@ -158,7 +160,7 @@ func testOutput(t *testing.T, format string) { klogr: new().V(0), text: "test", keysAndValues: []interface{}{"err", &customErrorJSON{"whoops"}}, - expectedOutput: ` "msg"="test" "err"="WHOOPS" + expectedOutput: ` "msg"="test" "err"="WHOOPS" `, expectedKlogOutput: `"test" err="whoops" `, @@ -168,9 +170,9 @@ func testOutput(t *testing.T, format string) { text: "test", err: errors.New("whoops"), // The message is printed to three different log files (info, warning, error), so we see it three times in our output buffer. - expectedOutput: ` "msg"="test" "error"="whoops" - "msg"="test" "error"="whoops" - "msg"="test" "error"="whoops" + expectedOutput: ` "msg"="test" "error"="whoops" + "msg"="test" "error"="whoops" + "msg"="test" "error"="whoops" `, expectedKlogOutput: `"test" err="whoops" "test" err="whoops" diff --git a/ktesting/testinglogger.go b/ktesting/testinglogger.go index 5269f89d..d796f60a 100644 --- a/ktesting/testinglogger.go +++ b/ktesting/testinglogger.go @@ -81,9 +81,8 @@ func (l *tlogger) GetCallStackHelper() func() { func (l *tlogger) Info(level int, msg string, kvList ...interface{}) { l.t.Helper() buffer := &bytes.Buffer{} - trimmed := serialize.TrimDuplicates(l.values, kvList) - serialize.KVListFormat(buffer, trimmed[0]...) - serialize.KVListFormat(buffer, trimmed[1]...) + merged := serialize.MergeKVs(l.values, kvList) + serialize.KVListFormat(buffer, merged...) l.log("INFO", msg, buffer) } @@ -97,9 +96,8 @@ func (l *tlogger) Error(err error, msg string, kvList ...interface{}) { if err != nil { serialize.KVListFormat(buffer, "err", err) } - trimmed := serialize.TrimDuplicates(l.values, kvList) - serialize.KVListFormat(buffer, trimmed[0]...) - serialize.KVListFormat(buffer, trimmed[1]...) + merged := serialize.MergeKVs(l.values, kvList) + serialize.KVListFormat(buffer, merged...) l.log("ERROR", msg, buffer) } diff --git a/ktesting/testinglogger_test.go b/ktesting/testinglogger_test.go index cc19c3b3..6c7ae187 100644 --- a/ktesting/testinglogger_test.go +++ b/ktesting/testinglogger_test.go @@ -46,13 +46,13 @@ func TestInfo(t *testing.T) { "should not print duplicate keys with the same value": { text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue"}, - expectedOutput: `INFO test akey="avalue" + expectedOutput: `INFO test akey="avalue" akey="avalue" `, }, "should only print the last duplicate key when the values are passed to Info": { text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue2"}, - expectedOutput: `INFO test akey="avalue2" + expectedOutput: `INFO test akey="avalue" akey="avalue2" `, }, "should only print the duplicate key that is passed to Info if one was passed to the logger": { diff --git a/test/output.go b/test/output.go index bec12018..4dd7ad40 100644 --- a/test/output.go +++ b/test/output.go @@ -212,16 +212,12 @@ I output.go:] "test" firstKey=1 secondKey=3 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" - // `, - // }, + "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", diff --git a/test/zapr.go b/test/zapr.go index 20b118aa..5612d763 100644 --- a/test/zapr.go +++ b/test/zapr.go @@ -35,6 +35,10 @@ func ZaprOutputMappingDirect() map[string]string { `I output.go:] "helper" akey="avalue" `: `{"caller":"test/output.go:","msg":"helper","v":0,"akey":"avalue"} +`, + + `I output.go:] "test" akey="avalue" akey="avalue2" +`: `{"caller":"test/output.go:","msg":"test","v":0,"akey":"avalue","akey":"avalue2"} `, `I output.go:] "hello/world: test" akey="avalue" diff --git a/textlogger/textlogger.go b/textlogger/textlogger.go index 2c0ec88f..17c7584f 100644 --- a/textlogger/textlogger.go +++ b/textlogger/textlogger.go @@ -132,9 +132,8 @@ func (l *tlogger) print(err error, s severity.Severity, msg string, kvList []int 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]...) + merged := serialize.MergeKVs(l.values, kvList) + serialize.KVListFormat(&b.Buffer, merged...) if b.Len() == 0 || b.Bytes()[b.Len()-1] != '\n' { b.WriteByte('\n') }