diff --git a/CHANGELOG.md b/CHANGELOG.md index 0fcfa9938a6..4d2c0d4d40a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -24,6 +24,12 @@ This project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.htm - Improve performance of concurrent synchronous gauge measurements in `go.opentelemetry.io/otel/sdk/metric`. (#7478) - Improve performance of concurrent exponential histogram measurements in `go.opentelemetry.io/otel/sdk/metric`. (#7702) +### Fixed + +- Fix bad log message when key-value pairs are dropped because of key duplication in `go.opentelemetry.io/otel/sdk/log`. (#7662) +- Fix `DroppedAttributes` on `Record` in `go.opentelemetry.io/otel/sdk/log` to not count the non-attribute key-value pairs dropped because of key duplication. (#7662) +- Fix `SetAttributes` on `Record` in `go.opentelemetry.io/otel/sdk/log` to not log that attributes are dropped when they are actually not dropped. (#7662) + diff --git a/sdk/log/record.go b/sdk/log/record.go index 5b830b7ea8f..83d1812efe2 100644 --- a/sdk/log/record.go +++ b/sdk/log/record.go @@ -27,6 +27,10 @@ var logAttrDropped = sync.OnceFunc(func() { global.Warn("limit reached: dropping log Record attributes") }) +var logKeyValuePairDropped = sync.OnceFunc(func() { + global.Warn("key duplication: dropping key-value pair") +}) + // uniquePool is a pool of unique attributes used for attributes de-duplication. var uniquePool = sync.Pool{ New: func() any { return new([]log.KeyValue) }, @@ -132,13 +136,10 @@ type Record struct { } func (r *Record) addDropped(n int) { - logAttrDropped() r.dropped += n -} - -func (r *Record) setDropped(n int) { - logAttrDropped() - r.dropped = n + if n > 0 { + logAttrDropped() + } } // EventName returns the event name. @@ -233,7 +234,9 @@ func (r *Record) AddAttributes(attrs ...log.KeyValue) { var drop int if !r.allowDupKeys { attrs, drop = dedup(attrs) - r.setDropped(drop) + if drop > 0 { + logKeyValuePairDropped() + } } attrs, drop := head(attrs, r.attributeCountLimit) @@ -266,6 +269,7 @@ func (r *Record) AddAttributes(attrs ...log.KeyValue) { idx, found := uIndex[a.Key] if found { dropped++ + logKeyValuePairDropped() (*unique)[idx] = a continue } @@ -274,6 +278,7 @@ func (r *Record) AddAttributes(attrs ...log.KeyValue) { if found { // New attrs overwrite any existing with the same key. dropped++ + logKeyValuePairDropped() if idx < 0 { r.front[-(idx + 1)] = a } else { @@ -289,7 +294,6 @@ func (r *Record) AddAttributes(attrs ...log.KeyValue) { if dropped > 0 { attrs = make([]log.KeyValue, len(*unique)) copy(attrs, *unique) - r.addDropped(dropped) } } @@ -349,10 +353,12 @@ func (r *Record) addAttrs(attrs []log.KeyValue) { // SetAttributes sets (and overrides) attributes to the log record. func (r *Record) SetAttributes(attrs ...log.KeyValue) { var drop int - r.setDropped(0) + r.dropped = 0 if !r.allowDupKeys { attrs, drop = dedup(attrs) - r.setDropped(drop) + if drop > 0 { + logKeyValuePairDropped() + } } attrs, drop = head(attrs, r.attributeCountLimit) @@ -515,7 +521,9 @@ func (r *Record) applyValueLimitsAndDedup(val log.Value) log.Value { // Deduplicate then truncate. // Do not do at the same time to avoid wasted truncation operations. newKvs, dropped = dedup(kvs) - r.addDropped(dropped) + if dropped > 0 { + logKeyValuePairDropped() + } } else { newKvs = kvs } diff --git a/sdk/log/record_test.go b/sdk/log/record_test.go index 6f363527df0..ec3107c719d 100644 --- a/sdk/log/record_test.go +++ b/sdk/log/record_test.go @@ -553,17 +553,33 @@ func TestRecordDroppedAttributes(t *testing.T) { attrs := make([]log.KeyValue, i) attrs[0] = log.Bool("only key different then the rest", true) - assert.False(t, called, "non-dropped attributed logged") r.AddAttributes(attrs...) - assert.Equalf(t, i-1, r.DroppedAttributes(), "%d: AddAttributes", i) - assert.True(t, called, "dropped attributes not logged") + // Deduplication doesn't count as dropped. + wantDropped := 0 + if i > 1 { + wantDropped = 1 + } + assert.Equalf(t, wantDropped, r.DroppedAttributes(), "%d: AddAttributes", i) + if i <= 1 { + assert.False(t, called, "%d: dropped attributes logged", i) + } else { + assert.True(t, called, "%d: dropped attributes not logged", i) + } r.AddAttributes(attrs...) - assert.Equalf(t, 2*i-1, r.DroppedAttributes(), "%d: second AddAttributes", i) + wantDropped = 0 + if i > 1 { + wantDropped = 2 + } + assert.Equalf(t, wantDropped, r.DroppedAttributes(), "%d: second AddAttributes", i) r.SetAttributes(attrs...) - assert.Equalf(t, i-1, r.DroppedAttributes(), "%d: SetAttributes", i) + wantDropped = 0 + if i > 1 { + wantDropped = 1 + } + assert.Equalf(t, wantDropped, r.DroppedAttributes(), "%d: SetAttributes", i) } } @@ -957,7 +973,7 @@ func TestApplyAttrLimitsDeduplication(t *testing.T) { log.String("g", "GG"), log.String("h", "H"), ), - wantDroppedAttrs: 10, + wantDroppedAttrs: 0, // Deduplication doesn't count as dropped }, { name: "EmptyMap", @@ -987,7 +1003,7 @@ func TestApplyAttrLimitsDeduplication(t *testing.T) { log.MapValue(log.String("key", "value2")), log.StringValue("normal"), ), - wantDroppedAttrs: 1, + wantDroppedAttrs: 0, // Nested deduplication doesn't count as dropped }, { name: "NestedSliceInMap", @@ -1001,7 +1017,7 @@ func TestApplyAttrLimitsDeduplication(t *testing.T) { log.MapValue(log.String("nested", "value2")), ), ), - wantDroppedAttrs: 1, + wantDroppedAttrs: 0, // Nested deduplication doesn't count as dropped }, { name: "DeeplyNestedStructure", @@ -1023,7 +1039,7 @@ func TestApplyAttrLimitsDeduplication(t *testing.T) { ), ), ), - wantDroppedAttrs: 1, + wantDroppedAttrs: 0, // Deeply nested deduplication doesn't count as dropped }, { name: "NestedMapWithoutDuplicateKeys", @@ -1060,6 +1076,96 @@ func TestApplyAttrLimitsDeduplication(t *testing.T) { } } +func TestDeduplicationBehavior(t *testing.T) { + origKeyValueDropped := logKeyValuePairDropped + origAttrDropped := logAttrDropped + t.Cleanup(func() { + logKeyValuePairDropped = origKeyValueDropped + logAttrDropped = origAttrDropped + }) + + testCases := []struct { + name string + attributeCountLimit int + allowDupKeys bool + attrs []log.KeyValue + wantKeyValueDropped bool + wantAttrDropped bool + wantDroppedCount int + wantAttributeCount int + }{ + { + name: "Duplicate keys only", + attrs: []log.KeyValue{log.String("key", "v1"), log.String("key", "v2")}, + wantKeyValueDropped: true, + wantDroppedCount: 0, // Deduplication doesn't count + wantAttributeCount: 1, + }, + { + name: "Limit exceeded only", + attributeCountLimit: 2, + attrs: []log.KeyValue{log.String("a", "v1"), log.String("b", "v2"), log.String("c", "v3")}, + wantAttrDropped: true, + wantDroppedCount: 1, + wantAttributeCount: 2, + }, + { + name: "Both duplicates and limit", + attributeCountLimit: 2, + attrs: []log.KeyValue{ + log.String("a", "v1"), + log.String("a", "v2"), + log.String("b", "v3"), + log.String("c", "v4"), + }, + wantKeyValueDropped: true, + wantAttrDropped: true, + wantDroppedCount: 1, // Only limit drops count + wantAttributeCount: 2, + }, + { + name: "allowDupKeys=true", + allowDupKeys: true, + attrs: []log.KeyValue{log.String("key", "v1"), log.String("key", "v2")}, + wantKeyValueDropped: false, + wantDroppedCount: 0, + wantAttributeCount: 2, + }, + { + name: "Nested map duplicates", + attrs: []log.KeyValue{ + log.Map("outer", log.String("nested", "v1"), log.String("nested", "v2")), + }, + wantKeyValueDropped: true, + wantDroppedCount: 0, + wantAttributeCount: 1, + }, + } + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + keyValueDroppedCalled := false + attrDroppedCalled := false + + logKeyValuePairDropped = sync.OnceFunc(func() { keyValueDroppedCalled = true }) + logAttrDropped = sync.OnceFunc(func() { attrDroppedCalled = true }) + + r := &Record{ + attributeValueLengthLimit: -1, + attributeCountLimit: tc.attributeCountLimit, + allowDupKeys: tc.allowDupKeys, + } + + r.SetAttributes(tc.attrs...) + + assert.Equal(t, tc.wantKeyValueDropped, keyValueDroppedCalled) + assert.Equal(t, tc.wantAttrDropped, attrDroppedCalled) + assert.Equal(t, tc.wantDroppedCount, r.DroppedAttributes()) + assert.Equal(t, tc.wantAttributeCount, r.AttributesLen()) + }) + } +} + func TestApplyAttrLimitsTruncation(t *testing.T) { testcases := []struct { name string