From b6dcbaa10d074d74e42cafbaf1048683d887ab97 Mon Sep 17 00:00:00 2001 From: Tyler Yahn Date: Fri, 17 May 2024 12:06:17 -0700 Subject: [PATCH 1/3] Log when log Record attr is dropped --- sdk/log/record.go | 37 +++++++++++++++++++++++++++---------- sdk/log/record_test.go | 9 +++++++++ 2 files changed, 36 insertions(+), 10 deletions(-) diff --git a/sdk/log/record.go b/sdk/log/record.go index 2cdac6e75f2..85c4233c514 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 bellow. - 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) From e8772407bcd58a8bc9bf0cda0f2411aa6c09df7a Mon Sep 17 00:00:00 2001 From: Tyler Yahn Date: Fri, 17 May 2024 12:13:11 -0700 Subject: [PATCH 2/3] Add changelog entry --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index d6925232f0d..bbb563a64f6 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -38,6 +38,7 @@ This project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.htm - Comparison of unordered maps in `go.opentelemetry.io/otel/log.KeyValue` and `go.opentelemetry.io/otel/log.Value`. (#5306) - Fix wrong package name of the error message when parsing endpoint URL in `go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp`. (#5371) - Split the behavior of `Recorder` in `go.opentelemetry.io/otel/log/logtest` so it behaves as a `LoggerProvider` only. (#5365) +- Log a warning to the global OTel logger when a `Record` in `go.opentelemetry.io/otel/sdk/log` drops an attribute due to a limit being reached. (#5376) ## [1.26.0/0.48.0/0.2.0-alpha] 2024-04-24 From aefa934b2ade580e4d6b83f86e85a151f85f6fd0 Mon Sep 17 00:00:00 2001 From: Tyler Yahn Date: Thu, 23 May 2024 07:36:33 -0700 Subject: [PATCH 3/3] Update CHANGELOG.md MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Robert Pająk --- CHANGELOG.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 018bc1b60a4..b3cb72b45a4 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,7 +10,7 @@ This project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.htm ### Fixed -- Log a warning to the global OTel logger when a `Record` in `go.opentelemetry.io/otel/sdk/log` drops an attribute due to a limit being reached. (#5376) +- 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