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}