From b8562570a45c505328400477e3e603628edd6a48 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Wed, 20 Nov 2024 16:04:33 +0100 Subject: [PATCH] de-duplicate all key/value pairs MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Previously, de-duplication was limited such that keys passed to a log call as parameters overwrote keys passed earlier to WithValues. Using the same key in different WithValues calls or multiple times in a WithValues call or the parameters led to duplicates in the output. Now all key/value pairs get checked for duplicates. The last one wins and is printed at the place where it was added. A potential improvement would be to keep it at the place where it first appeared if the value is the same because then different log entries are more likely to have it at the beginning of their key/value pairs because it was added by a common WithValues call. Because the new implementation avoids memory allocations, the performance impact is minimal. Some cases even become faster. goos: linux goarch: amd64 pkg: k8s.io/klog/examples/benchmarks cpu: Intel(R) Core(TM) i9-7980XE CPU @ 2.60GHz │ before │ after1 │ │ sec/op │ sec/op vs base │ Output/klog/fail-verbosity-non-standard-struct-key-check/objects/0-36 385.5n ± 9% 358.9n ± 5% -6.91% (p=0.041 n=6) Output/klog/fail-verbosity-non-standard-struct-key-check/objects/10-36 374.3n ± 4% 357.3n ± 5% -4.55% (p=0.015 n=6) Output/klog/fail-verbosity-non-standard-struct-key-check/objects/20-36 388.4n ± 3% 359.2n ± 4% -7.53% (p=0.002 n=6) ... Output/zapr/fail-verbosity-non-standard-int-key-check/objects/90-36 380.9n ± 4% 379.4n ± 2% ~ (p=0.937 n=6) Output/zapr/fail-verbosity-non-standard-int-key-check/objects/100-36 375.1n ± 3% 381.9n ± 4% ~ (p=0.093 n=6) geomean 3.461µ 3.442µ -0.55% pkg: k8s.io/klog/examples/output_test ZaprOutput/regular_error_types_as_value-36 3.270µ ± 10% 3.530µ ± 9% ~ (p=0.132 n=6) ZaprOutput/struct_values-36 3.932µ ± 11% 4.107µ ± 10% ~ (p=1.000 n=6) ZaprOutput/klog.Format-36 4.276µ ± 12% 4.439µ ± 7% ~ (p=0.132 n=6) ZaprOutput/regular_error_types_when_using_logr.Error-36 2.790µ ± 7% 2.834µ ± 15% ~ (p=0.699 n=6) ZaprOutput/map_values-36 5.802µ ± 9% 5.829µ ± 3% ~ (p=1.000 n=6) ZaprOutput/log_with_name_and_values-36 4.051µ ± 4% 3.864µ ± 6% -4.63% (p=0.015 n=6) ... geomean 5.581µ 5.646µ +1.16% pkg: k8s.io/klog/v2 Header-36 1.339µ ± 5% 1.311µ ± 6% ~ (p=0.513 n=6) ... KlogOutput/klog.Format-36 4.207µ ± 10% 4.667µ ± 3% +10.95% (p=0.009 n=6) KlogOutput/cyclic_list-36 151.3µ ± 1% 151.1µ ± 1% ~ (p=0.818 n=6) KlogOutput/override_single_value-36 2.308µ ± 9% 3.501µ ± 15% +51.66% (p=0.002 n=6) KlogOutput/multiple_WithValues-36 10.91µ ± 9% 12.46µ ± 7% +14.16% (p=0.004 n=6) ... KlogOutput/duplicates-36 21.34µ ± 2% 22.52µ ± 7% ~ (p=0.065 n=6) ... geomean 252.6n 260.6n +3.18% pkg: k8s.io/klog/v2/textlogger TextloggerOutput/html_characters-36 1.982µ ± 12% 1.978µ ± 6% ~ (p=0.937 n=6) TextloggerOutput/map_values-36 3.215µ ± 6% 3.429µ ± 4% +6.67% (p=0.041 n=6) ... TextloggerOutput/mixed_duplicates-36 19.33µ ± 5% 19.59µ ± 7% ~ (p=0.818 n=6) ... TextloggerOutput/print_duplicate_keys_in_arguments-36 2.067µ ± 7% 2.388µ ± 6% +15.53% (p=0.002 n=6) ... TextloggerOutput/duplicates-36 16.80µ ± 11% 17.06µ ± 4% ~ (p=0.310 n=6) ... geomean 2.798µ 2.860µ +2.24% --- internal/serialize/keyvalues.go | 183 +++++++++++++++--------- internal/serialize/keyvalues_no_slog.go | 10 +- internal/serialize/keyvalues_slog.go | 12 +- klogr/klogr_test.go | 8 +- ktesting/testinglogger_test.go | 6 +- test/output.go | 33 ++--- test/zapr.go | 36 +++-- 7 files changed, 170 insertions(+), 118 deletions(-) diff --git a/internal/serialize/keyvalues.go b/internal/serialize/keyvalues.go index d1a4751c..313fc9f1 100644 --- a/internal/serialize/keyvalues.go +++ b/internal/serialize/keyvalues.go @@ -71,24 +71,8 @@ func MergeKVs(first, second []interface{}) []interface{} { 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, first...) merged = append(merged, second...) if len(merged)%2 != 0 { merged = append(merged, missingValue) @@ -105,46 +89,7 @@ type AnyToStringFunc func(v interface{}) string // MergeKVsInto is a variant of MergeKVs which directly formats the key/value // pairs into a buffer. func (f Formatter) MergeAndFormatKVs(b *bytes.Buffer, first, second []interface{}) { - if len(first) == 0 && len(second) == 0 { - // Nothing to do at all. - return - } - - if len(first) == 0 && len(second)%2 == 0 { - // Nothing to be overridden, second slice is well-formed - // and can be used directly. - for i := 0; i < len(second); i += 2 { - f.KVFormat(b, second[i], second[i+1]) - } - return - } - - // 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 - } - for i := 0; i < len(first); i += 2 { - key := first[i] - if overrides[key] { - continue - } - f.KVFormat(b, key, first[i+1]) - } - // Round down. - l := len(second) - l = l / 2 * 2 - for i := 1; i < l; i += 2 { - f.KVFormat(b, second[i-1], second[i]) - } - if len(second)%2 == 1 { - f.KVFormat(b, second[len(second)-1], missingValue) - } + f.formatKVs(b, first, second) } func MergeAndFormatKVs(b *bytes.Buffer, first, second []interface{}) { @@ -156,16 +101,7 @@ 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 (f Formatter) 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 - } - f.KVFormat(b, k, v) - } + f.formatKVs(b, keysAndValues) } func KVListFormat(b *bytes.Buffer, keysAndValues ...interface{}) { @@ -176,6 +112,119 @@ func KVFormat(b *bytes.Buffer, k, v interface{}) { Formatter{}.KVFormat(b, k, v) } +// formatKVs formats all key/value pairs such that the output contains no +// duplicates ("last one wins"). +func (f Formatter) formatKVs(b *bytes.Buffer, kvs ...[]interface{}) { + // De-duplication is done by optimistically formatting all key value + // pairs and then cutting out the output of those key/value pairs which + // got overwritten later. + // + // In the common case of no duplicates, the only overhead is tracking + // previous keys. This uses a slice with a simple linear search because + // the number of entries is typically so low that allocating a map or + // keeping a sorted slice with binary search aren't justified. + // + // Using a fixed size here makes the Go compiler use the stack as + // initial backing store for the slice, which is crucial for + // performance. + existing := make([]obsoleteKV, 0, 32) + obsolete := make([]interval, 0, 32) // Sorted by start index. + for _, keysAndValues := range kvs { + 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 + } + var e obsoleteKV + e.start = b.Len() + e.key = f.KVFormat(b, k, v) + e.end = b.Len() + i := findObsoleteEntry(existing, e.key) + if i >= 0 { + // The old entry gets obsoleted. This ensures + // that if the more recent one has a different value, + // that value remains. If the value is the same, + // then we could also keep the old entry. That + // would lead to a more natural order of key/value + // pairs in the output (shared key/value in multiple + // log entries always at the beginning) but at the + // cost of another memory comparison. + obsolete = append(obsolete, existing[i].interval) + existing[i].interval = e.interval + } else { + // Instead of appending at the end and doing a + // linear search in findEntry, we could keep + // the slice sorted by key and do a binary search. + // + // Above: + // i, ok := slices.BinarySearchFunc(existing, e, func(a, b entry) int { return strings.Compare(a.key, b.key) }) + // Here: + // existing = slices.Insert(existing, i, e) + // + // But that adds a dependency on the slices package + // and made performance slightly worse, presumably + // because the cost of shifting entries around + // did not pay of with faster lookups. + existing = append(existing, e) + } + } + } + + // If we need to remove some obsolete key/value pairs then move the memory. + if len(obsolete) > 0 { + // Potentially the next remaining output (might itself be obsolete). + from := obsolete[0].end + // Next obsolete entry. + nextObsolete := 1 + // This is the source buffer, before truncation. + all := b.Bytes() + b.Truncate(obsolete[0].start) + + for nextObsolete < len(obsolete) { + if from == obsolete[nextObsolete].start { + // Skip also the next obsolete key/value. + from = obsolete[nextObsolete].end + nextObsolete++ + continue + } + + // Preserve some output. Write uses copy, which + // explicitly allows source and destination to overlap. + // That could happen here. + valid := all[from:obsolete[nextObsolete].start] + b.Write(valid) + from = obsolete[nextObsolete].end + nextObsolete++ + } + // Copy end of buffer. + valid := all[from:] + b.Write(valid) + } +} + +type obsoleteKV struct { + key string + interval +} + +// interval includes the start and excludes the end. +type interval struct { + start int + end int +} + +func findObsoleteEntry(entries []obsoleteKV, key string) int { + for i, entry := range entries { + if entry.key == key { + return i + } + } + return -1 +} + // formatAny is the fallback formatter for a value. It supports a hook (for // example, for YAML encoding) and itself uses JSON encoding. func (f Formatter) formatAny(b *bytes.Buffer, v interface{}) { diff --git a/internal/serialize/keyvalues_no_slog.go b/internal/serialize/keyvalues_no_slog.go index d9c7d154..b8c7e443 100644 --- a/internal/serialize/keyvalues_no_slog.go +++ b/internal/serialize/keyvalues_no_slog.go @@ -28,7 +28,7 @@ import ( // KVFormat serializes one key/value pair into the provided buffer. // A space gets inserted before the pair. -func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) { +func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) string { // This is the version without slog support. Must be kept in sync with // the version in keyvalues_slog.go. @@ -37,13 +37,15 @@ func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) { // 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. + var key string if sK, ok := k.(string); ok { // Avoid one allocation when the key is a string, which // normally it should be. - b.WriteString(sK) + key = sK } else { - b.WriteString(fmt.Sprintf("%s", k)) + key = fmt.Sprintf("%s", k) } + b.WriteString(key) // The type checks are sorted so that more frequently used ones // come first because that is then faster in the common @@ -94,4 +96,6 @@ func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) { default: f.formatAny(b, v) } + + return key } diff --git a/internal/serialize/keyvalues_slog.go b/internal/serialize/keyvalues_slog.go index 89acf977..8e008436 100644 --- a/internal/serialize/keyvalues_slog.go +++ b/internal/serialize/keyvalues_slog.go @@ -29,8 +29,8 @@ import ( ) // KVFormat serializes one key/value pair into the provided buffer. -// A space gets inserted before the pair. -func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) { +// A space gets inserted before the pair. It returns the key. +func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) string { // This is the version without slog support. Must be kept in sync with // the version in keyvalues_slog.go. @@ -39,13 +39,15 @@ func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) { // 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. + var key string if sK, ok := k.(string); ok { // Avoid one allocation when the key is a string, which // normally it should be. - b.WriteString(sK) + key = sK } else { - b.WriteString(fmt.Sprintf("%s", k)) + key = fmt.Sprintf("%s", k) } + b.WriteString(key) // The type checks are sorted so that more frequently used ones // come first because that is then faster in the common @@ -112,6 +114,8 @@ func (f Formatter) KVFormat(b *bytes.Buffer, k, v interface{}) { default: f.formatAny(b, v) } + + return key } // generateJSON has the same preference for plain strings as KVFormat. diff --git a/klogr/klogr_test.go b/klogr/klogr_test.go index 57ebf7a2..0d61bcea 100644 --- a/klogr/klogr_test.go +++ b/klogr/klogr_test.go @@ -69,22 +69,22 @@ func testOutput(t *testing.T, format string) { expectedKlogOutput: `"test" logger="hello.world" akey="avalue" `, }, - "may print duplicate keys with the same value": { + "de-duplicate keys with the same value": { klogr: createLogger().V(0), text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue"}, expectedOutput: `"msg"="test" "akey"="avalue" `, - expectedKlogOutput: `"test" akey="avalue" akey="avalue" + expectedKlogOutput: `"test" akey="avalue" `, }, - "may print duplicate keys when the values are passed to Info": { + "de-duplicate keys when the values are passed to Info": { klogr: createLogger().V(0), text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue2"}, expectedOutput: `"msg"="test" "akey"="avalue2" `, - expectedKlogOutput: `"test" akey="avalue" akey="avalue2" + expectedKlogOutput: `"test" akey="avalue2" `, }, "should only print the duplicate key that is passed to Info if one was passed to the logger": { diff --git a/ktesting/testinglogger_test.go b/ktesting/testinglogger_test.go index 57c7c2d8..fc22e62b 100644 --- a/ktesting/testinglogger_test.go +++ b/ktesting/testinglogger_test.go @@ -57,13 +57,13 @@ func TestInfo(t *testing.T) { "should not print duplicate keys with the same value": { text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue"}, - expectedOutput: `Ixxx test akey="avalue" akey="avalue" + expectedOutput: `Ixxx test akey="avalue" `, }, - "should only print the last duplicate key when the values are passed to Info": { + "should print no duplicate keys when the values are passed to Info": { text: "test", keysAndValues: []interface{}{"akey", "avalue", "akey", "avalue2"}, - expectedOutput: `Ixxx test akey="avalue" akey="avalue2" + expectedOutput: `Ixxx test 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 95e652b4..748fcc50 100644 --- a/test/output.go +++ b/test/output.go @@ -178,9 +178,9 @@ var tests = map[string]testcase{ }, "override single value": { withValues: []interface{}{"akey", "avalue"}, - text: "test", + text: "test-with-values", values: []interface{}{"akey", "avalue2"}, - expectedOutput: `I output.go:] "test" akey="avalue2" + expectedOutput: `I output.go:] "test-with-values" akey="avalue2" `, }, "override WithValues": { @@ -217,9 +217,9 @@ I output.go:] "test" firstKey=1 secondKey=3 `, }, "print duplicate keys in arguments": { - text: "test", + text: "test-arguments", values: []interface{}{"akey", "avalue", "akey", "avalue2"}, - expectedOutput: `I output.go:] "test" akey="avalue" akey="avalue2" + expectedOutput: `I output.go:] "test-arguments" akey="avalue2" `, }, "preserve order of key/value pairs": { @@ -433,11 +433,10 @@ I output.go:] "test" firstKey=1 secondKey=3 evenMoreValues: []interface{}{"trace", traceIDFromHex("101112131415161718191A1B1C1D1E1F"), "span", spanIDFromHex("2122232425262728")}, text: "duplicates", - // No de-duplication among WithValues calls at the moment! expectedOutput: `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" `, }, "mixed duplicates": { @@ -446,11 +445,10 @@ I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span=" evenMoreValues: []interface{}{"c", 3, "trace", traceIDFromHex("101112131415161718191A1B1C1D1E1F"), "span", spanIDFromHex("2122232425262728"), "d", 4}, text: "duplicates", - // No de-duplication among WithValues calls at the moment! expectedOutput: `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" d=4 +I output.go:] "duplicates" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" d=4 `, }, } @@ -467,6 +465,7 @@ func printWithLogger(logger logr.Logger, test testcase) { logger = logger.WithValues(test.withValues...) // loggers := []logr.Logger{logger} if test.moreValues != nil { + // Intentionally append the logger again: WithValues must not change what it prints. loggers = append(loggers, logger.WithValues(test.moreValues...), logger) // } if test.evenMoreValues != nil { @@ -505,22 +504,12 @@ func initPrintWithKlog(tb testing.TB, test testcase) { func printWithKlog(test testcase) { 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]) - } + kv = append(kv, withValues[i], withValues[i+1]) } } // Here we need to emulate the handling of WithValues above. @@ -597,7 +586,7 @@ func Output(t *testing.T, config OutputConfig) { } expectedWithPlaceholder := expected 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-19)) expected = strings.ReplaceAll(expected, "", fmt.Sprintf("%d", expectedLine-15)) expected = strings.ReplaceAll(expected, "", fmt.Sprintf("%d", expectedLine-12)) if actual != expected { diff --git a/test/zapr.go b/test/zapr.go index be766c72..bc9e03ab 100644 --- a/test/zapr.go +++ b/test/zapr.go @@ -32,8 +32,12 @@ func ZaprOutputMappingDirect() map[string]string { `: `{"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:] "test-arguments" akey="avalue2" +`: `{"caller":"test/output.go:","msg":"test-arguments","v":0,"akey":"avalue","akey":"avalue2"} +`, + + `I output.go:] "test-with-values" akey="avalue2" +`: `{"caller":"test/output.go:","msg":"test-with-values","akey":"avalue","v":0,"akey":"avalue2"} `, `I output.go:] "test" logger="hello.world" akey="avalue" @@ -261,9 +265,9 @@ I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" `, `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" `: `{"caller":"test/output.go:","msg":"duplicates","trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","v":0} {"caller":"test/output.go:","msg":"duplicates","trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","trace":"101112131415161718191a1b1c1d1e1f","span":"1112131415161718","v":0} {"caller":"test/output.go:","msg":"duplicates","trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","v":0} @@ -271,9 +275,9 @@ I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span=" `, `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" d=4 +I output.go:] "duplicates" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" d=4 `: `{"caller":"test/output.go:","msg":"duplicates","trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1,"v":0} {"caller":"test/output.go:","msg":"duplicates","trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1,"b":2,"trace":"101112131415161718191a1b1c1d1e1f","span":"1112131415161718","v":0} {"caller":"test/output.go:","msg":"duplicates","trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1,"v":0} @@ -295,8 +299,6 @@ I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span=" // - Output does that without emitting the warning that we get // from zapr. // - zap drops keys with missing values, here we get "(MISSING)". -// - zap does not de-duplicate key/value pairs, here klog does that -// for it. func ZaprOutputMappingIndirect() map[string]string { mapping := ZaprOutputMappingDirect() @@ -331,12 +333,16 @@ I output.go:] "odd WithValues" keyWithoutValue="(MISSING)" `: `{"caller":"test/output.go:","msg":"test","v":0,"akey9":"avalue9","akey8":"avalue8","akey1":"avalue1","akey5":"avalue5","akey4":"avalue4"} `, - `I output.go:] "test" akey="avalue2" -`: `{"caller":"test/output.go:","msg":"test","v":0,"akey":"avalue2"} + `I output.go:] "test-arguments" akey="avalue2" +`: `{"caller":"test/output.go:","msg":"test-arguments","v":0,"akey":"avalue","akey":"avalue2"} +`, + + `I output.go:] "test-with-values" akey="avalue2" +`: `{"caller":"test/output.go:","msg":"test-with-values","v":0,"akey":"avalue","akey":"avalue2"} `, `I output.go:] "test" X="y" duration="1m0s" A="b" -`: `{"caller":"test/output.go:","msg":"test","v":0,"X":"y","duration":"1m0s","A":"b"} +`: `{"caller":"test/output.go:","msg":"test","v":0,"duration":"1h0m0s","X":"y","duration":"1m0s","A":"b"} `, `I output.go:] "test" firstKey=1 @@ -367,9 +373,9 @@ I output.go:] "test" firstKey=1 secondKey=3 `: ``, `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" +I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" `: `{"caller":"test/output.go:","msg":"duplicates","v":0,"trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708"} {"caller":"test/output.go:","msg":"duplicates","v":0,"trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","trace":"101112131415161718191a1b1c1d1e1f","span":"1112131415161718"} {"caller":"test/output.go:","msg":"duplicates","v":0,"trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708"} @@ -377,9 +383,9 @@ I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span=" `, `I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" +I output.go:] "duplicates" a=1 b=2 trace="101112131415161718191a1b1c1d1e1f" span="1112131415161718" I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 -I output.go:] "duplicates" trace="101112131415161718191a1b1c1d1e1f" span="0102030405060708" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" d=4 +I output.go:] "duplicates" a=1 c=3 trace="101112131415161718191a1b1c1d1e1f" span="2122232425262728" d=4 `: `{"caller":"test/output.go:","msg":"duplicates","v":0,"trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1} {"caller":"test/output.go:","msg":"duplicates","v":0,"trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1,"b":2,"trace":"101112131415161718191a1b1c1d1e1f","span":"1112131415161718"} {"caller":"test/output.go:","msg":"duplicates","v":0,"trace":"101112131415161718191a1b1c1d1e1f","span":"0102030405060708","a":1}