fix: improve logging structure (#1583)

## What kind of change does this PR introduce?
* Remove unformatted logs which do not confirm to JSON
* Previously, we were logging both `time` (not UTC) and `timestamp` (in
UTC) which is redundant. I've opted to remove `timestamp` and just log
the UTC time as the `time` field, which is supported by logrus
* Previously, the `request_id` was not being logged because it was
unable to retrieve the context properly. Now, the `request_id` field is
added to every log entry, which allows us to filter by `request_id` to
see the entire lifecycle of the request
* Previously, panics weren't being handled properly and they were just
logged as text instead of JSON. The server would return an empty reply,
which leads to ugly responses like "Unexpected token < in JSON..." if
using fetch in JS. Now, the server returns a proper 500 error response:
`{"code":500,"error_code":"unexpected_failure","msg":"Internal Server
Error"}`
* Added tests for `recoverer` and `NewStructuredLogger` to prevent
regression
* Remove "request started" log since the `request_id` can be used to
keep track of the entire request lifecycle. This cuts down on the noise
to signal ratio as well.


## Log format
* Panics are now logged like this (note the additional fields like
`panic` and `stack` - which is a dump of the stack trace):
```json
{
  "component":"api",
  "duration":6065700500,
  "level":"info",
  "method":"GET",
  "msg":"request completed",
  "panic":"test panic",
  "path":"/panic",
  "referer":"http://localhost:3001",
  "remote_addr":"127.0.0.1",
  "request_id":"4cde5f20-2c3c-4645-bc75-52d6231e22e2",
  "stack":"goroutine 82 [running]:...rest of stack trace omitted for brevity",
  "status":500,
  "time":"2024-05-15T09:37:42Z"
}
```

* Requests that call `NewAuditLogEntry` will be logged with the
`auth_event` payload in this format (note that the timestamp field no
longer exists)
```json
{
  "auth_event": {
    "action": "token_refreshed",
    "actor_id": "733fb34d-a6f2-43e1-976a-8e6a456b6889",
    "actor_name": "Kang Ming Tay",
    "actor_username": "kang.ming1996@gmail.com",
    "actor_via_sso": false,
    "log_type": "token"
  },
  "component": "api",
  "duration": 75945042,
  "level": "info",
  "method": "POST",
  "msg": "request completed",
  "path": "/token",
  "referer": "http://localhost:3001",
  "remote_addr": "127.0.0.1",
  "request_id": "08c7e47b-42f4-44dc-a39b-7275ef5bbb45",
  "status": 200,
  "time": "2024-05-15T09:40:09Z"
}
```

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.Use(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/auth.go

@@ -4,7 +4,7 @@ import (
 	"context"
 	"fmt"
 	"net/http"
-	"time"
+	"strings"
 
 	"github.com/gofrs/uuid"
 	jwt "github.com/golang-jwt/jwt"
@@ -44,11 +44,10 @@ func (a *API) requireNotAnonymous(w http.ResponseWriter, r *http.Request) (conte
 	return ctx, nil
 }
 
-func (a *API) requireAdmin(ctx context.Context, r *http.Request) (context.Context, error) {
+func (a *API) requireAdmin(ctx context.Context) (context.Context, error) {
 	// Find the administrative user
 	claims := getClaims(ctx)
 	if claims == nil {
-		fmt.Printf("[%s] %s %s %d %s\n", time.Now().Format("2006-01-02 15:04:05"), r.Method, r.RequestURI, http.StatusForbidden, "Invalid token")
 		return nil, forbiddenError(ErrorCodeBadJWT, "Invalid token")
 	}
 
@@ -59,8 +58,7 @@ func (a *API) requireAdmin(ctx context.Context, r *http.Request) (context.Contex
 		return withAdminUser(ctx, &models.User{Role: claims.Role, Email: storage.NullString(claims.Role)}), nil
 	}
 
-	fmt.Printf("[%s] %s %s %d %s\n", time.Now().Format("2006-01-02 15:04:05"), r.Method, r.RequestURI, http.StatusForbidden, "this token needs role 'supabase_admin' or 'service_role'")
-	return nil, forbiddenError(ErrorCodeNotAdmin, "User not allowed")
+	return nil, forbiddenError(ErrorCodeNotAdmin, "User not allowed").WithInternalMessage(fmt.Sprintf("this token needs to have one of the following roles: %v", strings.Join(adminRoles, ", ")))
 }
 
 func (a *API) extractBearerToken(r *http.Request) (string, error) {

internal/api/context.go

@@ -16,7 +16,6 @@ func (c contextKey) String() string {
 
 const (
 	tokenKey                = contextKey("jwt")
-	requestIDKey            = contextKey("request_id")
 	inviteTokenKey          = contextKey("invite_token")
 	signatureKey            = contextKey("signature")
 	externalProviderTypeKey = contextKey("external_provider_type")
@@ -57,21 +56,6 @@ func getClaims(ctx context.Context) *AccessTokenClaims {
 	return token.Claims.(*AccessTokenClaims)
 }
 
-// withRequestID adds the provided request ID to the context.
-func withRequestID(ctx context.Context, id string) context.Context {
-	return context.WithValue(ctx, requestIDKey, id)
-}
-
-// getRequestID reads the request ID from the context.
-func getRequestID(ctx context.Context) string {
-	obj := ctx.Value(requestIDKey)
-	if obj == nil {
-		return ""
-	}
-
-	return obj.(string)
-}
-
 // withUser adds the user to the context.
 func withUser(ctx context.Context, u *models.User) context.Context {
 	return context.WithValue(ctx, userKey, u)

internal/api/errors.go

@@ -148,27 +148,28 @@ func httpError(httpStatus int, errorCode ErrorCode, fmtString string, args ...in
 // Recoverer is a middleware that recovers from panics, logs the panic (and a
 // backtrace), and returns a HTTP 500 (Internal Server Error) status if
 // possible. Recoverer prints a request ID if one is provided.
-func recoverer(w http.ResponseWriter, r *http.Request) (context.Context, error) {
-	defer func() {
-		if rvr := recover(); rvr != nil {
-
-			logEntry := observability.GetLogEntry(r)
-			if logEntry != nil {
-				logEntry.Panic(rvr, debug.Stack())
-			} else {
-				fmt.Fprintf(os.Stderr, "Panic: %+v\n", rvr)
-				debug.PrintStack()
-			}
+func recoverer(next http.Handler) http.Handler {
+	fn := func(w http.ResponseWriter, r *http.Request) {
+		defer func() {
+			if rvr := recover(); rvr != nil {
+				logEntry := observability.GetLogEntry(r)
+				if logEntry != nil {
+					logEntry.Panic(rvr, debug.Stack())
+				} else {
+					fmt.Fprintf(os.Stderr, "Panic: %+v\n", rvr)
+					debug.PrintStack()
+				}
 
-			se := &HTTPError{
-				HTTPStatus: http.StatusInternalServerError,
-				Message:    http.StatusText(http.StatusInternalServerError),
+				se := &HTTPError{
+					HTTPStatus: http.StatusInternalServerError,
+					Message:    http.StatusText(http.StatusInternalServerError),
+				}
+				HandleResponseError(se, w, r)
 			}
-			HandleResponseError(se, w, r)
-		}
-	}()
-
-	return nil, nil
+		}()
+		next.ServeHTTP(w, r)
+	}
+	return http.HandlerFunc(fn)
 }
 
 // ErrorCause is an error interface that contains the method Cause() for returning root cause errors
@@ -182,8 +183,8 @@ type HTTPErrorResponse20240101 struct {
 }
 
 func HandleResponseError(err error, w http.ResponseWriter, r *http.Request) {
-	log := observability.GetLogEntry(r)
-	errorID := getRequestID(r.Context())
+	log := observability.GetLogEntry(r).Entry
+	errorID := utilities.GetRequestID(r.Context())
 
 	apiVersion, averr := DetermineClosestAPIVersion(r.Header.Get(APIVersionHeaderName))
 	if averr != nil {

internal/api/errors_test.go

@@ -1,11 +1,16 @@
 package api
 
 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"
+	"github.com/supabase/auth/internal/observability"
 )
 
 func TestHandleResponseErrorWithHTTPError(t *testing.T) {
@@ -62,3 +67,39 @@ func TestHandleResponseErrorWithHTTPError(t *testing.T) {
 		require.Equal(t, example.ExpectedBody, rec.Body.String())
 	}
 }
+
+func TestRecoverer(t *testing.T) {
+	var logBuffer bytes.Buffer
+	config, err := conf.LoadGlobal(apiTestConfig)
+	require.NoError(t, err)
+	require.NoError(t, observability.ConfigureLogging(&config.Logging))
+
+	// logrus should write to the buffer so we can check if the logs are output correctly
+	logrus.SetOutput(&logBuffer)
+	panicHandler := recoverer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+		panic("test panic")
+	}))
+
+	w := httptest.NewRecorder()
+	req, err := http.NewRequest(http.MethodPost, "http://example.com", nil)
+	require.NoError(t, err)
+
+	panicHandler.ServeHTTP(w, req)
+
+	require.Equal(t, http.StatusInternalServerError, w.Code)
+
+	var data HTTPError
+
+	// panic should return an internal server error
+	require.NoError(t, json.NewDecoder(w.Body).Decode(&data))
+	require.Equal(t, ErrorCodeUnexpectedFailure, data.ErrorCode)
+	require.Equal(t, http.StatusInternalServerError, data.HTTPStatus)
+	require.Equal(t, "Internal Server Error", data.Message)
+
+	// panic should log the error message internally
+	var logs map[string]interface{}
+	require.NoError(t, json.NewDecoder(&logBuffer).Decode(&logs))
+	require.Equal(t, "request panicked", logs["msg"])
+	require.Equal(t, "test panic", logs["panic"])
+	require.NotEmpty(t, logs["stack"])
+}

internal/api/external.go

@@ -71,7 +71,7 @@ func (a *API) GetExternalProviderRedirectURL(w http.ResponseWriter, r *http.Requ
 	}
 
 	redirectURL := utilities.GetReferrer(r, config)
-	log := observability.GetLogEntry(r)
+	log := observability.GetLogEntry(r).Entry
 	log.WithField("provider", providerType).Info("Redirecting to external provider")
 	if err := validatePKCEParams(codeChallengeMethod, codeChallenge); err != nil {
 		return "", err
@@ -573,8 +573,8 @@ func (a *API) Provider(ctx context.Context, name string, scopes string) (provide
 
 func (a *API) redirectErrors(handler apiHandler, w http.ResponseWriter, r *http.Request, u *url.URL) {
 	ctx := r.Context()
-	log := observability.GetLogEntry(r)
-	errorID := getRequestID(ctx)
+	log := observability.GetLogEntry(r).Entry
+	errorID := utilities.GetRequestID(ctx)
 	err := handler(w, r)
 	if err != nil {
 		q := getErrorQueryString(err, errorID, log, u.Query())

internal/api/external_oauth.go

@@ -69,7 +69,7 @@ func (a *API) oAuthCallback(ctx context.Context, r *http.Request, providerType s
 		return nil, badRequestError(ErrorCodeOAuthProviderNotSupported, "Unsupported provider: %+v", err).WithInternalError(err)
 	}
 
-	log := observability.GetLogEntry(r)
+	log := observability.GetLogEntry(r).Entry
 	log.WithFields(logrus.Fields{
 		"provider": providerType,
 		"code":     oauthCode,

internal/api/helpers.go

@@ -6,30 +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 := ""
-		if globalConfig.API.RequestIDHeader != "" {
-			id = r.Header.Get(globalConfig.API.RequestIDHeader)
-		}
-		if id == "" {
-			uid := uuid.Must(uuid.NewV4())
-			id = uid.String()
-		}
-
-		ctx := r.Context()
-		ctx = 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/api/hooks.go

@@ -85,7 +85,7 @@ func (a *API) runHTTPHook(r *http.Request, hookConfig conf.ExtensibilityPointCon
 	ctx, cancel := context.WithTimeout(ctx, DefaultHTTPHookTimeout)
 	defer cancel()
 
-	log := observability.GetLogEntry(r)
+	log := observability.GetLogEntry(r).Entry
 	requestURL := hookConfig.URI
 	hookLog := log.WithFields(logrus.Fields{
 		"component": "auth_hook",

internal/api/middleware.go

@@ -62,7 +62,7 @@ func (a *API) limitHandler(lmt *limiter.Limiter) middlewareHandler {
 			key := req.Header.Get(limitHeader)
 
 			if key == "" {
-				log := observability.GetLogEntry(req)
+				log := observability.GetLogEntry(req).Entry
 				log.WithField("header", limitHeader).Warn("request does not have a value for the rate limiting header, rate limiting is not applied")
 				return c, nil
 			} else {
@@ -145,7 +145,7 @@ func (a *API) requireAdminCredentials(w http.ResponseWriter, req *http.Request)
 		return nil, err
 	}
 
-	return a.requireAdmin(ctx, req)
+	return a.requireAdmin(ctx)
 }
 
 func (a *API) requireEmailProvider(w http.ResponseWriter, req *http.Request) (context.Context, error) {
@@ -212,7 +212,7 @@ func (a *API) isValidExternalHost(w http.ResponseWriter, req *http.Request) (con
 	}
 	if u, err = url.ParseRequestURI(baseUrl); err != nil {
 		// fallback to the default hostname
-		log := observability.GetLogEntry(req)
+		log := observability.GetLogEntry(req).Entry
 		log.WithField("request_url", baseUrl).Warn(err)
 		if u, err = url.ParseRequestURI(config.API.ExternalURL); err != nil {
 			return ctx, err
@@ -251,7 +251,7 @@ func (a *API) databaseCleanup(cleanup *models.Cleanup) func(http.Handler) http.H
 			}
 
 			db := a.db.WithContext(r.Context())
-			log := observability.GetLogEntry(r)
+			log := observability.GetLogEntry(r).Entry
 
 			affectedRows, err := cleanup.Clean(db)
 			if err != nil {

internal/api/samlacs.go

@@ -49,7 +49,7 @@ func (a *API) SAMLACS(w http.ResponseWriter, r *http.Request) error {
 
 	db := a.db.WithContext(ctx)
 	config := a.config
-	log := observability.GetLogEntry(r)
+	log := observability.GetLogEntry(r).Entry
 
 	relayStateValue := r.FormValue("RelayState")
 	relayStateUUID := uuid.FromStringOrNil(relayStateValue)

internal/api/token.go

@@ -153,7 +153,7 @@ func (a *API) ResourceOwnerPasswordGrant(ctx context.Context, w http.ResponseWri
 			if wpe, ok := err.(*WeakPasswordError); ok {
 				weakPasswordError = wpe
 			} else {
-				observability.GetLogEntry(r).WithError(err).Warn("Password strength check on sign-in failed")
+				observability.GetLogEntry(r).Entry.WithError(err).Warn("Password strength check on sign-in failed")
 			}
 		}
 	}

internal/api/token_oidc.go

@@ -25,7 +25,7 @@ type IdTokenGrantParams struct {
 }
 
 func (p *IdTokenGrantParams) getProvider(ctx context.Context, config *conf.GlobalConfiguration, r *http.Request) (*oidc.Provider, *conf.OAuthProviderConfiguration, string, []string, error) {
-	log := observability.GetLogEntry(r)
+	log := observability.GetLogEntry(r).Entry
 
 	var cfg *conf.OAuthProviderConfiguration
 	var issuer string
@@ -113,7 +113,7 @@ func (p *IdTokenGrantParams) getProvider(ctx context.Context, config *conf.Globa
 
 // IdTokenGrant implements the id_token grant type flow
 func (a *API) IdTokenGrant(ctx context.Context, w http.ResponseWriter, r *http.Request) error {
-	log := observability.GetLogEntry(r)
+	log := observability.GetLogEntry(r).Entry
 
 	db := a.db.WithContext(ctx)
 	config := a.config

internal/api/verify.go

@@ -433,8 +433,8 @@ func (a *API) prepErrorRedirectURL(err *HTTPError, r *http.Request, rurl string,
 
 	// Maintain separate query params for hash and query
 	hq := url.Values{}
-	log := observability.GetLogEntry(r)
-	errorID := getRequestID(r.Context())
+	log := observability.GetLogEntry(r).Entry
+	errorID := utilities.GetRequestID(r.Context())
 	err.ErrorID = errorID
 	log.WithError(err.Cause()).Info(err.Error())
 	if str, ok := oauthErrorMap[err.HTTPStatus]; ok {