logger: otlp support

logger/logfmt.go

@@ -0,0 +1,79 @@
+package logger
+
+import (
+	"bytes"
+	"context"
+	"log/slog"
+	"slices"
+	"strings"
+	"sync"
+)
+
+type logfmt struct {
+	buf  *bytes.Buffer
+	txt  slog.Handler
+	next slog.Handler
+	mu   sync.Mutex
+}
+
+func newLogFmtHandler(next slog.Handler) slog.Handler {
+
+	buf := bytes.NewBuffer([]byte{})
+
+	h := &logfmt{
+		buf:  buf,
+		next: next,
+		txt: slog.NewTextHandler(buf, &slog.HandlerOptions{
+			ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
+				if a.Key == slog.TimeKey && len(groups) == 0 {
+					return slog.Attr{}
+				}
+				if a.Key == slog.LevelKey && len(groups) == 0 {
+					return slog.Attr{}
+				}
+				return a
+			},
+		}),
+	}
+
+	return h
+}
+
+func (h *logfmt) Enabled(ctx context.Context, lvl slog.Level) bool {
+	return h.next.Enabled(ctx, lvl)
+}
+
+func (h *logfmt) WithAttrs(attrs []slog.Attr) slog.Handler {
+	return &logfmt{
+		buf:  bytes.NewBuffer([]byte{}),
+		next: h.next.WithAttrs(slices.Clone(attrs)),
+		txt:  h.txt.WithAttrs(slices.Clone(attrs)),
+	}
+}
+
+func (h *logfmt) WithGroup(g string) slog.Handler {
+	if g == "" {
+		return h
+	}
+	return &logfmt{
+		buf:  bytes.NewBuffer([]byte{}),
+		next: h.next.WithGroup(g),
+		txt:  h.txt.WithGroup(g),
+	}
+}
+
+func (h *logfmt) Handle(ctx context.Context, r slog.Record) error {
+	h.mu.Lock()
+	defer h.mu.Unlock()
+
+	if h.buf.Len() > 0 {
+		panic("buffer wasn't empty")
+	}
+
+	h.txt.Handle(ctx, r)
+	r.Message = h.buf.String()
+	r.Message = strings.TrimSuffix(r.Message, "\n")
+	h.buf.Reset()
+
+	return h.next.Handle(ctx, r)
+}

logger/logfmt_test.go

@@ -0,0 +1,43 @@
+package logger
+
+import (
+	"bytes"
+	"encoding/json"
+	"log/slog"
+	"strings"
+	"testing"
+)
+
+func TestLogFmt(t *testing.T) {
+
+	var buf bytes.Buffer
+	jsonh := slog.NewJSONHandler(&buf, nil)
+	h := newLogFmtHandler(jsonh)
+
+	log := slog.New(h)
+	log.Info("test message", "id", 1010)
+	t.Logf("buf: %s", buf.String())
+
+	msg := map[string]any{}
+
+	err := json.Unmarshal(buf.Bytes(), &msg)
+	if err != nil {
+		t.Logf("couldn't unmarshal json log: %s", err)
+		t.Fail()
+	}
+
+	if msgTxt, ok := msg["msg"].(string); ok {
+		if !strings.Contains(msgTxt, "id=1010") {
+			t.Log("didn't find id in msg value")
+			t.Fail()
+		}
+		if strings.Contains(msgTxt, "level=") {
+			t.Log("msg value contains level=")
+			t.Fail()
+		}
+	} else {
+		t.Log("didn't find message in output")
+		t.Fail()
+	}
+
+}

logger/logger.go

@@ -8,77 +8,143 @@ import (
 	"strconv"
 	"sync"
 
-	slogotel "github.com/remychantenay/slog-otel"
+	slogtraceid "github.com/remychantenay/slog-otel"
+	slogmulti "github.com/samber/slog-multi"
+	"go.opentelemetry.io/contrib/bridges/otelslog"
 )
 
 var ConfigPrefix = ""
 
-var rootLogger *slog.Logger
-var setup sync.Once
+var textLogger *slog.Logger
+var otlpLogger *slog.Logger
+var multiLogger *slog.Logger
 
-func Setup() *slog.Logger {
+var setupText sync.Once  // this sets the default
+var setupOtlp sync.Once  // this never sets the default
+var setupMulti sync.Once // this sets the default, and will always run after the others
+var mu sync.Mutex
 
-	setup.Do(func() {
+func setupStdErrHandler() slog.Handler {
+	var programLevel = new(slog.LevelVar) // Info by default
 
-		var programLevel = new(slog.LevelVar) // Info by default
+	envVar := "DEBUG"
+	if len(ConfigPrefix) > 0 {
+		envVar = ConfigPrefix + "_" + envVar
+	}
 
-		envVar := "DEBUG"
-		if len(ConfigPrefix) > 0 {
-			envVar = ConfigPrefix + "_" + envVar
+	if opt := os.Getenv(envVar); len(opt) > 0 {
+		if debug, _ := strconv.ParseBool(opt); debug {
+			programLevel.Set(slog.LevelDebug)
 		}
+	}
 
-		if opt := os.Getenv(envVar); len(opt) > 0 {
-			if debug, _ := strconv.ParseBool(opt); debug {
-				programLevel.Set(slog.LevelDebug)
-			}
-		}
+	logOptions := &slog.HandlerOptions{Level: programLevel}
 
-		logOptions := &slog.HandlerOptions{Level: programLevel}
+	if len(os.Getenv("INVOCATION_ID")) > 0 {
+		// don't add timestamps when running under systemd
+		log.Default().SetFlags(0)
 
-		if len(os.Getenv("INVOCATION_ID")) > 0 {
-			// don't add timestamps when running under systemd
-			log.Default().SetFlags(0)
+		logOptions.ReplaceAttr = logRemoveTime
+	}
 
-			logReplace := func(groups []string, a slog.Attr) slog.Attr {
-				// Remove time
-				if a.Key == slog.TimeKey && len(groups) == 0 {
-					return slog.Attr{}
-				}
-				return a
-			}
+	logHandler := slogtraceid.OtelHandler{
+		Next: slog.NewTextHandler(os.Stderr, logOptions),
+	}
 
-			logOptions.ReplaceAttr = logReplace
-		}
+	return logHandler
+}
 
-		logHandler := slogotel.OtelHandler{
-			Next: slog.NewTextHandler(os.Stderr, logOptions),
-		}
+func setupOtlpLogger() *slog.Logger {
+	setupOtlp.Do(func() {
+		otlpLogger = slog.New(
+			newLogFmtHandler(otelslog.NewHandler("common")),
+		)
+	})
+	return otlpLogger
+}
 
-		// https://github.com/cyrusaf/ctxlog/pull/1
-		// log := slog.New(ctxlog.NewHandler(logHandler))
-		log := slog.New(logHandler)
-
-		slog.SetDefault(log)
-
-		rootLogger = log
+// SetupMultiLogger will setup and make default a logger that
+// logs as described in Setup() as well as an OLTP logger.
+// The "multi logger" is made the default the first time
+// this function is called
+func SetupMultiLogger() *slog.Logger {
+	setupMulti.Do(func() {
+		textHandler := Setup().Handler()
+		otlpHandler := setupOtlpLogger().Handler()
 
+		multiHandler := slogmulti.Fanout(
+			textHandler,
+			otlpHandler,
+		)
+		mu.Lock()
+		defer mu.Unlock()
+		multiLogger = slog.New(multiHandler)
+		slog.SetDefault(multiLogger)
 	})
 
-	return rootLogger
+	return multiLogger
+}
+
+// SetupOLTP configures and returns a logger sending logs
+// via OpenTelemetry (configured via the tracing package).
+//
+// This was made to work with Loki + Grafana that makes it
+// hard to view the log attributes in the UI, so the log
+// message is formatted similarly to the text logger. The
+// attributes are duplicated as OLTP attributes in the
+// log messages. https://github.com/grafana/loki/issues/14788
+func SetupOLTP() *slog.Logger {
+	return setupOtlpLogger()
+}
+
+// Setup returns an slog.Logger configured for text formatting
+// to stderr.
+// OpenTelemetry trace_id and span_id's are logged as attributes
+// when available.
+// When the application is running under systemd timestamps are
+// omitted. On first call the slog default logger is set to this
+// logger as well.
+//
+// If SetupMultiLogger has been called Setup() will return
+// the "multi logger"
+func Setup() *slog.Logger {
+	setupText.Do(func() {
+		h := setupStdErrHandler()
+		textLogger = slog.New(h)
+		slog.SetDefault(textLogger)
+	})
+
+	mu.Lock()
+	defer mu.Unlock()
+
+	if multiLogger != nil {
+		return multiLogger
+	}
+	return textLogger
 }
 
 type loggerKey struct{}
 
-// NewContext adds the logger to the context.
+// NewContext adds the logger to the context. Use this
+// to for example make a request specific logger available
+// to other functions through the context
 func NewContext(ctx context.Context, l *slog.Logger) context.Context {
 	return context.WithValue(ctx, loggerKey{}, l)
 }
 
 // FromContext retrieves a logger from the context. If there is none,
-// it returns the default logger.
+// it returns the default logger
 func FromContext(ctx context.Context) *slog.Logger {
 	if l, ok := ctx.Value(loggerKey{}).(*slog.Logger); ok {
 		return l
 	}
 	return Setup()
 }
+
+func logRemoveTime(groups []string, a slog.Attr) slog.Attr {
+	// Remove time
+	if a.Key == slog.TimeKey && len(groups) == 0 {
+		return slog.Attr{}
+	}
+	return a
+}