diff --git a/internal/kslog/otel_slog.go b/internal/kslog/otel_slog.go deleted file mode 100644 index 353b0d1..0000000 --- a/internal/kslog/otel_slog.go +++ /dev/null @@ -1,173 +0,0 @@ -package kslog - -import ( - "context" - "fmt" - "log/slog" - "time" - - "go.opentelemetry.io/otel/attribute" - "go.opentelemetry.io/otel/baggage" - "go.opentelemetry.io/otel/codes" - "go.opentelemetry.io/otel/trace" -) - -// otelHandler is an implementation of slog's Handler interface. -// Its role is to ensure correlation between logs and OTel spans -// by: -// -// 1. Adding otel span and trace IDs to the log record. -// 2. Adding otel context baggage members to the log record. -// 3. Setting slog record as otel span event. -// 4. Adding slog record attributes to the otel span event. -// 5. Setting span status based on slog record level (only if >= slog.LevelError). -type otelHandler struct { - // Next represents the next handler in the chain. - Next slog.Handler - // NoBaggage determines whether to add context baggage members to the log record. - NoBaggage bool -} - -// NewOtelHandler creates and returns a new OtelHandler to use with log/slog. -func NewOtelHandler(next slog.Handler) slog.Handler { - return &otelHandler{ - Next: next, - } -} - -// Handle handles the provided log record and adds correlation between a slog record and an Open-Telemetry span. -func (h otelHandler) Handle(ctx context.Context, record slog.Record) error { - if ctx == nil { - return h.Next.Handle(ctx, record) - } - - span := trace.SpanFromContext(ctx) - if span == nil || !span.IsRecording() { - return h.Next.Handle(ctx, record) - } - - if !h.NoBaggage { - // Adding context baggage members to log record. - b := baggage.FromContext(ctx) - for _, m := range b.Members() { - record.AddAttrs(slog.String(m.Key(), m.Value())) - } - } - - // Adding log info to span event. - eventAttrs := make([]attribute.KeyValue, 0) - eventAttrs = append(eventAttrs, attribute.String("msg", record.Message)) - eventAttrs = append(eventAttrs, attribute.String("level", record.Level.String())) - eventAttrs = append(eventAttrs, attribute.String("time", record.Time.Format(time.RFC3339Nano))) - - record.Attrs(func(attr slog.Attr) bool { - otelAttr := h.slogAttrToOtelAttr(attr) - if otelAttr.Valid() { - eventAttrs = append(eventAttrs, otelAttr) - } - - return true - }) - - span.AddEvent("log_record", trace.WithAttributes(eventAttrs...)) - - // // Adding span info to log record. - // spanContext := span.SpanContext() - // if spanContext.HasTraceID() { - // traceID := spanContext.TraceID().String() - // record.AddAttrs(slog.String("trace_id", traceID)) - // } - - // if spanContext.HasSpanID() { - // spanID := spanContext.SpanID().String() - // record.AddAttrs(slog.String("span_id", spanID)) - // } - - // Setting span status if the log is an error. - // Purposely leaving as codes.Unset (default) otherwise. - if record.Level >= slog.LevelError { - span.SetStatus(codes.Error, record.Message) - } - - return h.Next.Handle(ctx, record) -} - -// WithAttrs returns a new Otel whose attributes consists of handler's attributes followed by attrs. -func (h otelHandler) WithAttrs(attrs []slog.Attr) slog.Handler { - return otelHandler{ - Next: h.Next.WithAttrs(attrs), - } -} - -// WithGroup returns a new Otel with a group, provided the group's name. -func (h otelHandler) WithGroup(name string) slog.Handler { - return otelHandler{ - Next: h.Next.WithGroup(name), - } -} - -// Enabled reports whether the logger emits log records at the given context and level. -// Note: We handover the decision down to the next handler. -func (h otelHandler) Enabled(ctx context.Context, level slog.Level) bool { - return h.Next.Enabled(ctx, level) -} - -// slogAttrToOtelAttr converts a slog attribute to an OTel one. -// Note: returns an empty attribute if the provided slog attribute is empty. -func (h otelHandler) slogAttrToOtelAttr(attr slog.Attr, groupKeys ...string) attribute.KeyValue { - attr.Value = attr.Value.Resolve() - if attr.Equal(slog.Attr{}) { - return attribute.KeyValue{} - } - - key := func(k string, prefixes ...string) string { - for _, prefix := range prefixes { - k = fmt.Sprintf("%s.%s", prefix, k) - } - - return k - }(attr.Key, groupKeys...) - - value := attr.Value.Resolve() - - switch attr.Value.Kind() { - case slog.KindAny: - return attribute.String(key, fmt.Sprintf("%+v", value.Any())) - case slog.KindBool: - return attribute.Bool(key, value.Bool()) - case slog.KindFloat64: - return attribute.Float64(key, value.Float64()) - case slog.KindInt64: - return attribute.Int64(key, value.Int64()) - case slog.KindString: - return attribute.String(key, value.String()) - case slog.KindTime: - return attribute.String(key, value.Time().Format(time.RFC3339Nano)) - case slog.KindGroup: - groupAttrs := value.Group() - if len(groupAttrs) == 0 { - return attribute.KeyValue{} - } - - for _, groupAttr := range groupAttrs { - return h.slogAttrToOtelAttr(groupAttr, append(groupKeys, key)...) - } - default: - return attribute.KeyValue{} - } - - return attribute.KeyValue{} -} - -// LogWithContext returns a logger with trace information. -func LogWithContext(ctx context.Context, logger *slog.Logger) *slog.Logger { - s := trace.SpanContextFromContext(ctx) - if s.HasTraceID() { - logger = logger.With(slog.String("trace_id", s.TraceID().String())) - } - if s.HasSpanID() { - logger = logger.With(slog.String("span_id", s.SpanID().String())) - } - - return logger -} diff --git a/internal/kslog/otel_slog_otel_test.go b/internal/kslog/otel_slog_otel_test.go deleted file mode 100644 index 4f7592c..0000000 --- a/internal/kslog/otel_slog_otel_test.go +++ /dev/null @@ -1,277 +0,0 @@ -package kslog - -import ( - "bytes" - "context" - "encoding/json" - "fmt" - "log/slog" - "strings" - "testing" - "time" - - "go.opentelemetry.io/otel/attribute" - "go.opentelemetry.io/otel/baggage" - "go.opentelemetry.io/otel/codes" - sdktrace "go.opentelemetry.io/otel/sdk/trace" - "go.opentelemetry.io/otel/sdk/trace/tracetest" - "go.opentelemetry.io/otel/trace" -) - -func TestOtelHandler(t *testing.T) { - const testOperationName = "operation-name" - - setupTracer := func() (*tracetest.SpanRecorder, trace.Tracer) { - spanRecorder := tracetest.NewSpanRecorder() - traceProvider := sdktrace.NewTracerProvider(sdktrace.WithSpanProcessor(spanRecorder)) - tracer := traceProvider.Tracer("test-tracer") - - return spanRecorder, tracer - } - - setupLogger := func() *bytes.Buffer { - var buffer bytes.Buffer - - slog.SetDefault(slog.New(NewOtelHandler(slog.NewJSONHandler(&buffer, nil)))) - - return &buffer - } - - t.Run("simple call", func(t *testing.T) { - buffer := setupLogger() - - slog.With("attr", 1).Info("logAttrs") - slog.Default().WithGroup("group").Info("group", slog.String("a", "b")) - - fmt.Println(buffer.String()) - }) - - t.Run("without span", func(t *testing.T) { - buffer := setupLogger() - - want := map[string]string{ - "level": "INFO", - "msg": "without span", - "a_key": "a_value", - } - - func() { - slog.Info("without span", "a_key", "a_value") - }() - - got := map[string]string{} - if err := json.Unmarshal([]byte(strings.TrimSuffix(buffer.String(), "\n")), &got); err != nil { - panic(err) - } - - for key := range want { - if got[key] != want[key] { - t.Errorf("\ngot %q for key %q\nwant %q", got[key], key, want[key]) - } - } - }) - - // t.Run("adds span and trace ids to log", func(t *testing.T) { - // spanRecorder, tracer := setupTracer() - // buffer := setupLogger() - - // want := []string{"trace_id", "span_id"} - - // func() { - // ctx := context.Background() - // ctx, span := tracer.Start(ctx, testOperationName) - // defer span.End() - - // slog.InfoContext(ctx, "adds span and trace ids to log") - // }() - - // got := map[string]string{} - // if err := json.Unmarshal([]byte(strings.TrimSuffix(buffer.String(), "\n")), &got); err != nil { - // t.Fatal(err) - // } - - // spans := spanRecorder.Ended() - // if len(spans) != 1 { - // t.Errorf("\ngot %d spans\nwant %d", len(spans), 1) - // } - - // for _, key := range want { - // if _, ok := got[key]; !ok { - // t.Errorf("\n%q attribute is missing", key) - // } - // } - // }) - - t.Run("adds event to span", func(t *testing.T) { - spanRecorder, tracer := setupTracer() - _ = setupLogger() - - want := []attribute.KeyValue{{ - Key: "a_key", - Value: attribute.StringValue("a_value"), - }, { - Key: "bool_key", - Value: attribute.BoolValue(true), - }, { - Key: "float64_key", - Value: attribute.Float64Value(1.0), - }, { - Key: "int64_key", - Value: attribute.Int64Value(1), - }, { - Key: "time_key", - Value: attribute.StringValue("2023-11-06T14:58:12.140329296+08:00"), - }, { - Key: "msg", - Value: attribute.StringValue("adds event to span"), - }, { - Key: "level", - Value: attribute.StringValue("INFO"), - }, { - Key: "group_1.key_1", - Value: attribute.StringValue("value_1"), - }, { - Key: "group_2.key_2", - Value: attribute.StringValue("value_2"), - }} - - func() { - ctx := context.Background() - ctx, span := tracer.Start(ctx, testOperationName) - defer span.End() - - testT, _ := time.Parse(time.RFC3339Nano, "2023-11-06T14:58:12.140329296+08:00") - - group1 := slog.Group("group_1", "key_1", "value_1") - group2 := slog.Group("group_2", "key_2", "value_2") - slog.InfoContext(ctx, "adds event to span", - "a_key", "a_value", - "bool_key", true, - "float64_key", 1.0, - "int64_key", 1, - "time_key", testT, - group1, group2) - }() - - spans := spanRecorder.Ended() - - if len(spans) != 1 { - t.Errorf("\ngot %d spans\nwant %d", len(spans), 1) - } - - expectedEventName := "log_record" - if spans[0].Events()[0].Name != expectedEventName { - t.Errorf("\ngot %q\nwant %q", spans[0].Events()[0].Name, expectedEventName) - } - - for _, wantAttr := range want { - found := false - - for _, gotAttr := range spans[0].Events()[0].Attributes { - if wantAttr.Key == gotAttr.Key && - wantAttr.Value == gotAttr.Value { - found = true - break - } - } - - if !found { - t.Errorf("\nspan event attribute with key %v and value %v is missing", - wantAttr.Key, wantAttr.Value) - } - } - }) - - t.Run("adds context baggage attributes to log", func(t *testing.T) { - spanRecorder, tracer := setupTracer() - buffer := setupLogger() - - want := map[string]string{ - "key1b": "value1b", - "key2b": "value2b", - } - - func() { - m1, _ := baggage.NewMember("key1b", "value1b") - m2, _ := baggage.NewMember("key2b", "value2b") - bag, _ := baggage.New(m1, m2) - ctx := baggage.ContextWithBaggage(context.Background(), bag) - - ctx, span := tracer.Start(ctx, testOperationName) - defer span.End() - - slog.InfoContext(ctx, "adds context baggage attributes to log") - }() - - spanRecorder.Ended() - - got := map[string]string{} - if err := json.Unmarshal([]byte(strings.TrimSuffix(buffer.String(), "\n")), &got); err != nil { - t.Fatal(err) - } - - for key := range want { - if got[key] != want[key] { - t.Errorf("\ngot %q for key %q\nwant %q", got[key], key, want[key]) - } - } - }) - - t.Run("does not set span status with non error logs", func(t *testing.T) { - spanRecorder, tracer := setupTracer() - _ = setupLogger() - - want := sdktrace.Status{ - Code: codes.Unset, - } - - func() { - ctx := context.Background() - - ctx, span := tracer.Start(ctx, testOperationName) - defer span.End() - - slog.InfoContext(ctx, "sets span status as error with error log") - slog.DebugContext(ctx, "sets span status as error with error log") - slog.WarnContext(ctx, "sets span status as error with error log") - }() - - spans := spanRecorder.Ended() - for _, span := range spans { - if span.Status() != want { - t.Errorf("\ngot %v\nwant %v", span.Status(), want) - } - } - }) - - t.Run("sets span status as error with error log", func(t *testing.T) { - spanRecorder, tracer := setupTracer() - buffer := setupLogger() - - want := sdktrace.Status{ - Code: codes.Error, - Description: "an error", - } - - func() { - ctx := context.Background() - - ctx, span := tracer.Start(ctx, testOperationName) - defer span.End() - - slog.ErrorContext(ctx, "an error") - }() - - spans := spanRecorder.Ended() - spans[0].Status() - - got := map[string]string{} - if err := json.Unmarshal([]byte(strings.TrimSuffix(buffer.String(), "\n")), &got); err != nil { - t.Fatal(err) - } - - if spans[0].Status() != want { - t.Errorf("\ngot %v\nwant %v", spans[0].Status(), want) - } - }) -} diff --git a/internal/kslog/log_observer.go b/internal/kslog/slog.go similarity index 73% rename from internal/kslog/log_observer.go rename to internal/kslog/slog.go index ac5f48f..3ee2999 100644 --- a/internal/kslog/log_observer.go +++ b/internal/kslog/slog.go @@ -2,13 +2,28 @@ package kslog import ( "bytes" + "context" "encoding/json" "log/slog" "strings" "github.com/samber/lo" + "go.opentelemetry.io/otel/trace" ) +// LogWithContext returns a logger with trace information. +func LogWithContext(ctx context.Context, logger *slog.Logger) *slog.Logger { + s := trace.SpanContextFromContext(ctx) + if s.HasTraceID() { + logger = logger.With(slog.String("trace_id", s.TraceID().String())) + } + if s.HasSpanID() { + logger = logger.With(slog.String("span_id", s.SpanID().String())) + } + + return logger +} + // NewTestLogger returns a new test logger. func NewTestLogger() (*slog.Logger, *observer) { observer := &observer{ @@ -68,13 +83,8 @@ func (b *observer) Filter(filter func(map[string]any) bool) *observer { } } - buf := new(bytes.Buffer) - for _, line := range filtered { - lo.Must0(json.NewEncoder(buf).Encode(line)) - } - return &observer{ - buf: buf, + buf: b.encode(filtered), } } @@ -89,14 +99,18 @@ func (b *observer) RemoveKeys(keys ...string) *observer { filtered = append(filtered, line) } - buf := new(bytes.Buffer) - for _, line := range filtered { - lo.Must0(json.NewEncoder(buf).Encode(line)) + return &observer{ + buf: b.encode(filtered), } +} - return &observer{ - buf: buf, +// encode encodes the provided value to a buffer. +func (b *observer) encode(lines []map[string]any) *bytes.Buffer { + buf := new(bytes.Buffer) + for _, v := range lines { + lo.Must0(json.NewEncoder(buf).Encode(v)) } + return buf } // Clean clears the observed logs. diff --git a/internal/kslog/log_level.go b/internal/kslog/slog_level.go similarity index 100% rename from internal/kslog/log_level.go rename to internal/kslog/slog_level.go diff --git a/kod.go b/kod.go index 4f270a0..85195ce 100644 --- a/kod.go +++ b/kod.go @@ -61,7 +61,7 @@ func (i *Implements[T]) Tracer(opts ...trace.TracerOption) trace.Tracer { // Meter return the associated meter. func (i *Implements[T]) Meter(opts ...metric.MeterOption) metric.Meter { - return otel.GetMeterProvider().Meter(i.name, opts...) + return otel.Meter(i.name, opts...) } // setLogger sets the logger for the component.