From d2b11a4e23d11c28f0efbb9adf56b637ffd78bcd Mon Sep 17 00:00:00 2001
From: Wojtek Bednarzak <wojtek.bednarzak@gmail.com>
Date: Sat, 16 Sep 2023 23:59:41 +0300
Subject: [PATCH] Add trace details to every log

This will make it easier to correlate logs with tracing.
---
 internal/cmd/saferplace/dependencies.go |  8 +++-
 internal/log/handler.go                 | 53 +++++++++++++++++++++++--
 2 files changed, 56 insertions(+), 5 deletions(-)

diff --git a/internal/cmd/saferplace/dependencies.go b/internal/cmd/saferplace/dependencies.go
index 80b7a74..d3abdce 100644
--- a/internal/cmd/saferplace/dependencies.go
+++ b/internal/cmd/saferplace/dependencies.go
@@ -66,9 +66,9 @@ func StringsToDependencies(ss []string) []Dependency {
 
 type dependencies struct {
 	// always created dependencies
+	logger  log.Logger
 	tracing trace.TracerProvider
 	metrics *prometheus.Registry
-	logger  log.Logger
 
 	// dynamically created dependencies
 	database database.Database
@@ -96,6 +96,12 @@ func createDependencies(ctx context.Context, cfg *config.Config, components []Co
 	mc = append(mc, tracingCloser)
 	deps.tracing = tracing
 
+	deps.logger.Debug(ctx, "tracing initialized",
+		slog.Bool("enabled", cfg.Tracing.Enabled),
+		slog.String("endpoint", cfg.Tracing.Endpoint),
+		slog.Float64("sampling_ratio", cfg.Tracing.SamplingRatio),
+	)
+
 	deps.logger.Debug(ctx, "initializing dependencies",
 		slog.Any("components", components),
 		slog.Any("dependencies", wantedDependencies),
diff --git a/internal/log/handler.go b/internal/log/handler.go
index 67144eb..7c20c7a 100644
--- a/internal/log/handler.go
+++ b/internal/log/handler.go
@@ -7,6 +7,8 @@ import (
 	"log/slog"
 	"strings"
 	"time"
+
+	"go.opentelemetry.io/otel/trace"
 )
 
 // handler is a new handler with a more human readable output which takes less space.
@@ -32,16 +34,59 @@ func NewHandler(out io.Writer, level slog.Level) *handler {
 }
 
 func (h *handler) Handle(ctx context.Context, r slog.Record) error {
-	kvs := make([]string, 0, r.NumAttrs())
+	builder := new(strings.Builder)
+	if !r.Time.IsZero() {
+		builder.WriteString(r.Time.Format(time.RFC3339Nano) + " ")
+	}
+	builder.WriteString(r.Level.String() + "\t" + r.Message + "\t")
 	r.Attrs(func(a slog.Attr) bool {
-		kvs = append(kvs, strings.Join(append(h.groups, a.Key), ".")+"="+a.Value.String())
+		h.appendAttr(builder, a)
 		return true
 	})
-	fmt.Fprintf(h.out, "%s %s\t%s\t%s\n",
-		r.Time.Format(time.RFC3339Nano), r.Level, r.Message, strings.Join(kvs, " "))
+
+	extraAttr := h.attrs[:]
+	// Add the tracing information if available.
+	span := trace.SpanFromContext(ctx)
+	if traceID := span.SpanContext().TraceID(); traceID.IsValid() {
+		extraAttr = append(extraAttr,
+			slog.String("trace_id", traceID.String()),
+			slog.String("span_id", span.SpanContext().SpanID().String()),
+		)
+	}
+
+	for _, attr := range extraAttr {
+		h.appendAttr(builder, attr)
+	}
+
+	fmt.Fprintln(h.out, builder.String())
 	return nil
 }
 
+func (h *handler) appendAttr(builder *strings.Builder, a slog.Attr) {
+	a.Value = a.Value.Resolve()
+	// ignore empty attr
+	if a.Equal(slog.Attr{}) {
+		return
+	}
+	switch a.Value.Kind() {
+	case slog.KindString:
+		builder.WriteString(fmt.Sprintf("%s=%q", a.Key, a.Value.String()) + " ")
+	case slog.KindTime:
+		builder.WriteString(a.Key + "=" + a.Value.Time().Format(time.RFC3339Nano) + " ")
+	case slog.KindGroup:
+		attrs := a.Value.Group()
+		if len(attrs) == 0 {
+			return
+		}
+		for _, ga := range attrs {
+			ga.Key = a.Key + "." + ga.Key
+			h.appendAttr(builder, ga)
+		}
+	default:
+		builder.WriteString(fmt.Sprintf("%s=%s", a.Key, a.Value.String()) + " ")
+	}
+}
+
 func (h *handler) clone() *handler {
 	c := *h
 	return &c