refactor: standardize API error handling (#1635)

backend/internal/bootstrap/router_bootstrap.go

@@ -20,6 +20,7 @@ import (
 	"github.com/italypaleale/francis/builtin/ratelimit"
 	"github.com/italypaleale/go-kit/servicerunner"
 	"go.opentelemetry.io/contrib/instrumentation/github.com/gin-gonic/gin/otelgin"
+	"go.opentelemetry.io/otel/trace"
 	"gorm.io/gorm"
 
 	"github.com/pocket-id/pocket-id/backend/frontend"
@@ -404,6 +405,12 @@ func initLogger(r *gin.Engine) {
 		sloggin.WithLogger(func(_ *gin.Context, _ *slog.Logger) *slog.Logger {
 			return slog.Default()
 		}),
+		sloggin.WithClientErrorLevel(slog.LevelInfo),
+		sloggin.WithSpecificLogLevelByStatusCode(map[int]slog.Level{
+			http.StatusTooManyRequests: slog.LevelWarn,
+		}),
+		sloggin.WithContext(enrichRequestLog),
+		// Skip logging for certain paths to reduce noise in the logs
 		sloggin.WithSkipper(func(c *gin.Context) bool {
 			for _, prefix := range loggerSkipPathsPrefix {
 				if strings.HasPrefix(c.Request.Method+" "+c.Request.URL.String(), prefix) {
@@ -415,6 +422,33 @@ func initLogger(r *gin.Engine) {
 	))
 }
 
+// enrichRequestLog enriches the slog.Record with additional attributes from the request context, such as request ID, error code, and trace/span IDs.
+func enrichRequestLog(c *gin.Context, record *slog.Record) *slog.Record {
+	enriched := slog.NewRecord(record.Time, record.Level, "HTTP request completed", record.PC)
+	// Add request ID if present in the context
+	if requestID := middleware.RequestID(c); requestID != "" {
+		enriched.AddAttrs(slog.String("request_id", requestID))
+	}
+	// Add error code if present in the context
+	if errorCode := middleware.RequestErrorCode(c); errorCode != "" {
+		enriched.AddAttrs(slog.String("error_code", string(errorCode)))
+	}
+
+	// Add trace and span IDs if present in the context
+	if spanContext := trace.SpanFromContext(c.Request.Context()).SpanContext(); spanContext.IsValid() {
+		enriched.AddAttrs(
+			slog.String("trace_id", spanContext.TraceID().String()),
+			slog.String("span_id", spanContext.SpanID().String()),
+		)
+	}
+	record.Attrs(func(attr slog.Attr) bool {
+		enriched.AddAttrs(attr)
+		return true
+	})
+
+	return &enriched
+}
+
 // tlsCertProvider holds certificates that can be dynamically reloaded
 type tlsCertProvider struct {
 	certMutex   sync.RWMutex

backend/internal/bootstrap/router_bootstrap_test.go

@@ -0,0 +1,80 @@
+package bootstrap
+
+import (
+	"bytes"
+	"encoding/json"
+	"log/slog"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	"github.com/gin-gonic/gin"
+	"github.com/pocket-id/pocket-id/backend/internal/apperror"
+	"github.com/pocket-id/pocket-id/backend/internal/middleware"
+	"github.com/stretchr/testify/require"
+)
+
+func TestRequestLoggerUsesStructuredErrorMetadata(t *testing.T) {
+	gin.SetMode(gin.TestMode)
+
+	var output bytes.Buffer
+	previousLogger := slog.Default()
+	slog.SetDefault(slog.New(slog.NewTextHandler(&output, nil)))
+	t.Cleanup(func() {
+		slog.SetDefault(previousLogger)
+	})
+
+	router := gin.New()
+	initLogger(router)
+	router.Use(middleware.NewErrorHandlerMiddleware().Add())
+	router.GET("/api/users/me", func(c *gin.Context) {
+		_ = c.Error(apperror.NotSignedIn())
+		c.Abort()
+	})
+
+	recorder := httptest.NewRecorder()
+	request := httptest.NewRequestWithContext(t.Context(), http.MethodGet, "/api/users/me", nil)
+	router.ServeHTTP(recorder, request)
+
+	var body struct {
+		RequestID string `json:"request_id"`
+	}
+	require.NoError(t, json.Unmarshal(recorder.Body.Bytes(), &body))
+	require.NotEmpty(t, body.RequestID)
+
+	logLine := output.String()
+	require.Contains(t, logLine, "level=INFO")
+	require.Contains(t, logLine, `msg="HTTP request completed"`)
+	require.Contains(t, logLine, "request_id="+body.RequestID)
+	require.Contains(t, logLine, "error_code=not_signed_in")
+	require.Contains(t, logLine, "status=401")
+	require.NotContains(t, logLine, "Request with errors")
+	require.NotContains(t, logLine, "Error #01")
+}
+
+func TestRequestLoggerKeepsRateLimitsAtWarningLevel(t *testing.T) {
+	gin.SetMode(gin.TestMode)
+
+	var output bytes.Buffer
+	previousLogger := slog.Default()
+	slog.SetDefault(slog.New(slog.NewTextHandler(&output, nil)))
+	t.Cleanup(func() {
+		slog.SetDefault(previousLogger)
+	})
+
+	router := gin.New()
+	initLogger(router)
+	router.Use(middleware.NewErrorHandlerMiddleware().Add())
+	router.GET("/api/limited", func(c *gin.Context) {
+		_ = c.Error(apperror.TooManyRequests())
+		c.Abort()
+	})
+
+	recorder := httptest.NewRecorder()
+	request := httptest.NewRequestWithContext(t.Context(), http.MethodGet, "/api/limited", nil)
+	router.ServeHTTP(recorder, request)
+
+	require.Equal(t, http.StatusTooManyRequests, recorder.Code)
+	require.Contains(t, output.String(), "level=WARN")
+	require.Contains(t, output.String(), "error_code=rate_limited")
+}