auth: slog, otel, & logging improvements (#1204)

auth/go.mod

@@ -41,6 +41,7 @@ require (
 	github.com/lestrrat-go/option/v2 v2.0.0 // indirect
 	github.com/segmentio/asm v1.2.1 // indirect
 	go.opentelemetry.io/auto/sdk v1.1.0 // indirect
+	go.opentelemetry.io/contrib/bridges/otelslog v0.13.0 // indirect
 	go.opentelemetry.io/otel/metric v1.38.0 // indirect
 	go.opentelemetry.io/otel/trace v1.38.0 // indirect
 	go.opentelemetry.io/proto/otlp v1.7.1 // indirect

auth/go.sum

@@ -161,6 +161,8 @@ github.com/valyala/fasttemplate v1.2.2/go.mod h1:KHLXt3tVN2HBp8eijSv/kGJopbvo7S+
 github.com/yuin/goldmark v1.4.13/go.mod h1:6yULJ656Px+3vBD8DxQVa3kxgyrAnzto9xy5taEt/CY=
 go.opentelemetry.io/auto/sdk v1.1.0 h1:cH53jehLUN6UFLY71z+NDOiNJqDdPRaXzTel0sJySYA=
 go.opentelemetry.io/auto/sdk v1.1.0/go.mod h1:3wSPjt5PWp2RhlCcmmOial7AvC4DQqZb7a7wCow3W8A=
+go.opentelemetry.io/contrib/bridges/otelslog v0.13.0 h1:bwnLpizECbPr1RrQ27waeY2SPIPeccCx/xLuoYADZ9s=
+go.opentelemetry.io/contrib/bridges/otelslog v0.13.0/go.mod h1:3nWlOiiqA9UtUnrcNk82mYasNxD8ehOspL0gOfEo6Y4=
 go.opentelemetry.io/contrib/instrumentation/github.com/labstack/echo/otelecho v0.63.0 h1:6YeICKmGrvgJ5th4+OMNpcuoB6q/Xs8gt0YCO7MUv1k=
 go.opentelemetry.io/contrib/instrumentation/github.com/labstack/echo/otelecho v0.63.0/go.mod h1:ZEA7j2B35siNV0T00aapacNzjz4tvOlNoHp0ncCfwNQ=
 go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.61.0 h1:F7Jx+6hwnZ41NSFTO5q4LYDtJRXBf2PD0rNBkeB/lus=

auth/main.go

@@ -5,9 +5,12 @@ import (
 	"encoding/base64"
 	"errors"
 	"fmt"
+	"log/slog"
 	"net/http"
 	"os"
 	"os/user"
+	"slices"
+	"sort"
 	"strings"
 
 	"github.com/zoriya/kyoo/keibi/dbc"
@@ -140,7 +143,7 @@ func OpenDatabase() (*pgxpool.Pool, error) {
 		return nil, err
 	}
 
-	fmt.Println("Migrating database")
+	slog.Info("Database migration state", "state", "starting")
 	dbi := stdlib.OpenDBFromPool(db)
 	defer dbi.Close()
 
@@ -156,7 +159,7 @@ func OpenDatabase() (*pgxpool.Pool, error) {
 		return nil, err
 	}
 	m.Up()
-	fmt.Println("Migrating finished")
+	slog.Info("Database migration state", "state", "completed")
 
 	return db, nil
 }
@@ -227,17 +230,72 @@ func (h *Handler) TokenToJwt(next echo.HandlerFunc) echo.HandlerFunc {
 // @in header
 // @name Authorization
 func main() {
-	e := echo.New()
+	ctx := context.Background()
-	e.Use(middleware.Logger())
-	e.Validator = &Validator{validator: validator.New(validator.WithRequiredStructEnabled())}
-	e.HTTPErrorHandler = ErrorHandler
 
-	cleanup, err := setupOtel(e)
+	logger, _, err := SetupLogger(ctx)
 	if err != nil {
-		e.Logger.Fatal("Failed to setup otel: ", err)
+		slog.Error("logger init", "err", err)
+	}
+
+	cleanup, err := setupOtel(ctx)
+	if err != nil {
+		slog.Error("Failed to setup otel: ", "err", err)
 		return
 	}
-	defer cleanup()
+	defer cleanup(ctx)
+
+	e := echo.New()
+	e.HideBanner = true
+	e.Logger.SetOutput(logger)
+	instrument(e)
+
+	ignorepath := []string{
+		"/.well-known/jwks.json",
+		"/auth/health",
+		"/auth/ready",
+	}
+	slog.Info("Skipping request logging for these paths", "paths", func() string { sort.Strings(ignorepath); return strings.Join(ignorepath, ",") }())
+
+	// using example from https://echo.labstack.com/docs/middleware/logger#examples
+	// full configs https://github.com/labstack/echo/blob/master/middleware/request_logger.go
+	e.Use(middleware.RequestLoggerWithConfig(middleware.RequestLoggerConfig{
+		// declare a small set of paths to ignore
+		Skipper: func(c echo.Context) bool {
+			p := c.Request().URL.Path
+			return slices.Contains(ignorepath, p)
+		},
+		LogStatus:    true,
+		LogURI:       true,
+		LogError:     true,
+		LogHost:      true,
+		LogMethod:    true,
+		LogUserAgent: true,
+		HandleError:  true, // forwards error to the global error handler, so it can decide appropriate status code
+		LogValuesFunc: func(c echo.Context, v middleware.RequestLoggerValues) error {
+			if v.Error == nil {
+				logger.LogAttrs(ctx, slog.LevelInfo, "web_request",
+					slog.String("method", v.Method),
+					slog.Int("status", v.Status),
+					slog.String("host", v.Host),
+					slog.String("uri", v.URI),
+					slog.String("agent", v.UserAgent),
+				)
+			} else {
+				logger.LogAttrs(ctx, slog.LevelError, "web_request_error",
+					slog.String("method", v.Method),
+					slog.Int("status", v.Status),
+					slog.String("host", v.Host),
+					slog.String("uri", v.URI),
+					slog.String("agent", v.UserAgent),
+					slog.String("err", v.Error.Error()),
+				)
+			}
+			return nil
+		},
+	}))
+
+	e.Validator = &Validator{validator: validator.New(validator.WithRequiredStructEnabled())}
+	e.HTTPErrorHandler = ErrorHandler
 
 	db, err := OpenDatabase()
 	if err != nil {

auth/otel.go

@@ -2,6 +2,9 @@ package main
 
 import (
 	"context"
+	"errors"
+	"log/slog"
+	"os"
 	"strings"
 
 	"github.com/labstack/echo/v4"
@@ -11,21 +14,23 @@ import (
 	"go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploghttp"
 	"go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetricgrpc"
 	"go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetrichttp"
-	"go.opentelemetry.io/otel/exporters/otlp/otlptrace"
 	"go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc"
 	"go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracehttp"
-	"go.opentelemetry.io/otel/log/global"
+	logotel "go.opentelemetry.io/otel/log"
-	"go.opentelemetry.io/otel/sdk/log"
+	logotelglobal "go.opentelemetry.io/otel/log/global"
-	"go.opentelemetry.io/otel/sdk/metric"
+	logotelnoop "go.opentelemetry.io/otel/log/noop"
+	metricotel "go.opentelemetry.io/otel/metric"
+	metricotelnoop "go.opentelemetry.io/otel/metric/noop"
+	logsdk "go.opentelemetry.io/otel/sdk/log"
+	metricsdk "go.opentelemetry.io/otel/sdk/metric"
 	"go.opentelemetry.io/otel/sdk/resource"
-	"go.opentelemetry.io/otel/sdk/trace"
+	tracesdk "go.opentelemetry.io/otel/sdk/trace"
 	semconv "go.opentelemetry.io/otel/semconv/v1.26.0"
+	traceotel "go.opentelemetry.io/otel/trace"
+	traceotelnoop "go.opentelemetry.io/otel/trace/noop"
 )
 
-func setupOtel(e *echo.Echo) (func(), error) {
+func setupOtel(ctx context.Context) (func(context.Context) error, error) {
-	ctx := context.Background()
-	proto := GetenvOr("OTEL_EXPORTER_OTLP_PROTOCOL", "http/protobuf")
-
 	res, err := resource.New(
 		ctx,
 		resource.WithAttributes(semconv.ServiceNameKey.String("kyoo.auth")),
@@ -40,64 +45,141 @@ func setupOtel(e *echo.Echo) (func(), error) {
 		return nil, err
 	}
 
-	var le log.Exporter
+	slog.Info("Configuring OTEL")
-	if proto == "http/protobuf" {
+
-		le, err = otlploghttp.New(ctx)
+	var le logsdk.Exporter
-	} else {
+	var me metricsdk.Exporter
+	var te tracesdk.SpanExporter
+	switch {
+	case strings.TrimSpace(os.Getenv("OTEL_EXPORTER_OTLP_ENDPOINT")) == "":
+		slog.Info("Using OLTP type", "type", "noop")
+		le = nil
+		me = nil
+		te = nil
+	case strings.ToLower(strings.TrimSpace(os.Getenv("OTEL_EXPORTER_OTLP_PROTOCOL"))) == "grpc":
+		slog.Info("Using OLTP type", "type", "grpc")
 		le, err = otlploggrpc.New(ctx)
+		if err != nil {
+			slog.Error("Failed setting up OLTP: ", err)
+			return nil, err
+		}
+		me, err = otlpmetricgrpc.New(ctx)
+		if err != nil {
+			slog.Error("Failed setting up OLTP: ", err)
+			return nil, err
+		}
+		te, err = otlptracegrpc.New(ctx)
+		if err != nil {
+			slog.Error("Failed setting up OLTP: ", err)
+			return nil, err
+		}
+	default:
+		slog.Info("Using OLTP type", "type", "http")
+		le, err = otlploghttp.New(ctx)
+		if err != nil {
+			slog.Error("Failed setting up OLTP: ", err)
+			return nil, err
+		}
+		me, err = otlpmetrichttp.New(ctx)
+		if err != nil {
+			slog.Error("Failed setting up OLTP: ", err)
+			return nil, err
+		}
+		te, err = otlptracehttp.New(ctx)
+		if err != nil {
+			slog.Error("Failed setting up OLTP: ", err)
+			return nil, err
+		}
 	}
 	if err != nil {
 		return nil, err
 	}
-	lp := log.NewLoggerProvider(
-		log.WithProcessor(log.NewBatchProcessor(le)),
-		log.WithResource(res),
-	)
-	global.SetLoggerProvider(lp)
 
-	var me metric.Exporter
+	// default to noop providers
-	if proto == "http/protobuf" {
+	var lp logotel.LoggerProvider = logotelnoop.NewLoggerProvider()
-		me, err = otlpmetrichttp.New(ctx)
+	var mp metricotel.MeterProvider = metricotelnoop.NewMeterProvider()
-	} else {
+	var tp traceotel.TracerProvider = traceotelnoop.NewTracerProvider()
-		me, err = otlpmetricgrpc.New(ctx)
+
+	// use exporter if configured
+	if le != nil {
+		lp = logsdk.NewLoggerProvider(
+			logsdk.WithProcessor(logsdk.NewBatchProcessor(le)),
+			logsdk.WithResource(res),
+		)
 	}
-	if err != nil {
+
-		return func() {}, err
+	if me != nil {
+		mp = metricsdk.NewMeterProvider(
+			metricsdk.WithReader(
+				metricsdk.NewPeriodicReader(me),
+			),
+			metricsdk.WithResource(res),
+		)
 	}
-	mp := metric.NewMeterProvider(
+
-		metric.WithReader(
+	if te != nil {
-			metric.NewPeriodicReader(me),
+		tp = tracesdk.NewTracerProvider(
-		),
+			tracesdk.WithBatcher(te),
-		metric.WithResource(res),
+			tracesdk.WithResource(res),
-	)
+		)
+	}
+
+	// set providers
+	logotelglobal.SetLoggerProvider(lp)
 	otel.SetMeterProvider(mp)
-
-	var te *otlptrace.Exporter
-	if proto == "http/protobuf" {
-		te, err = otlptracehttp.New(ctx)
-	} else {
-		te, err = otlptracegrpc.New(ctx)
-	}
-	if err != nil {
-		return func() {}, err
-	}
-	tp := trace.NewTracerProvider(
-		trace.WithBatcher(te),
-		trace.WithResource(res),
-	)
 	otel.SetTracerProvider(tp)
 
+	// configure shutting down
+	// noop providers do not have a Shudown method
+	log_shutdown := func(ctx context.Context) error {
+		if otelprovider, ok := lp.(*logsdk.LoggerProvider); ok && otelprovider != nil {
+			return otelprovider.Shutdown(ctx)
+		}
+		return nil
+	}
+
+	metric_shutdown := func(ctx context.Context) error {
+		if otelprovider, ok := mp.(*metricsdk.MeterProvider); ok && otelprovider != nil {
+			return otelprovider.Shutdown(ctx)
+		}
+		return nil
+	}
+
+	trace_shutdown := func(ctx context.Context) error {
+		if otelprovider, ok := tp.(*tracesdk.TracerProvider); ok && otelprovider != nil {
+			return otelprovider.Shutdown(ctx)
+		}
+		return nil
+	}
+
+	return func(ctx context.Context) error {
+		slog.Info("Shutting down OTEL")
+
+		// run shutdowns and collect errors
+		var errs []error
+		if err := trace_shutdown(ctx); err != nil {
+			errs = append(errs, err)
+		}
+		if err := metric_shutdown(ctx); err != nil {
+			errs = append(errs, err)
+		}
+		if err := log_shutdown(ctx); err != nil {
+			errs = append(errs, err)
+		}
+
+		if len(errs) == 0 {
+			return nil
+		}
+		return errors.Join(errs...)
+	}, nil
+}
+
+func instrument(e *echo.Echo) {
 	e.Use(otelecho.Middleware("kyoo.auth", otelecho.WithSkipper(func(c echo.Context) bool {
 		return (c.Path() == "/auth/health" ||
 			c.Path() == "/auth/ready" ||
 			strings.HasPrefix(c.Path(), "/.well-known/"))
 	})))
-
-	return func() {
-		lp.Shutdown(ctx)
-		mp.Shutdown(ctx)
-		tp.Shutdown(ctx)
-	}, nil
 }
 
 // stolen from https://github.com/exaring/otelpgx/issues/47

auth/slog.go

@@ -0,0 +1,111 @@
+package main
+
+import (
+	"context"
+	"log/slog"
+	"os"
+	"strings"
+
+	logotelbridge "go.opentelemetry.io/contrib/bridges/otelslog"
+	logotelglobal "go.opentelemetry.io/otel/log/global"
+)
+
+type SlogAdapter struct {
+	*slog.Logger
+}
+
+// add Write so SlogAdapter satisfies io.Writer (Echo's logger output)
+func (a *SlogAdapter) Write(p []byte) (int, error) {
+	msg := strings.TrimSpace(string(p))
+	// Echo middleware writes request lines at INFO; use Info here.
+	a.Info(msg)
+	return len(p), nil
+}
+
+type tee struct {
+	a, b slog.Handler
+	minA slog.Level
+	minB slog.Level
+}
+
+// a = stdout
+// b = otel
+// minA = minimum level for stdout
+// minB = minimum level for otel (from OTEL_LOG_LEVEL)
+func NewTee(a, b slog.Handler, minA, minB slog.Level) slog.Handler {
+	return &tee{a: a, b: b, minA: minA, minB: minB}
+}
+
+func (t *tee) Enabled(ctx context.Context, level slog.Level) bool {
+	if (t.minA == 0 || level >= t.minA) && t.a.Enabled(ctx, level) {
+		return true
+	}
+	if (t.minB == 0 || level >= t.minB) && t.b.Enabled(ctx, level) {
+		return true
+	}
+	return false
+}
+
+func (t *tee) Handle(ctx context.Context, r slog.Record) error {
+	if t.minA == 0 || r.Level >= t.minA {
+		if err := t.a.Handle(ctx, r); err != nil {
+			return err
+		}
+	}
+	if t.minB == 0 || r.Level >= t.minB {
+		return t.b.Handle(ctx, r)
+	}
+	return nil
+}
+
+func (t *tee) WithAttrs(attrs []slog.Attr) slog.Handler {
+	return NewTee(t.a.WithAttrs(attrs), t.b.WithAttrs(attrs), t.minA, t.minB)
+}
+
+func (t *tee) WithGroup(name string) slog.Handler {
+	return NewTee(t.a.WithGroup(name), t.b.WithGroup(name), t.minA, t.minB)
+}
+
+func SetupLogger(ctx context.Context) (*SlogAdapter, func(context.Context) error, error) {
+	stdout := slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
+		ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
+			// drop the default time attribute so text output has no timestamp
+			if a.Key == "time" {
+				return slog.Attr{}
+			}
+			return a
+		},
+	})
+	otelHandler := logotelbridge.NewHandler("slog", logotelbridge.WithLoggerProvider(logotelglobal.GetLoggerProvider()))
+
+	minStdout := parseLogLevel(os.Getenv("STDOUT_LOG_LEVEL"))
+	minOtel := parseLogLevel(os.Getenv("OTEL_LOG_LEVEL"))
+
+	handler := NewTee(stdout, otelHandler, minStdout, minOtel)
+
+	logger := slog.New(handler)
+	adapter := &SlogAdapter{logger}
+	shutdown := func(ctx context.Context) error { return nil }
+
+	slog.SetDefault(adapter.Logger)
+	return adapter, shutdown, nil
+}
+
+func parseLogLevel(v string) slog.Level {
+	v = strings.ToUpper(strings.TrimSpace(v))
+	if v == "" {
+		return slog.LevelInfo
+	}
+	m := map[string]slog.Level{
+		"TRACE":   slog.LevelDebug,
+		"DEBUG":   slog.LevelDebug,
+		"INFO":    slog.LevelInfo,
+		"WARN":    slog.LevelWarn,
+		"WARNING": slog.LevelWarn,
+		"ERROR":   slog.LevelError,
+	}
+	if lv, ok := m[v]; ok {
+		return lv
+	}
+	return slog.LevelInfo
+}