sdk/log: fix "limit reached" logging and Record.DroppedAttributes

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)
+
 <!-- Released section -->
 <!-- Don't change this section unless doing release -->
 

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
 		}

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