feat: Support OTel and JSON for logs (via log/slog) (#760)

Co-authored-by: Kyle Mendell <kmendell@ofkm.us>

backend/internal/bootstrap/application_images_bootstrap.go

@@ -1,7 +1,7 @@
 package bootstrap
 
 import (
-	"log"
+	"fmt"
 	"os"
 	"path"
 	"strings"
@@ -12,17 +12,17 @@ import (
 )
 
 // initApplicationImages copies the images from the images directory to the application-images directory
-func initApplicationImages() {
+func initApplicationImages() error {
 	dirPath := common.EnvConfig.UploadPath + "/application-images"
 
 	sourceFiles, err := resources.FS.ReadDir("images")
 	if err != nil && !os.IsNotExist(err) {
-		log.Fatalf("Error reading directory: %v", err)
+		return fmt.Errorf("failed to read directory: %w", err)
 	}
 
 	destinationFiles, err := os.ReadDir(dirPath)
 	if err != nil && !os.IsNotExist(err) {
-		log.Fatalf("Error reading directory: %v", err)
+		return fmt.Errorf("failed to read directory: %w", err)
 	}
 
 	// Copy images from the images directory to the application-images directory if they don't already exist
@@ -35,9 +35,11 @@ func initApplicationImages() {
 
 		err := utils.CopyEmbeddedFileToDisk(srcFilePath, destFilePath)
 		if err != nil {
-			log.Fatalf("Error copying file: %v", err)
+			return fmt.Errorf("failed to copy file: %w", err)
 		}
 	}
+
+	return nil
 }
 
 func imageAlreadyExists(fileName string, destinationFiles []os.DirEntry) bool {

backend/internal/bootstrap/bootstrap.go

@@ -3,7 +3,7 @@ package bootstrap
 import (
 	"context"
 	"fmt"
-	"log"
+	"log/slog"
 	"time"
 
 	_ "github.com/golang-migrate/migrate/v4/source/file"
@@ -14,13 +14,17 @@ import (
 )
 
 func Bootstrap(ctx context.Context) error {
-	initApplicationImages()
-
-	// Initialize the tracer and metrics exporter
-	shutdownFns, httpClient, err := initOtel(ctx, common.EnvConfig.MetricsEnabled, common.EnvConfig.TracingEnabled)
+	// Initialize the observability stack, including the logger, distributed tracing, and metrics
+	shutdownFns, httpClient, err := initObservability(ctx, common.EnvConfig.MetricsEnabled, common.EnvConfig.TracingEnabled)
 	if err != nil {
 		return fmt.Errorf("failed to initialize OpenTelemetry: %w", err)
 	}
+	slog.InfoContext(ctx, "Pocket ID is starting")
+
+	err = initApplicationImages()
+	if err != nil {
+		return fmt.Errorf("failed to initialize application images: %w", err)
+	}
 
 	// Connect to the database
 	db := NewDatabase()
@@ -62,7 +66,7 @@ func Bootstrap(ctx context.Context) error {
 		NewServiceRunner(shutdownFns...).
 		Run(shutdownCtx) //nolint:contextcheck
 	if err != nil {
-		log.Printf("Error shutting down services: %v", err)
+		slog.Error("Error shutting down services", slog.Any("error", err))
 	}
 
 	return nil

backend/internal/bootstrap/db_bootstrap.go

@@ -4,8 +4,8 @@ import (
 	"errors"
 	"fmt"
 	"log"
+	"log/slog"
 	"net/url"
-	"os"
 	"strings"
 	"time"
 
@@ -15,9 +15,10 @@ import (
 	postgresMigrate "github.com/golang-migrate/migrate/v4/database/postgres"
 	sqliteMigrate "github.com/golang-migrate/migrate/v4/database/sqlite3"
 	"github.com/golang-migrate/migrate/v4/source/iofs"
+	slogGorm "github.com/orandin/slog-gorm"
 	"gorm.io/driver/postgres"
 	"gorm.io/gorm"
-	"gorm.io/gorm/logger"
+	gormLogger "gorm.io/gorm/logger"
 
 	"github.com/pocket-id/pocket-id/backend/internal/common"
 	sqliteutil "github.com/pocket-id/pocket-id/backend/internal/utils/sqlite"
@@ -107,13 +108,13 @@ func connectDatabase() (db *gorm.DB, err error) {
 	for i := 1; i <= 3; i++ {
 		db, err = gorm.Open(dialector, &gorm.Config{
 			TranslateError: true,
-			Logger:         getLogger(),
+			Logger:         getGormLogger(),
 		})
 		if err == nil {
 			return db, nil
 		}
 
-		log.Printf("Attempt %d: Failed to initialize database. Retrying...", i)
+		slog.Info("Failed to initialize database", slog.Int("attempt", i))
 		time.Sleep(3 * time.Second)
 	}
 
@@ -164,24 +165,25 @@ func parseSqliteConnectionString(connString string) (string, error) {
 	return connStringUrl.String(), nil
 }
 
-func getLogger() logger.Interface {
-	isProduction := common.EnvConfig.AppEnv == "production"
+func getGormLogger() gormLogger.Interface {
+	loggerOpts := make([]slogGorm.Option, 0, 5)
+	loggerOpts = append(loggerOpts,
+		slogGorm.WithSlowThreshold(200*time.Millisecond),
+		slogGorm.WithErrorField("error"),
+	)
 
-	var logLevel logger.LogLevel
-	if isProduction {
-		logLevel = logger.Error
+	if common.EnvConfig.AppEnv == "production" {
+		loggerOpts = append(loggerOpts,
+			slogGorm.SetLogLevel(slogGorm.DefaultLogType, slog.LevelWarn),
+			slogGorm.WithIgnoreTrace(),
+		)
 	} else {
-		logLevel = logger.Info
+		loggerOpts = append(loggerOpts,
+			slogGorm.SetLogLevel(slogGorm.DefaultLogType, slog.LevelDebug),
+			slogGorm.WithRecordNotFoundError(),
+			slogGorm.WithTraceAll(),
+		)
 	}
 
-	return logger.New(
-		log.New(os.Stdout, "\r\n", log.LstdFlags),
-		logger.Config{
-			SlowThreshold:             200 * time.Millisecond,
-			LogLevel:                  logLevel,
-			IgnoreRecordNotFoundError: isProduction,
-			ParameterizedQueries:      isProduction,
-			Colorful:                  !isProduction,
-		},
-	)
+	return slogGorm.New(loggerOpts...)
 }

backend/internal/bootstrap/observability_boostrap.go

@@ -0,0 +1,210 @@
+package bootstrap
+
+import (
+	"context"
+	"fmt"
+	"log/slog"
+	"net/http"
+	"os"
+	"time"
+
+	"github.com/lmittmann/tint"
+	"github.com/mattn/go-isatty"
+	"go.opentelemetry.io/contrib/bridges/otelslog"
+	"go.opentelemetry.io/contrib/exporters/autoexport"
+	"go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp"
+	"go.opentelemetry.io/otel"
+	globallog "go.opentelemetry.io/otel/log/global"
+	metricnoop "go.opentelemetry.io/otel/metric/noop"
+	"go.opentelemetry.io/otel/propagation"
+	sdklog "go.opentelemetry.io/otel/sdk/log"
+	"go.opentelemetry.io/otel/sdk/metric"
+	"go.opentelemetry.io/otel/sdk/resource"
+	sdktrace "go.opentelemetry.io/otel/sdk/trace"
+	semconv "go.opentelemetry.io/otel/semconv/v1.30.0"
+	tracenoop "go.opentelemetry.io/otel/trace/noop"
+
+	"github.com/pocket-id/pocket-id/backend/internal/common"
+	"github.com/pocket-id/pocket-id/backend/internal/utils"
+)
+
+func defaultResource() (*resource.Resource, error) {
+	return resource.Merge(
+		resource.Default(),
+		resource.NewSchemaless(
+			semconv.ServiceName(common.Name),
+			semconv.ServiceVersion(common.Version),
+		),
+	)
+}
+
+func initObservability(ctx context.Context, metrics, traces bool) (shutdownFns []utils.Service, httpClient *http.Client, err error) {
+	resource, err := defaultResource()
+	if err != nil {
+		return nil, nil, fmt.Errorf("failed to create OpenTelemetry resource: %w", err)
+	}
+
+	shutdownFns = make([]utils.Service, 0, 2)
+
+	httpClient = &http.Client{}
+	defaultTransport, ok := http.DefaultTransport.(*http.Transport)
+	if !ok {
+		// Indicates a development-time error
+		panic("Default transport is not of type *http.Transport")
+	}
+	httpClient.Transport = defaultTransport.Clone()
+
+	// Logging
+	err = initOtelLogging(ctx, resource)
+	if err != nil {
+		return nil, nil, err
+	}
+
+	// Tracing
+	tracingShutdownFn, err := initOtelTracing(ctx, traces, resource, httpClient)
+	if err != nil {
+		return nil, nil, err
+	} else if tracingShutdownFn != nil {
+		shutdownFns = append(shutdownFns, tracingShutdownFn)
+	}
+
+	// Metrics
+	metricsShutdownFn, err := initOtelMetrics(ctx, metrics, resource)
+	if err != nil {
+		return nil, nil, err
+	} else if metricsShutdownFn != nil {
+		shutdownFns = append(shutdownFns, metricsShutdownFn)
+	}
+
+	return shutdownFns, httpClient, nil
+}
+
+func initOtelLogging(ctx context.Context, resource *resource.Resource) error {
+	// If the env var OTEL_LOGS_EXPORTER is empty, we set it to "none", for autoexport to work
+	if os.Getenv("OTEL_LOGS_EXPORTER") == "" {
+		os.Setenv("OTEL_LOGS_EXPORTER", "none")
+	}
+	exp, err := autoexport.NewLogExporter(ctx)
+	if err != nil {
+		return fmt.Errorf("failed to initialize OpenTelemetry log exporter: %w", err)
+	}
+
+	level := slog.LevelDebug
+	if common.EnvConfig.AppEnv == "production" {
+		level = slog.LevelInfo
+	}
+
+	// Create the handler
+	var handler slog.Handler
+	switch {
+	case common.EnvConfig.LogJSON:
+		// Log as JSON if configured
+		handler = slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{
+			Level: level,
+		})
+	case isatty.IsTerminal(os.Stdout.Fd()):
+		// Enable colors if we have a TTY
+		handler = tint.NewHandler(os.Stdout, &tint.Options{
+			TimeFormat: time.StampMilli,
+			Level:      level,
+		})
+	default:
+		handler = slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
+			Level: level,
+		})
+	}
+
+	// Create the logger provider
+	provider := sdklog.NewLoggerProvider(
+		sdklog.WithProcessor(
+			sdklog.NewBatchProcessor(exp),
+		),
+		sdklog.WithResource(resource),
+	)
+
+	// Set the logger provider globally
+	globallog.SetLoggerProvider(provider)
+
+	// Wrap the handler in a "fanout" one
+	handler = utils.LogFanoutHandler{
+		handler,
+		otelslog.NewHandler(common.Name, otelslog.WithLoggerProvider(provider)),
+	}
+
+	// Set the default slog to send logs to OTel and add the app name
+	log := slog.New(handler).
+		With(slog.String("app", common.Name)).
+		With(slog.String("version", common.Version))
+	slog.SetDefault(log)
+
+	return nil
+}
+
+func initOtelTracing(ctx context.Context, traces bool, resource *resource.Resource, httpClient *http.Client) (shutdownFn utils.Service, err error) {
+	if !traces {
+		otel.SetTracerProvider(tracenoop.NewTracerProvider())
+		return nil, nil
+	}
+
+	tr, err := autoexport.NewSpanExporter(ctx)
+	if err != nil {
+		return nil, fmt.Errorf("failed to initialize OpenTelemetry span exporter: %w", err)
+	}
+	tp := sdktrace.NewTracerProvider(
+		sdktrace.WithResource(resource),
+		sdktrace.WithBatcher(tr),
+	)
+
+	otel.SetTracerProvider(tp)
+	otel.SetTextMapPropagator(
+		propagation.NewCompositeTextMapPropagator(
+			propagation.TraceContext{},
+			propagation.Baggage{},
+		),
+	)
+
+	shutdownFn = func(shutdownCtx context.Context) error { //nolint:contextcheck
+		tpCtx, tpCancel := context.WithTimeout(shutdownCtx, 10*time.Second)
+		defer tpCancel()
+		shutdownErr := tp.Shutdown(tpCtx)
+		if shutdownErr != nil {
+			return fmt.Errorf("failed to gracefully shut down traces exporter: %w", shutdownErr)
+		}
+		return nil
+	}
+
+	// Add tracing to the HTTP client
+	httpClient.Transport = otelhttp.NewTransport(httpClient.Transport)
+
+	return shutdownFn, nil
+}
+
+func initOtelMetrics(ctx context.Context, metrics bool, resource *resource.Resource) (shutdownFn utils.Service, err error) {
+	if !metrics {
+		otel.SetMeterProvider(metricnoop.NewMeterProvider())
+		return nil, nil
+	}
+
+	mr, err := autoexport.NewMetricReader(ctx)
+	if err != nil {
+		return nil, fmt.Errorf("failed to initialize OpenTelemetry metric reader: %w", err)
+	}
+
+	mp := metric.NewMeterProvider(
+		metric.WithResource(resource),
+		metric.WithReader(mr),
+	)
+	otel.SetMeterProvider(mp)
+
+	shutdownFn = func(shutdownCtx context.Context) error { //nolint:contextcheck
+		mpCtx, mpCancel := context.WithTimeout(shutdownCtx, 10*time.Second)
+		defer mpCancel()
+		shutdownErr := mp.Shutdown(mpCtx)
+		if shutdownErr != nil {
+			return fmt.Errorf("failed to gracefully shut down metrics exporter: %w", shutdownErr)
+		}
+		return nil
+	}
+
+	return shutdownFn, nil
+}

backend/internal/bootstrap/otel_boostrap.go

@@ -1,107 +0,0 @@
-package bootstrap
-
-import (
-	"context"
-	"fmt"
-	"net/http"
-	"time"
-
-	"github.com/pocket-id/pocket-id/backend/internal/common"
-	"github.com/pocket-id/pocket-id/backend/internal/utils"
-	"go.opentelemetry.io/contrib/exporters/autoexport"
-	"go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp"
-	"go.opentelemetry.io/otel"
-	metricnoop "go.opentelemetry.io/otel/metric/noop"
-	"go.opentelemetry.io/otel/propagation"
-	"go.opentelemetry.io/otel/sdk/metric"
-	"go.opentelemetry.io/otel/sdk/resource"
-	sdktrace "go.opentelemetry.io/otel/sdk/trace"
-	semconv "go.opentelemetry.io/otel/semconv/v1.30.0"
-	tracenoop "go.opentelemetry.io/otel/trace/noop"
-)
-
-func defaultResource() (*resource.Resource, error) {
-	return resource.Merge(
-		resource.Default(),
-		resource.NewSchemaless(
-			semconv.ServiceName("pocket-id-backend"),
-			semconv.ServiceVersion(common.Version),
-		),
-	)
-}
-
-func initOtel(ctx context.Context, metrics, traces bool) (shutdownFns []utils.Service, httpClient *http.Client, err error) {
-	resource, err := defaultResource()
-	if err != nil {
-		return nil, nil, fmt.Errorf("failed to create OpenTelemetry resource: %w", err)
-	}
-
-	shutdownFns = make([]utils.Service, 0, 2)
-
-	httpClient = &http.Client{}
-	defaultTransport, ok := http.DefaultTransport.(*http.Transport)
-	if !ok {
-		// Indicates a development-time error
-		panic("Default transport is not of type *http.Transport")
-	}
-	httpClient.Transport = defaultTransport.Clone()
-
-	if traces {
-		tr, err := autoexport.NewSpanExporter(ctx)
-		if err != nil {
-			return nil, nil, fmt.Errorf("failed to initialize OpenTelemetry span exporter: %w", err)
-		}
-		tp := sdktrace.NewTracerProvider(
-			sdktrace.WithResource(resource),
-			sdktrace.WithBatcher(tr),
-		)
-
-		otel.SetTracerProvider(tp)
-		otel.SetTextMapPropagator(
-			propagation.NewCompositeTextMapPropagator(
-				propagation.TraceContext{},
-				propagation.Baggage{},
-			),
-		)
-
-		shutdownFns = append(shutdownFns, func(shutdownCtx context.Context) error { //nolint:contextcheck
-			tpCtx, tpCancel := context.WithTimeout(shutdownCtx, 10*time.Second)
-			defer tpCancel()
-			shutdownErr := tp.Shutdown(tpCtx)
-			if shutdownErr != nil {
-				return fmt.Errorf("failed to gracefully shut down traces exporter: %w", shutdownErr)
-			}
-			return nil
-		})
-
-		httpClient.Transport = otelhttp.NewTransport(httpClient.Transport)
-	} else {
-		otel.SetTracerProvider(tracenoop.NewTracerProvider())
-	}
-
-	if metrics {
-		mr, err := autoexport.NewMetricReader(ctx)
-		if err != nil {
-			return nil, nil, fmt.Errorf("failed to initialize OpenTelemetry metric reader: %w", err)
-		}
-		mp := metric.NewMeterProvider(
-			metric.WithResource(resource),
-			metric.WithReader(mr),
-		)
-
-		otel.SetMeterProvider(mp)
-		shutdownFns = append(shutdownFns, func(shutdownCtx context.Context) error { //nolint:contextcheck
-			mpCtx, mpCancel := context.WithTimeout(shutdownCtx, 10*time.Second)
-			defer mpCancel()
-			shutdownErr := mp.Shutdown(mpCtx)
-			if shutdownErr != nil {
-				return fmt.Errorf("failed to gracefully shut down metrics exporter: %w", shutdownErr)
-			}
-			return nil
-		})
-	} else {
-		otel.SetMeterProvider(metricnoop.NewMeterProvider())
-	}
-
-	return shutdownFns, httpClient, nil
-}

backend/internal/bootstrap/router_bootstrap.go

@@ -4,7 +4,7 @@ import (
 	"context"
 	"errors"
 	"fmt"
-	"log"
+	"log/slog"
 	"net"
 	"net/http"
 	"os"
@@ -12,13 +12,13 @@ import (
 	"strings"
 	"time"
 
-	"github.com/pocket-id/pocket-id/backend/frontend"
-
 	"github.com/gin-gonic/gin"
+	sloggin "github.com/samber/slog-gin"
 	"go.opentelemetry.io/contrib/instrumentation/github.com/gin-gonic/gin/otelgin"
 	"golang.org/x/time/rate"
 	"gorm.io/gorm"
 
+	"github.com/pocket-id/pocket-id/backend/frontend"
 	"github.com/pocket-id/pocket-id/backend/internal/common"
 	"github.com/pocket-id/pocket-id/backend/internal/controller"
 	"github.com/pocket-id/pocket-id/backend/internal/middleware"
@@ -32,7 +32,8 @@ var registerTestControllers []func(apiGroup *gin.RouterGroup, db *gorm.DB, svc *
 func initRouter(db *gorm.DB, svc *services) utils.Service {
 	runner, err := initRouterInternal(db, svc)
 	if err != nil {
-		log.Fatalf("failed to init router: %v", err)
+		slog.Error("Failed to init router", "error", err)
+		os.Exit(1)
 	}
 	return runner
 }
@@ -60,21 +61,25 @@ func initRouterInternal(db *gorm.DB, svc *services) (utils.Service, error) {
 	}
 
 	r := gin.New()
-	r.Use(gin.LoggerWithConfig(gin.LoggerConfig{Skip: func(c *gin.Context) bool {
-		for _, prefix := range loggerSkipPathsPrefix {
-			if strings.HasPrefix(c.Request.Method+" "+c.Request.URL.String(), prefix) {
+	r.Use(sloggin.NewWithConfig(slog.Default(), sloggin.Config{
+		Filters: []sloggin.Filter{
+			func(c *gin.Context) bool {
+				for _, prefix := range loggerSkipPathsPrefix {
+					if strings.HasPrefix(c.Request.Method+" "+c.Request.URL.String(), prefix) {
+						return false
+					}
+				}
 				return true
-			}
-		}
-		return false
-	}}))
+			},
+		},
+	}))
 
 	if !common.EnvConfig.TrustProxy {
 		_ = r.SetTrustedProxies(nil)
 	}
 
 	if common.EnvConfig.TracingEnabled {
-		r.Use(otelgin.Middleware("pocket-id-backend"))
+		r.Use(otelgin.Middleware(common.Name))
 	}
 
 	rateLimitMiddleware := middleware.NewRateLimitMiddleware().Add(rate.Every(time.Second), 60)
@@ -85,7 +90,7 @@ func initRouterInternal(db *gorm.DB, svc *services) (utils.Service, error) {
 
 	err := frontend.RegisterFrontend(r)
 	if errors.Is(err, frontend.ErrFrontendNotIncluded) {
-		log.Println("Frontend is not included in the build. Skipping frontend registration.")
+		slog.Warn("Frontend is not included in the build. Skipping frontend registration.")
 	} else if err != nil {
 		return nil, fmt.Errorf("failed to register frontend: %w", err)
 	}
@@ -154,7 +159,7 @@ func initRouterInternal(db *gorm.DB, svc *services) (utils.Service, error) {
 
 	// Service runner function
 	runFn := func(ctx context.Context) error {
-		log.Printf("Server listening on %s", addr)
+		slog.Info("Server listening", slog.String("addr", addr))
 
 		// Start the server in a background goroutine
 		go func() {
@@ -163,7 +168,8 @@ func initRouterInternal(db *gorm.DB, svc *services) (utils.Service, error) {
 			// Next call blocks until the server is shut down
 			srvErr := srv.Serve(listener)
 			if srvErr != http.ErrServerClosed {
-				log.Fatalf("Error starting app server: %v", srvErr)
+				slog.Error("Error starting app server", "error", srvErr)
+				os.Exit(1)
 			}
 		}()
 
@@ -171,7 +177,7 @@ func initRouterInternal(db *gorm.DB, svc *services) (utils.Service, error) {
 		err = systemd.SdNotifyReady()
 		if err != nil {
 			// Log the error only
-			log.Printf("[WARN] Unable to notify systemd that the service is ready: %v", err)
+			slog.Warn("Unable to notify systemd that the service is ready", "error", err)
 		}
 
 		// Block until the context is canceled
@@ -184,7 +190,7 @@ func initRouterInternal(db *gorm.DB, svc *services) (utils.Service, error) {
 		shutdownCancel()
 		if shutdownErr != nil {
 			// Log the error only (could be context canceled)
-			log.Printf("[WARN] App server shutdown error: %v", shutdownErr)
+			slog.Warn("App server shutdown error", "error", shutdownErr)
 		}
 
 		return nil

backend/internal/bootstrap/services_bootstrap.go

@@ -38,7 +38,11 @@ func initServices(ctx context.Context, db *gorm.DB, httpClient *http.Client) (sv
 
 	svc.geoLiteService = service.NewGeoLiteService(httpClient)
 	svc.auditLogService = service.NewAuditLogService(db, svc.appConfigService, svc.emailService, svc.geoLiteService)
-	svc.jwtService = service.NewJwtService(db, svc.appConfigService)
+	svc.jwtService, err = service.NewJwtService(db, svc.appConfigService)
+	if err != nil {
+		return nil, fmt.Errorf("failed to create JWT service: %w", err)
+	}
+
 	svc.userService = service.NewUserService(db, svc.jwtService, svc.auditLogService, svc.emailService, svc.appConfigService)
 	svc.customClaimService = service.NewCustomClaimService(db)