fix: reorder logger & recoverer middleware & add request-logger tests

internal/api/api.go

@@ -98,21 +98,20 @@ func NewAPIWithVersion(ctx context.Context, globalConfig *conf.GlobalConfigurati
 	logger := observability.NewStructuredLogger(logrus.StandardLogger(), globalConfig)
 
 	r := newRouter()
+	r.UseBypass(observability.AddRequestID(globalConfig))
+	r.UseBypass(logger)
+	r.UseBypass(xffmw.Handler)
+	r.UseBypass(recoverer)
 
 	if globalConfig.API.MaxRequestDuration > 0 {
 		r.UseBypass(api.timeoutMiddleware(globalConfig.API.MaxRequestDuration))
 	}
 
-	r.Use(addRequestID(globalConfig))
-
 	// request tracing should be added only when tracing or metrics is enabled
 	if globalConfig.Tracing.Enabled || globalConfig.Metrics.Enabled {
 		r.UseBypass(observability.RequestTracing())
 	}
 
-	r.UseBypass(xffmw.Handler)
-	r.UseBypass(recoverer)
-
 	if globalConfig.DB.CleanupEnabled {
 		cleanup := models.NewCleanup(globalConfig)
 		r.UseBypass(api.databaseCleanup(cleanup))
@@ -121,7 +120,6 @@ func NewAPIWithVersion(ctx context.Context, globalConfig *conf.GlobalConfigurati
 	r.Get("/health", api.HealthCheck)
 
 	r.Route("/callback", func(r *router) {
-		r.UseBypass(logger)
 		r.Use(api.isValidExternalHost)
 		r.Use(api.loadFlowState)
 
@@ -130,7 +128,6 @@ func NewAPIWithVersion(ctx context.Context, globalConfig *conf.GlobalConfigurati
 	})
 
 	r.Route("/", func(r *router) {
-		r.UseBypass(logger)
 		r.Use(api.isValidExternalHost)
 
 		r.Get("/settings", api.Settings)

internal/api/helpers.go

@@ -6,25 +6,12 @@ import (
 	"fmt"
 	"net/http"
 
-	"github.com/gofrs/uuid"
 	"github.com/pkg/errors"
 	"github.com/supabase/auth/internal/conf"
 	"github.com/supabase/auth/internal/models"
 	"github.com/supabase/auth/internal/utilities"
 )
 
-func addRequestID(globalConfig *conf.GlobalConfiguration) middlewareHandler {
-	return func(w http.ResponseWriter, r *http.Request) (context.Context, error) {
-		id := uuid.Must(uuid.NewV4()).String()
-		if globalConfig.API.RequestIDHeader != "" {
-			id = r.Header.Get(globalConfig.API.RequestIDHeader)
-		}
-		ctx := r.Context()
-		ctx = utilities.WithRequestID(ctx, id)
-		return ctx, nil
-	}
-}
-
 func sendJSON(w http.ResponseWriter, status int, obj interface{}) error {
 	w.Header().Set("Content-Type", "application/json")
 	b, err := json.Marshal(obj)

internal/observability/request-logger.go

@@ -6,11 +6,27 @@ import (
 	"time"
 
 	chimiddleware "github.com/go-chi/chi/middleware"
+	"github.com/gofrs/uuid"
 	"github.com/sirupsen/logrus"
 	"github.com/supabase/auth/internal/conf"
 	"github.com/supabase/auth/internal/utilities"
 )
 
+func AddRequestID(globalConfig *conf.GlobalConfiguration) func(next http.Handler) http.Handler {
+	return func(next http.Handler) http.Handler {
+		fn := func(w http.ResponseWriter, r *http.Request) {
+			id := uuid.Must(uuid.NewV4()).String()
+			if globalConfig.API.RequestIDHeader != "" {
+				id = r.Header.Get(globalConfig.API.RequestIDHeader)
+			}
+			ctx := r.Context()
+			ctx = utilities.WithRequestID(ctx, id)
+			next.ServeHTTP(w, r.WithContext(ctx))
+		}
+		return http.HandlerFunc(fn)
+	}
+}
+
 func NewStructuredLogger(logger *logrus.Logger, config *conf.GlobalConfiguration) func(next http.Handler) http.Handler {
 	return chimiddleware.RequestLogger(&structuredLogger{logger, config})
 }

internal/observability/request-logger_test.go

@@ -0,0 +1,48 @@
+package observability
+
+import (
+	"bytes"
+	"encoding/json"
+	"net/http"
+	"net/http/httptest"
+	"testing"
+
+	"github.com/sirupsen/logrus"
+	"github.com/stretchr/testify/require"
+	"github.com/supabase/auth/internal/conf"
+)
+
+const apiTestConfig = "../../hack/test.env"
+
+func TestLogger(t *testing.T) {
+	logger := logrus.StandardLogger()
+	var logBuffer bytes.Buffer
+	config, err := conf.LoadGlobal(apiTestConfig)
+	require.NoError(t, err)
+
+	config.Logging.Level = "info"
+	require.NoError(t, ConfigureLogging(&config.Logging))
+
+	// add request id header
+	config.API.RequestIDHeader = "X-Request-ID"
+	addRequestIdHandler := AddRequestID(config)
+	// logrus should write to the buffer so we can check if the logs are output correctly
+	logger.SetOutput(&logBuffer)
+	logHandler := NewStructuredLogger(logger, config)(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		w.WriteHeader(http.StatusOK)
+	}))
+	w := httptest.NewRecorder()
+	req, err := http.NewRequest(http.MethodPost, "http://example.com/path", nil)
+	req.Header.Add("X-Request-ID", "test-request-id")
+	require.NoError(t, err)
+	addRequestIdHandler(logHandler).ServeHTTP(w, req)
+	require.Equal(t, http.StatusOK, w.Code)
+
+	var logs map[string]interface{}
+	require.NoError(t, json.NewDecoder(&logBuffer).Decode(&logs))
+	require.Equal(t, "api", logs["component"])
+	require.Equal(t, http.MethodPost, logs["method"])
+	require.Equal(t, "/path", logs["path"])
+	require.Equal(t, "test-request-id", logs["request_id"])
+	require.NotNil(t, logs["time"])
+}