From be1b9cfc3774d6fe73b1965a4ee1d52139489e39 Mon Sep 17 00:00:00 2001 From: Tyler Yahn Date: Tue, 28 May 2024 11:12:53 -0700 Subject: [PATCH] Log a warning when log Record attribute is dropped (#5376) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 --- CHANGELOG.md | 4 ++++ sdk/log/record.go | 37 +++++++++++++++++++++++++++---------- sdk/log/record_test.go | 9 +++++++++ 3 files changed, 40 insertions(+), 10 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 22907f311bc..34bc4eda8dc 100644 --- a/CHANGELOG.md +++ b/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 diff --git a/sdk/log/record.go b/sdk/log/record.go index 36d84d0b06e..9f8c63d2cd3 100644 --- a/sdk/log/record.go +++ b/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,7 +200,7 @@ 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 } @@ -192,7 +208,7 @@ func (r *Record) AddAttributes(attrs ...log.KeyValue) { 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]) } diff --git a/sdk/log/record_test.go b/sdk/log/record_test.go index ccdcb98fa57..f76634496dc 100644 --- a/sdk/log/record_test.go +++ b/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)