Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Implement the slog Handler functionality #5314

Merged
merged 11 commits into from
Mar 28, 2024
335 changes: 329 additions & 6 deletions bridges/otelslog/handler.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 will be
MrAlias marked this conversation as resolved.
Show resolved Hide resolved
// encoded used [fmt.Sprintf].
MrAlias marked this conversation as resolved.
Show resolved Hide resolved
// - [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"
Expand Down Expand Up @@ -97,11 +137,13 @@
}

// 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
}

Expand All @@ -124,10 +166,46 @@

// 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)
XSAM marked this conversation as resolved.
Show resolved Hide resolved
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 {
Expand All @@ -140,13 +218,258 @@
// 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()

Check warning on line 229 in bridges/otelslog/handler.go

View check run for this annotation

Codecov / codecov/patch

bridges/otelslog/handler.go#L229

Added line #L229 was not covered by tests
}
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

Check warning on line 331 in bridges/otelslog/handler.go

View check run for this annotation

Codecov / codecov/patch

bridges/otelslog/handler.go#L331

Added line #L331 was not covered by tests
}
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)
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I used 5 for the array inside a Record because there was a tradeoff: using too much space would hurt performance. There's no similar tradeoff here, so you could make this a bit larger. Maybe 10?

},
}

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
pellared marked this conversation as resolved.
Show resolved Hide resolved

// 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)}

Check warning on line 388 in bridges/otelslog/handler.go

View check run for this annotation

Codecov / codecov/patch

bridges/otelslog/handler.go#L388

Added line #L388 was not covered by tests
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You lose any extra capacity when you clone b.data, so the subsequent AddAttrs will always allocate. (I think.)

In general though, it's probably best not to worry too much about these details. You can always tweak the performance later.

}

// 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 {
MrAlias marked this conversation as resolved.
Show resolved Hide resolved
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())

Check warning on line 451 in bridges/otelslog/handler.go

View check run for this annotation

Codecov / codecov/patch

bridges/otelslog/handler.go#L442-L451

Added lines #L442 - L451 were not covered by tests
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()))

Check warning on line 457 in bridges/otelslog/handler.go

View check run for this annotation

Codecov / codecov/patch

bridges/otelslog/handler.go#L454-L457

Added lines #L454 - L457 were not covered by tests
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:

Check warning on line 465 in bridges/otelslog/handler.go

View check run for this annotation

Codecov / codecov/patch

bridges/otelslog/handler.go#L465

Added line #L465 was not covered by tests
// 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()))

Check warning on line 473 in bridges/otelslog/handler.go

View check run for this annotation

Codecov / codecov/patch

bridges/otelslog/handler.go#L473

Added line #L473 was not covered by tests
}
}
Loading