diff --git a/CHANGELOG.md b/CHANGELOG.md index 81f36f642d6..e282bfb7055 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -13,6 +13,7 @@ This project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.htm - Add `go.opentelemetry.io/otel/semconv/v1.40.0` package. The package contains semantic conventions from the `v1.40.0` version of the OpenTelemetry Semantic Conventions. See the [migration documentation](./semconv/v1.40.0/MIGRATION.md) for information on how to upgrade from `go.opentelemetry.io/otel/semconv/v1.39.0`. (#7985) +- Add `Err` and `SetErr` on `Record` in `go.opentelemetry.io/otel/log` to attach an error and set record exception attributes in `go.opentelemetry.io/otel/log/sdk`. (#7924) ### Changed diff --git a/log/record.go b/log/record.go index adde7a0dc6f..cf62deb9ef2 100644 --- a/log/record.go +++ b/log/record.go @@ -26,6 +26,7 @@ type Record struct { severity Severity severityText string body Value + err error // The fields below are for optimizing the implementation of Attributes and // AddAttributes. This design is borrowed from the slog Record type: @@ -110,6 +111,16 @@ func (r *Record) SetBody(v Value) { r.body = v } +// Err returns the associated error if one has been set. +func (r *Record) Err() error { + return r.err +} + +// SetErr sets the associated error. Passing nil clears the error. +func (r *Record) SetErr(err error) { + r.err = err +} + // WalkAttributes walks all attributes the log record holds by calling f for // each on each [KeyValue] in the [Record]. Iteration stops if f returns false. func (r *Record) WalkAttributes(f func(KeyValue) bool) { diff --git a/log/record_test.go b/log/record_test.go index 7e44bbfc074..f23983e0881 100644 --- a/log/record_test.go +++ b/log/record_test.go @@ -221,3 +221,39 @@ func TestRecordClone(t *testing.T) { assert.Contains(t, r1Attrs, attr0) assert.Contains(t, r1Attrs, attr1) } + +func TestRecordErr(t *testing.T) { + tests := []struct { + name string + fn func(*log.Record) + want error + }{ + { + name: "zero value", + }, + { + name: "set error", + fn: func(r *log.Record) { + r.SetErr(assert.AnError) + }, + want: assert.AnError, + }, + { + name: "clear error", + fn: func(r *log.Record) { + r.SetErr(assert.AnError) + r.SetErr(nil) + }, + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + var r log.Record + if tt.fn != nil { + tt.fn(&r) + } + assert.Equal(t, tt.want, r.Err()) + }) + } +} diff --git a/sdk/log/logger.go b/sdk/log/logger.go index f43a867c8d5..7efb96240d3 100644 --- a/sdk/log/logger.go +++ b/sdk/log/logger.go @@ -5,17 +5,25 @@ package log // import "go.opentelemetry.io/otel/sdk/log" import ( "context" + "reflect" "time" "go.opentelemetry.io/otel" "go.opentelemetry.io/otel/log" "go.opentelemetry.io/otel/log/embedded" "go.opentelemetry.io/otel/sdk/instrumentation" + semconv "go.opentelemetry.io/otel/semconv/v1.40.0" "go.opentelemetry.io/otel/trace" ) var now = time.Now +const ( + exceptionTypeKey = string(semconv.ExceptionTypeKey) + exceptionMessageKey = string(semconv.ExceptionMessageKey) + exceptionStacktraceKey = string(semconv.ExceptionStacktraceKey) +) + // Compile-time check logger implements log.Logger. var _ log.Logger = (*logger)(nil) @@ -108,10 +116,70 @@ func (l *logger) newRecord(ctx context.Context, r log.Record) Record { newRecord.observedTimestamp = now() } + hasExceptionAttr := false r.WalkAttributes(func(kv log.KeyValue) bool { + switch kv.Key { + case exceptionTypeKey, exceptionMessageKey, exceptionStacktraceKey: + hasExceptionAttr = true + } newRecord.AddAttributes(kv) return true }) + if err := r.Err(); err != nil && !hasExceptionAttr { + addExceptionAttrs(&newRecord, err) + } + return newRecord } + +func addExceptionAttrs(r *Record, err error) { + var attrs [2]log.KeyValue + n := 0 + if msg := err.Error(); msg != "" { + if r.attributeCountLimit > 0 && r.attributeCountLimit-r.AttributesLen() < n+1 { + goto flush + } + attrs[n] = log.String(exceptionMessageKey, msg) + n++ + } + if errType := errorType(err); errType != "" { + if r.attributeCountLimit > 0 && r.attributeCountLimit-r.AttributesLen() < n+1 { + goto flush + } + attrs[n] = log.String(exceptionTypeKey, errType) + n++ + } + +flush: + if n > 0 { + r.addAttrs(attrs[:n]) + } +} + +func errorType(err error) string { + if et, ok := err.(interface{ ErrorType() string }); ok { + if s := et.ErrorType(); s != "" { + return s + } + } + + t := reflect.TypeOf(err) + if t == nil { + return "" + } + + pkg, name := t.PkgPath(), t.Name() + if pkg != "" && name != "" { + return pkg + "." + name + } + + // The type has no package path or name (predeclared, not-defined, + // or alias for a not-defined type). + // + // The type has no package path or name (predeclared, not-defined, + // or alias for a not-defined type). + // + // This is not guaranteed to be unique, but is a best effort. + return t.String() +} diff --git a/sdk/log/logger_bench_test.go b/sdk/log/logger_bench_test.go index 215755be384..78533e5cb8e 100644 --- a/sdk/log/logger_bench_test.go +++ b/sdk/log/logger_bench_test.go @@ -4,6 +4,7 @@ package log // import "go.opentelemetry.io/otel/sdk/log" import ( + "errors" "testing" "time" @@ -14,6 +15,7 @@ import ( "go.opentelemetry.io/otel/sdk/instrumentation" "go.opentelemetry.io/otel/sdk/metric" "go.opentelemetry.io/otel/sdk/metric/metricdata" + semconv "go.opentelemetry.io/otel/semconv/v1.39.0" ) func BenchmarkLoggerEmit(b *testing.B) { @@ -119,6 +121,33 @@ func BenchmarkLoggerEnabled(b *testing.B) { _ = enabled } +func BenchmarkLoggerSetErrAndEmit(b *testing.B) { + logger := newTestLogger(b) + err := errors.New("boom") + + b.ReportAllocs() + b.ResetTimer() + for b.Loop() { + r := log.Record{} + r.SetErr(err) + logger.Emit(b.Context(), r) + } +} + +func BenchmarkLoggerSetExceptionAttributesAndEmit(b *testing.B) { + logger := newTestLogger(b) + err := errors.New("boom") + + b.ReportAllocs() + b.ResetTimer() + for b.Loop() { + r := log.Record{} + r.AddAttributes(log.String(string(semconv.ExceptionMessageKey), err.Error())) + r.AddAttributes(log.String(string(semconv.ExceptionTypeKey), errorType(err))) + logger.Emit(b.Context(), r) + } +} + func newTestLogger(t testing.TB) log.Logger { provider := NewLoggerProvider( WithProcessor(newFltrProcessor("0", false)), diff --git a/sdk/log/logger_test.go b/sdk/log/logger_test.go index 80fa6575066..99eb3815527 100644 --- a/sdk/log/logger_test.go +++ b/sdk/log/logger_test.go @@ -314,6 +314,163 @@ func TestLoggerEmit(t *testing.T) { } } +func TestNewRecordAddsExceptionAttrs(t *testing.T) { + l := newLogger(NewLoggerProvider(), instrumentation.Scope{}) + + t.Run("AddsMissing", func(t *testing.T) { + var in log.Record + in.SetBody(log.StringValue("boom")) + in.SetSeverity(log.SeverityError) + in.SetErr(errors.New("boom")) + got := l.newRecord(t.Context(), in) + + var gotAttrs []log.KeyValue + got.WalkAttributes(func(kv log.KeyValue) bool { + gotAttrs = append(gotAttrs, kv) + return true + }) + + assert.Len(t, gotAttrs, 2) + assert.Contains(t, gotAttrs, log.String(string(semconv.ExceptionTypeKey), "*errors.errorString")) + assert.Contains(t, gotAttrs, log.String(string(semconv.ExceptionMessageKey), "boom")) + }) + + t.Run("ShortCircuitsAtAttributeLimit", func(t *testing.T) { + var in log.Record + in.SetBody(log.StringValue("boom")) + in.SetSeverity(log.SeverityError) + in.SetErr(errors.New("boom")) + in.AddAttributes(log.String("k1", "v1")) + + lLimited := newLogger(NewLoggerProvider(WithAttributeCountLimit(2)), instrumentation.Scope{}) + got := lLimited.newRecord(t.Context(), in) + + var gotType, gotMessage string + got.WalkAttributes(func(kv log.KeyValue) bool { + switch kv.Key { + case string(semconv.ExceptionTypeKey): + gotType = kv.Value.AsString() + case string(semconv.ExceptionMessageKey): + gotMessage = kv.Value.AsString() + } + return true + }) + + assert.Empty(t, gotType) + assert.Equal(t, "boom", gotMessage) + }) + + t.Run("NoSlotsLeft", func(t *testing.T) { + var in log.Record + in.SetBody(log.StringValue("boom")) + in.SetSeverity(log.SeverityError) + in.SetErr(errors.New("boom")) + in.AddAttributes(log.String("k1", "v1")) + lLimited := newLogger(NewLoggerProvider(WithAttributeCountLimit(1)), instrumentation.Scope{}) + got := lLimited.newRecord(t.Context(), in) + + var gotType, gotMessage string + got.WalkAttributes(func(kv log.KeyValue) bool { + switch kv.Key { + case string(semconv.ExceptionTypeKey): + gotType = kv.Value.AsString() + case string(semconv.ExceptionMessageKey): + gotMessage = kv.Value.AsString() + } + return true + }) + + assert.Empty(t, gotType) + assert.Empty(t, gotMessage) + }) +} + +func TestErrorType(t *testing.T) { + t.Run("UsesErrorTypeMethod", func(t *testing.T) { + err := errWithType{msg: "boom", typ: "custom.type"} + assert.Equal(t, "custom.type", errorType(err)) + }) + + t.Run("FallsBackWhenErrorTypeEmpty", func(t *testing.T) { + err := errWithType{msg: "boom", typ: ""} + assert.Equal(t, "go.opentelemetry.io/otel/sdk/log.errWithType", errorType(err)) + }) + + t.Run("NilError", func(t *testing.T) { + assert.Empty(t, errorType(nil)) + }) + + t.Run("UnnamedType", func(t *testing.T) { + var err error = struct{ baseErr }{} + assert.Contains(t, errorType(err), "struct") + }) +} + +type errWithType struct { + msg string + typ string +} + +func (e errWithType) Error() string { return e.msg } + +func (e errWithType) ErrorType() string { return e.typ } + +type baseErr struct{} + +func (baseErr) Error() string { return "boom" } + +func TestNewRecordSkipsExceptionWhenPresent(t *testing.T) { + l := newLogger(NewLoggerProvider(), instrumentation.Scope{}) + + t.Run("ExistingMessage", func(t *testing.T) { + var r log.Record + r.SetBody(log.StringValue("boom")) + r.SetSeverity(log.SeverityError) + r.SetErr(errors.New("boom")) + r.AddAttributes(log.String(string(semconv.ExceptionMessageKey), "existing.message")) + + got := l.newRecord(t.Context(), r) + + var gotType, gotMessage string + got.WalkAttributes(func(kv log.KeyValue) bool { + switch kv.Key { + case string(semconv.ExceptionTypeKey): + gotType = kv.Value.AsString() + case string(semconv.ExceptionMessageKey): + gotMessage = kv.Value.AsString() + } + return true + }) + + assert.Equal(t, "existing.message", gotMessage) + assert.Empty(t, gotType) + }) + + t.Run("ExistingType", func(t *testing.T) { + var r log.Record + r.SetBody(log.StringValue("boom")) + r.SetSeverity(log.SeverityError) + r.SetErr(errors.New("boom")) + r.AddAttributes(log.String(string(semconv.ExceptionTypeKey), "existing.type")) + + got := l.newRecord(t.Context(), r) + + var gotType, gotMessage string + got.WalkAttributes(func(kv log.KeyValue) bool { + switch kv.Key { + case string(semconv.ExceptionTypeKey): + gotType = kv.Value.AsString() + case string(semconv.ExceptionMessageKey): + gotMessage = kv.Value.AsString() + } + return true + }) + + assert.Equal(t, "existing.type", gotType) + assert.Empty(t, gotMessage) + }) +} + func TestLoggerEnabled(t *testing.T) { p0 := newFltrProcessor("0", true) p1 := newFltrProcessor("1", true)