From 3ca855bd973e70acef07fe68ddb2c8abeaa84c46 Mon Sep 17 00:00:00 2001 From: Tyler Yahn Date: Thu, 28 Mar 2024 11:33:57 -0700 Subject: [PATCH] Implement the slog Handler functionality (#5314) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * Implement the Handler functionality * Update bridges/otelslog/handler_test.go * Update bridges/otelslog/handler.go Co-authored-by: Sam Xie * Add kind to unhandled converted type * Document conversion * Apply suggestions from code review Co-authored-by: Robert Pająk --------- Co-authored-by: Sam Xie Co-authored-by: Robert Pająk --- bridges/otelslog/handler.go | 335 ++++++++++++++++++++++++++++++- bridges/otelslog/handler_test.go | 82 +++++++- 2 files changed, 403 insertions(+), 14 deletions(-) diff --git a/bridges/otelslog/handler.go b/bridges/otelslog/handler.go index dbf8e498256..7ba452d0f56 100644 --- a/bridges/otelslog/handler.go +++ b/bridges/otelslog/handler.go @@ -4,12 +4,52 @@ // Package otelslog provides [Handler], an [slog.Handler] implementation, that // can be used to bridge between the [log/slog] API and [OpenTelemetry]. // +// # Record Convesion +// +// The [slog.Record] are converted to OpenTelemetry [log.Record] in the following +// way: +// +// - Time is set as the Timestamp. +// - Message is set as the Body using a [log.StringValue]. +// - Level is transformed and set as the Severity. The SeverityText is not +// set. +// - PC is dropped. +// - Attr are transformed and set as the Attributes. +// +// The Level is transformed by using the static offset to the OpenTelemetry +// Severity types. For example: +// +// - [slog.LevelDebug] is transformed to [log.SeverityDebug] +// - [slog.LevelInfo] is transformed to [log.SeverityInfo] +// - [slog.LevelWarn] is transformed to [log.SeverityWarn] +// - [slog.LevelError] is transformed to [log.SeverityError] +// +// Attribute values are transformed based on their [slog.Kind]: +// +// - [slog.KindAny] are transformed to [log.StringValue]. The value is +// encoded using [fmt.Sprintf]. +// - [slog.KindBool] are transformed to [log.BoolValue] directly. +// - [slog.KindDuration] are transformed to [log.Int64Value] as nanoseconds. +// - [slog.KindFloat64] are transformed to [log.Float64Value] directly. +// - [slog.KindInt64] are transformed to [log.Int64Value] directly. +// - [slog.KindString] are transformed to [log.StringValue] directly. +// - [slog.KindTime] are transformed to [log.Int64Value] as nanoseconds since +// the Unix epoch. +// - [slog.KindUint64] are transformed to [log.Int64Value] using int64 +// conversion. +// - [slog.KindGroup] are transformed to [log.MapValue] using appropriate +// transforms for each group value. +// - [slog.KindLogValuer] the value is resolved and then transformed. +// // [OpenTelemetry]: https://opentelemetry.io/docs/concepts/signals/logs/ package otelslog // import "go.opentelemetry.io/contrib/bridges/otelslog" import ( "context" + "fmt" "log/slog" + "slices" + "sync" "go.opentelemetry.io/otel/log" "go.opentelemetry.io/otel/log/global" @@ -97,11 +137,13 @@ func WithLoggerProvider(provider log.LoggerProvider) Option { } // Handler is an [slog.Handler] that sends all logging records it receives to -// OpenTelemetry. +// OpenTelemetry. See package documentation for how conversions are made. type Handler struct { // Ensure forward compatibility by explicitly making this not comparable. noCmp [0]func() //nolint: unused // This is indeed used. + attrs *kvBuffer + group *group logger log.Logger } @@ -124,10 +166,46 @@ func NewHandler(options ...Option) *Handler { // Handle handles the passed record. func (h *Handler) Handle(ctx context.Context, record slog.Record) error { - // TODO: implement. + h.logger.Emit(ctx, h.convertRecord(record)) return nil } +func (h *Handler) convertRecord(r slog.Record) log.Record { + var record log.Record + record.SetTimestamp(r.Time) + record.SetBody(log.StringValue(r.Message)) + + const sevOffset = slog.Level(log.SeverityDebug) - slog.LevelDebug + record.SetSeverity(log.Severity(r.Level + sevOffset)) + + if h.attrs.Len() > 0 { + record.AddAttributes(h.attrs.KeyValues()...) + } + + n := r.NumAttrs() + if h.group != nil { + if n > 0 { + buf, free := getKVBuffer() + defer free() + r.Attrs(buf.AddAttr) + record.AddAttributes(h.group.KeyValue(buf.KeyValues()...)) + } else { + // A Handler should not output groups if there are no attributes. + g := h.group.NextNonEmpty() + if g != nil { + record.AddAttributes(g.KeyValue()) + } + } + } else if n > 0 { + buf, free := getKVBuffer() + defer free() + r.Attrs(buf.AddAttr) + record.AddAttributes(buf.KeyValues()...) + } + + return record +} + // Enable returns true if the Handler is enabled to log for the provided // context and Level. Otherwise, false is returned if it is not enabled. func (h *Handler) Enabled(ctx context.Context, l slog.Level) bool { @@ -140,13 +218,258 @@ func (h *Handler) Enabled(ctx context.Context, l slog.Level) bool { // WithAttrs returns a new [slog.Handler] based on h that will log using the // passed attrs. func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler { - // TODO: implement. - return h + h2 := *h + if h2.group != nil { + h2.group = h2.group.Clone() + h2.group.AddAttrs(attrs) + } else { + if h2.attrs == nil { + h2.attrs = newKVBuffer(len(attrs)) + } else { + h2.attrs = h2.attrs.Clone() + } + h2.attrs.AddAttrs(attrs) + } + return &h2 } // WithGroup returns a new [slog.Handler] based on h that will log all messages // and attributes within a group of the provided name. func (h *Handler) WithGroup(name string) slog.Handler { - // TODO: implement. - return h + h2 := *h + h2.group = &group{name: name, next: h2.group} + return &h2 +} + +// group represents a group received from slog. +type group struct { + // name is the name of the group. + name string + // attrs are the attributes associated with the group. + attrs *kvBuffer + // next points to the next group that holds this group. + // + // Groups are represented as map value types in OpenTelemetry. This means + // that for an slog group hierarchy like the following ... + // + // WithGroup("G").WithGroup("H").WithGroup("I") + // + // the corresponding OpenTelemetry log value types will have the following + // hierarchy ... + // + // KeyValue{ + // Key: "G", + // Value: []KeyValue{{ + // Key: "H", + // Value: []KeyValue{{ + // Key: "I", + // Value: []KeyValue{}, + // }}, + // }}, + // } + // + // When attributes are recorded (i.e. Info("msg", "key", "value") or + // WithAttrs("key", "value")) they need to be added to the "leaf" group. In + // the above example, that would be group "I": + // + // KeyValue{ + // Key: "G", + // Value: []KeyValue{{ + // Key: "H", + // Value: []KeyValue{{ + // Key: "I", + // Value: []KeyValue{ + // String("key", "value"), + // }, + // }}, + // }}, + // } + // + // Therefore, groups are structured as a linked-list with the "leaf" node + // being the head of the list. Following the above example, the group data + // representation would be ... + // + // *group{"I", next: *group{"H", next: *group{"G"}}} + next *group +} + +// NextNonEmpty returns the next group within g's linked-list that has +// attributes (including g itself). If no group is found, nil is returned. +func (g *group) NextNonEmpty() *group { + if g == nil || g.attrs.Len() > 0 { + return g + } + return g.next.NextNonEmpty() +} + +// KeyValue returns group g containing kvs as a [log.KeyValue]. The value of +// the returned KeyValue will be of type [log.KindMap]. +// +// The passed kvs are rendered in the returned value, but are not added to the +// group. +// +// This does not check g. It is the callers responsibility to ensure g is +// non-empty or kvs is non-empty so as to return a valid group representation +// (according to slog). +func (g *group) KeyValue(kvs ...log.KeyValue) log.KeyValue { + // Assumes checking of group g already performed (i.e. non-empty). + out := log.Map(g.name, g.attrs.KeyValues(kvs...)...) + g = g.next + for g != nil { + // A Handler should not output groups if there are no attributes. + if g.attrs.Len() > 0 { + out = log.Map(g.name, g.attrs.KeyValues(out)...) + } + g = g.next + } + return out +} + +// Clone returns a copy of g. +func (g *group) Clone() *group { + if g == nil { + return g + } + g2 := *g + g2.attrs = g2.attrs.Clone() + return &g2 +} + +// AddAttrs add attrs to g. +func (g *group) AddAttrs(attrs []slog.Attr) { + if g.attrs == nil { + g.attrs = newKVBuffer(len(attrs)) + } + g.attrs.AddAttrs(attrs) +} + +var kvBufferPool = sync.Pool{ + New: func() any { + // Based on slog research (https://go.dev/blog/slog#performance), 95% + // of use-cases will use 5 or less attributes. + return newKVBuffer(5) + }, +} + +func getKVBuffer() (buf *kvBuffer, free func()) { + buf = kvBufferPool.Get().(*kvBuffer) + return buf, func() { + // TODO: limit returned size so the pool doesn't hold on to very large + // buffers. Idea is based on + // https://cs.opensource.google/go/x/exp/+/814bf88c:slog/internal/buffer/buffer.go;l=27-34 + + // Do not modify any previously held data. + buf.data = buf.data[:0:0] + kvBufferPool.Put(buf) + } +} + +type kvBuffer struct { + data []log.KeyValue +} + +func newKVBuffer(n int) *kvBuffer { + return &kvBuffer{data: make([]log.KeyValue, 0, n)} +} + +// Len returns the number of [log.KeyValue] held by b. +func (b *kvBuffer) Len() int { + if b == nil { + return 0 + } + return len(b.data) +} + +// Clone returns a copy of b. +func (b *kvBuffer) Clone() *kvBuffer { + if b == nil { + return nil + } + return &kvBuffer{data: slices.Clone(b.data)} +} + +// KeyValues returns kvs appended to the [log.KeyValue] held by b. +func (b *kvBuffer) KeyValues(kvs ...log.KeyValue) []log.KeyValue { + if b == nil { + return kvs + } + return append(b.data, kvs...) +} + +// AddAttrs adds attrs to b. +func (b *kvBuffer) AddAttrs(attrs []slog.Attr) { + b.data = slices.Grow(b.data, len(attrs)) + for _, a := range attrs { + _ = b.AddAttr(a) + } +} + +// AddAttr adds attr to b and returns true. +// +// This is designed to be passed to the AddAttributes method of an +// [slog.Record]. +// +// If attr is a group with an empty key, its values will be flattened. +// +// If attr is empty, it will be dropped. +func (b *kvBuffer) AddAttr(attr slog.Attr) bool { + if attr.Key == "" { + if attr.Value.Kind() == slog.KindGroup { + // A Handler should inline the Attrs of a group with an empty key. + for _, a := range attr.Value.Group() { + b.data = append(b.data, log.KeyValue{ + Key: a.Key, + Value: convertValue(a.Value), + }) + } + return true + } + + if attr.Value.Any() == nil { + // A Handler should ignore an empty Attr. + return true + } + } + b.data = append(b.data, log.KeyValue{ + Key: attr.Key, + Value: convertValue(attr.Value), + }) + return true +} + +func convertValue(v slog.Value) log.Value { + switch v.Kind() { + case slog.KindAny: + return log.StringValue(fmt.Sprintf("%+v", v.Any())) + case slog.KindBool: + return log.BoolValue(v.Bool()) + case slog.KindDuration: + return log.Int64Value(v.Duration().Nanoseconds()) + case slog.KindFloat64: + return log.Float64Value(v.Float64()) + case slog.KindInt64: + return log.Int64Value(v.Int64()) + case slog.KindString: + return log.StringValue(v.String()) + case slog.KindTime: + return log.Int64Value(v.Time().UnixNano()) + case slog.KindUint64: + return log.Int64Value(int64(v.Uint64())) + case slog.KindGroup: + buf, free := getKVBuffer() + defer free() + buf.AddAttrs(v.Group()) + return log.MapValue(buf.data...) + case slog.KindLogValuer: + return convertValue(v.Resolve()) + default: + // Try to handle this as gracefully as possible. + // + // Don't panic here. The goal here is to have developers find this + // first if a new slog.Kind is added. A test on the new kind will find + // this malformed attribute as well as a panic. However, it is + // preferable to have user's open issue asking why their attributes + // have a "unhandled: " prefix than say that their code is panicking. + return log.StringValue(fmt.Sprintf("unhandled: (%s) %+v", v.Kind(), v.Any())) + } } diff --git a/bridges/otelslog/handler_test.go b/bridges/otelslog/handler_test.go index 0822606648d..2654c4a7842 100644 --- a/bridges/otelslog/handler_test.go +++ b/bridges/otelslog/handler_test.go @@ -7,6 +7,7 @@ import ( "context" "log/slog" "testing" + "testing/slogtest" "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" @@ -30,6 +31,9 @@ type recorder struct { embedded.LoggerProvider embeddedLogger // nolint:unused // Used to embed embedded.Logger. + // Records are the records emitted. + Records []log.Record + // Scope is the Logger scope recorder received when Logger was called. Scope instrumentation.Scope @@ -41,17 +45,12 @@ type recorder struct { func (r *recorder) Logger(name string, opts ...log.LoggerOption) log.Logger { cfg := log.NewLoggerConfig(opts...) - r2 := *r - r2.Scope = instrumentation.Scope{ + r.Scope = instrumentation.Scope{ Name: name, Version: cfg.InstrumentationVersion(), SchemaURL: cfg.SchemaURL(), } - return &r2 -} - -func (r *recorder) Emit(context.Context, log.Record) { - // TODO: implement. + return r } type enablerKey uint @@ -62,6 +61,74 @@ func (r *recorder) Enabled(ctx context.Context, record log.Record) bool { return ctx.Value(enableKey) != nil || record.Severity() >= r.MinSeverity } +func (r *recorder) Emit(_ context.Context, record log.Record) { + r.Records = append(r.Records, record) +} + +func (r *recorder) Results() []map[string]any { + out := make([]map[string]any, len(r.Records)) + for i := range out { + r := r.Records[i] + + m := make(map[string]any) + if tStamp := r.Timestamp(); !tStamp.IsZero() { + m[slog.TimeKey] = tStamp + } + if lvl := r.Severity(); lvl != 0 { + m[slog.LevelKey] = lvl - 9 + } + if body := r.Body(); body.Kind() != log.KindEmpty { + m[slog.MessageKey] = value2Result(body) + } + r.WalkAttributes(func(kv log.KeyValue) bool { + m[kv.Key] = value2Result(kv.Value) + return true + }) + + out[i] = m + } + return out +} + +func value2Result(v log.Value) any { + switch v.Kind() { + case log.KindBool: + return v.AsBool() + case log.KindFloat64: + return v.AsFloat64() + case log.KindInt64: + return v.AsInt64() + case log.KindString: + return v.AsString() + case log.KindBytes: + return v.AsBytes() + case log.KindSlice: + return v.AsSlice() + case log.KindMap: + m := make(map[string]any) + for _, val := range v.AsMap() { + m[val.Key] = value2Result(val.Value) + } + return m + } + return nil +} + +func TestSLogHandler(t *testing.T) { + t.Run("slogtest.TestHandler", func(t *testing.T) { + r := new(recorder) + h := NewHandler(WithLoggerProvider(r)) + + // TODO: use slogtest.Run when Go 1.21 is no longer supported. + err := slogtest.TestHandler(h, r.Results) + if err != nil { + t.Fatal(err) + } + }) + + // TODO: Add multi-logged testing. See #5195. +} + func TestNewHandlerConfiguration(t *testing.T) { t.Run("Default", func(t *testing.T) { r := new(recorder) @@ -100,7 +167,6 @@ func TestHandlerEnabled(t *testing.T) { r.MinSeverity = log.SeverityInfo h := NewHandler(WithLoggerProvider(r)) - h.logger = r.Logger("") // TODO: Remove when #5311 merged. ctx := context.Background() assert.False(t, h.Enabled(ctx, slog.LevelDebug), "level conversion: permissive")