Log a warning when log Record attribute is dropped (#5376)

Fix #5317 

According to the
[specification](https://github.com/open-telemetry/opentelemetry-specification/blob/main/specification/logs/sdk.md#logrecord-limits),
there should be a message printed in the SDK's log to indicate to the
user that an attribute was discarded due to such a limit. To prevent
excessive logging, the message must be printed at most once per
`LogRecord` (i.e., not per discarded attribute).

This change centralizes the `Record` dropped field writes and calls a
global logging function. This will at most log once per any `Record`
dropping attributes, meeting the specification requirement.

This does not log once per `Record` when an attribute is dropped. To do
that we would need to maintain state within the `Record` (i.e.
`sync.Mutex` or `sync.Once`). These types cannot be copied, meaning the
`Record` would take on this "no copy" requirement. This seems too
restrictive and with the permissive specification allowing a single log
line, that is the solution added.

---------

Co-authored-by: Robert Pająk <[email protected]>

CHANGELOG.md

@@ -8,6 +8,10 @@ This project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.htm
 
 ## [Unreleased]
 
+### Fixed
+
+- Log a warning to the OpenTelemetry internal logger when a `Record` in `go.opentelemetry.io/otel/sdk/log` drops an attribute due to a limit being reached. (#5376)
+
 ## [1.27.0/0.49.0/0.3.0] 2024-05-21
 
 ### Added

sdk/log/record.go

@@ -10,6 +10,7 @@ import (
 	"time"
 	"unicode/utf8"
 
+	"go.opentelemetry.io/otel/internal/global"
 	"go.opentelemetry.io/otel/log"
 	"go.opentelemetry.io/otel/sdk/instrumentation"
 	"go.opentelemetry.io/otel/sdk/resource"
@@ -22,6 +23,10 @@ import (
 // cover 95% of all use-cases (https://go.dev/blog/slog#performance).
 const attributesInlineCount = 5
 
+var logAttrDropped = sync.OnceFunc(func() {
+	global.Warn("limit reached: dropping log Record attributes")
+})
+
 // indexPool is a pool of index maps used for de-duplication.
 var indexPool = sync.Pool{
 	New: func() any { return make(map[string]int) },
@@ -83,6 +88,16 @@ type Record struct {
 	attributeCountLimit       int
 }
 
+func (r *Record) addDropped(n int) {
+	logAttrDropped()
+	r.dropped += n
+}
+
+func (r *Record) setDropped(n int) {
+	logAttrDropped()
+	r.dropped = n
+}
+
 // Timestamp returns the time when the log record occurred.
 func (r *Record) Timestamp() time.Time {
 	return r.timestamp
@@ -155,11 +170,12 @@ func (r *Record) AddAttributes(attrs ...log.KeyValue) {
 	n := r.AttributesLen()
 	if n == 0 {
 		// Avoid the more complex duplicate map lookups below.
-		attrs, r.dropped = dedup(attrs)
-
 		var drop int
+		attrs, drop = dedup(attrs)
+		r.setDropped(drop)
+
 		attrs, drop = head(attrs, r.attributeCountLimit)
-		r.dropped += drop
+		r.addDropped(drop)
 
 		r.addAttrs(attrs)
 		return
@@ -184,15 +200,15 @@ func (r *Record) AddAttributes(attrs ...log.KeyValue) {
 		// Last-value-wins for any duplicates in attrs.
 		idx, found := uIndex[a.Key]
 		if found {
-			r.dropped++
+			r.addDropped(1)
 			unique[idx] = a
 			continue
 		}
 
 		idx, found = rIndex[a.Key]
 		if found {
 			// New attrs overwrite any existing with the same key.
-			r.dropped++
+			r.addDropped(1)
 			if idx < 0 {
 				r.front[-(idx + 1)] = a
 			} else {
@@ -212,7 +228,7 @@ func (r *Record) AddAttributes(attrs ...log.KeyValue) {
 		// Do not use head(attrs, r.attributeCountLimit - n) here. If
 		// (r.attributeCountLimit - n) <= 0 attrs needs to be emptied.
 		last := max(0, (r.attributeCountLimit - n))
-		r.dropped += len(attrs) - last
+		r.addDropped(len(attrs) - last)
 		attrs = attrs[:last]
 	}
 
@@ -261,11 +277,12 @@ func (r *Record) addAttrs(attrs []log.KeyValue) {
 func (r *Record) SetAttributes(attrs ...log.KeyValue) {
 	// TODO: apply truncation to string and []string values.
 	// TODO: deduplicate map values.
-	attrs, r.dropped = dedup(attrs)
-
 	var drop int
+	attrs, drop = dedup(attrs)
+	r.setDropped(drop)
+
 	attrs, drop = head(attrs, r.attributeCountLimit)
-	r.dropped += drop
+	r.addDropped(drop)
 
 	r.nFront = 0
 	var i int
@@ -396,7 +413,7 @@ func (r Record) applyValueLimits(val log.Value) log.Value {
 		// Deduplicate then truncate. Do not do at the same time to avoid
 		// wasted truncation operations.
 		kvs, dropped := dedup(val.AsMap())
-		r.dropped += dropped
+		r.addDropped(dropped)
 		for i := range kvs {
 			kvs[i] = r.applyAttrLimits(kvs[i])
 		}

sdk/log/record_test.go

@@ -196,14 +196,23 @@ func TestRecordClone(t *testing.T) {
 }
 
 func TestRecordDroppedAttributes(t *testing.T) {
+	orig := logAttrDropped
+	t.Cleanup(func() { logAttrDropped = orig })
+
 	for i := 1; i < attributesInlineCount*5; i++ {
+		var called bool
+		logAttrDropped = func() { called = true }
+
 		r := new(Record)
 		r.attributeCountLimit = 1
 
 		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")
 
 		r.AddAttributes(attrs...)
 		assert.Equalf(t, 2*i-1, r.DroppedAttributes(), "%d: second AddAttributes", i)