Repository: supabase/gotrue
Pull request #562 (2022-07-23 08:40:29)

fix: standardise logging format to use json 
## What kind of change does this PR introduce?
* standardise logging format to use JSON
* moved logging setup into it's own package to make it easier to use across other packages
* new logging format for auth events will follow:
```bash
{"auth_event":{"action":"user_signedup","actor_id":"c93b6eb0-4af8-4247-84a9-00c88c041b75","actor_username":"foo@example.com","log_type":"team"},"component":"api","duration":386683041,"level":"info","method":"GET","msg":"request completed","path":"/callback","referer":"","remote_addr":"127.0.0.1:54356","status":302,"timestamp":"2022-07-23T08:33:22Z"}

```

kangmingtay: @chasers lmk if this is easier for you to parse - we can also change the logging key from `auth_event` to something else to make it more explicit if you want
chasers: @burmecia FYI
kangmingtay: i've also removed the timestamp field from `auth.audit_log_entries->>'payload'` because there's already a column called `created_at` which is basically the same thing 

Patch:
diff --git a/api/admin.go b/api/admin.go
index 2134ce2d..7671b271 100644
--- a/api/admin.go
+++ b/api/admin.go
@@ -10,6 +10,7 @@ import (
 
 	"github.com/go-chi/chi"
 	"github.com/gofrs/uuid"
+	"github.com/netlify/gotrue/logger"
 	"github.com/netlify/gotrue/models"
 	"github.com/netlify/gotrue/storage"
 	"github.com/sethvargo/go-password/password"
@@ -34,7 +35,7 @@ func (a *API) loadUser(w http.ResponseWriter, r *http.Request) (context.Context,
 		return nil, badRequestError("user_id must be an UUID")
 	}
 
-	logEntrySetField(r, "user_id", userID)
+	logger.LogEntrySetField(r, "user_id", userID)
 	instanceID := getInstanceID(r.Context())
 
 	u, err := models.FindUserByInstanceIDAndID(a.db, instanceID, userID)
@@ -175,7 +176,7 @@ func (a *API) adminUserUpdate(w http.ResponseWriter, r *http.Request) error {
 			}
 		}
 
-		if terr := models.NewAuditLogEntry(tx, instanceID, adminUser, models.UserModifiedAction, "", map[string]interface{}{
+		if terr := models.NewAuditLogEntry(r, tx, instanceID, adminUser, models.UserModifiedAction, "", map[string]interface{}{
 			"user_id":    user.ID,
 			"user_email": user.Email,
 			"user_phone": user.Phone,
@@ -270,7 +271,7 @@ func (a *API) adminUserCreate(w http.ResponseWriter, r *http.Request) error {
 	}
 
 	err = a.db.Transaction(func(tx *storage.Connection) error {
-		if terr := models.NewAuditLogEntry(tx, instanceID, adminUser, models.UserSignedUpAction, "", map[string]interface{}{
+		if terr := models.NewAuditLogEntry(r, tx, instanceID, adminUser, models.UserSignedUpAction, "", map[string]interface{}{
 			"user_id":    user.ID,
 			"user_email": user.Email,
 			"user_phone": user.Phone,
@@ -323,7 +324,7 @@ func (a *API) adminUserDelete(w http.ResponseWriter, r *http.Request) error {
 	adminUser := getAdminUser(ctx)
 
 	err := a.db.Transaction(func(tx *storage.Connection) error {
-		if terr := models.NewAuditLogEntry(tx, instanceID, adminUser, models.UserDeletedAction, "", map[string]interface{}{
+		if terr := models.NewAuditLogEntry(r, tx, instanceID, adminUser, models.UserDeletedAction, "", map[string]interface{}{
 			"user_id":    user.ID,
 			"user_email": user.Email,
 			"user_phone": user.Phone,
diff --git a/api/api.go b/api/api.go
index 116707de..00c061ac 100644
--- a/api/api.go
+++ b/api/api.go
@@ -15,6 +15,7 @@ import (
 	"github.com/gofrs/uuid"
 	"github.com/imdario/mergo"
 	"github.com/netlify/gotrue/conf"
+	"github.com/netlify/gotrue/logger"
 	"github.com/netlify/gotrue/mailer"
 	"github.com/netlify/gotrue/storage"
 	"github.com/rs/cors"
@@ -81,7 +82,7 @@ func NewAPIWithVersion(ctx context.Context, globalConfig *conf.GlobalConfigurati
 	api := &API{config: globalConfig, db: db, version: version}
 
 	xffmw, _ := xff.Default()
-	logger := newStructuredLogger(logrus.StandardLogger())
+	logger := logger.NewStructuredLogger(logrus.StandardLogger())
 
 	r := newRouter()
 	r.UseBypass(xffmw.Handler)
diff --git a/api/errors.go b/api/errors.go
index 335dc4e7..a75e4b08 100644
--- a/api/errors.go
+++ b/api/errors.go
@@ -8,6 +8,7 @@ import (
 	"runtime/debug"
 
 	"github.com/netlify/gotrue/conf"
+	"github.com/netlify/gotrue/logger"
 	"github.com/netlify/gotrue/utilities"
 	"github.com/pkg/errors"
 )
@@ -214,7 +215,7 @@ func recoverer(w http.ResponseWriter, r *http.Request) (context.Context, error)
 	defer func() {
 		if rvr := recover(); rvr != nil {
 
-			logEntry := getLogEntry(r)
+			logEntry := logger.GetLogEntry(r)
 			if logEntry != nil {
 				logEntry.Panic(rvr, debug.Stack())
 			} else {
@@ -239,7 +240,7 @@ type ErrorCause interface {
 }
 
 func handleError(err error, w http.ResponseWriter, r *http.Request) {
-	log := getLogEntry(r)
+	log := logger.GetLogEntry(r)
 	errorID := getRequestID(r.Context())
 	switch e := err.(type) {
 	case *HTTPError:
diff --git a/api/external.go b/api/external.go
index d8516e8a..a2bbbc7a 100644
--- a/api/external.go
+++ b/api/external.go
@@ -14,6 +14,7 @@ import (
 	jwt "github.com/golang-jwt/jwt"
 	"github.com/netlify/gotrue/api/provider"
 	"github.com/netlify/gotrue/conf"
+	"github.com/netlify/gotrue/logger"
 	"github.com/netlify/gotrue/models"
 	"github.com/netlify/gotrue/storage"
 	"github.com/netlify/gotrue/utilities"
@@ -60,7 +61,7 @@ func (a *API) ExternalProviderRedirect(w http.ResponseWriter, r *http.Request) e
 	}
 
 	redirectURL := a.getRedirectURLOrReferrer(r, query.Get("redirect_to"))
-	log := getLogEntry(r)
+	log := logger.GetLogEntry(r)
 	log.WithField("provider", providerType).Info("Redirecting to external provider")
 
 	token := jwt.NewWithClaims(jwt.SigningMethodHS256, ExternalProviderClaims{
@@ -140,7 +141,7 @@ func (a *API) internalExternalProviderCallback(w http.ResponseWriter, r *http.Re
 		var terr error
 		inviteToken := getInviteToken(ctx)
 		if inviteToken != "" {
-			if user, terr = a.processInvite(ctx, tx, userData, instanceID, inviteToken, providerType); terr != nil {
+			if user, terr = a.processInvite(r, ctx, tx, userData, instanceID, inviteToken, providerType); terr != nil {
 				return terr
 			}
 		} else {
@@ -255,7 +256,7 @@ func (a *API) internalExternalProviderCallback(w http.ResponseWriter, r *http.Re
 					return nil
 				}
 
-				if terr := models.NewAuditLogEntry(tx, instanceID, user, models.UserSignedUpAction, "", map[string]interface{}{
+				if terr := models.NewAuditLogEntry(r, tx, instanceID, user, models.UserSignedUpAction, "", map[string]interface{}{
 					"provider": providerType,
 				}); terr != nil {
 					return terr
@@ -269,7 +270,7 @@ func (a *API) internalExternalProviderCallback(w http.ResponseWriter, r *http.Re
 					return internalServerError("Error updating user").WithInternalError(terr)
 				}
 			} else {
-				if terr := models.NewAuditLogEntry(tx, instanceID, user, models.LoginAction, "", map[string]interface{}{
+				if terr := models.NewAuditLogEntry(r, tx, instanceID, user, models.LoginAction, "", map[string]interface{}{
 					"provider": providerType,
 				}); terr != nil {
 					return terr
@@ -311,7 +312,7 @@ func (a *API) internalExternalProviderCallback(w http.ResponseWriter, r *http.Re
 	return nil
 }
 
-func (a *API) processInvite(ctx context.Context, tx *storage.Connection, userData *provider.UserProvidedData, instanceID uuid.UUID, inviteToken, providerType string) (*models.User, error) {
+func (a *API) processInvite(r *http.Request, ctx context.Context, tx *storage.Connection, userData *provider.UserProvidedData, instanceID uuid.UUID, inviteToken, providerType string) (*models.User, error) {
 	config := a.getConfig(ctx)
 	user, err := models.FindUserByConfirmationToken(tx, inviteToken)
 	if err != nil {
@@ -357,7 +358,7 @@ func (a *API) processInvite(ctx context.Context, tx *storage.Connection, userDat
 		return nil, internalServerError("Database error updating user").WithInternalError(err)
 	}
 
-	if err := models.NewAuditLogEntry(tx, instanceID, user, models.InviteAcceptedAction, "", map[string]interface{}{
+	if err := models.NewAuditLogEntry(r, tx, instanceID, user, models.InviteAcceptedAction, "", map[string]interface{}{
 		"provider": providerType,
 	}); err != nil {
 		return nil, err
@@ -443,7 +444,7 @@ func (a *API) Provider(ctx context.Context, name string, scopes string, query *u
 
 func (a *API) redirectErrors(handler apiHandler, w http.ResponseWriter, r *http.Request) {
 	ctx := r.Context()
-	log := getLogEntry(r)
+	log := logger.GetLogEntry(r)
 	errorID := getRequestID(ctx)
 	err := handler(w, r)
 	if err != nil {
diff --git a/api/external_oauth.go b/api/external_oauth.go
index 0e7e72a4..dc645fff 100644
--- a/api/external_oauth.go
+++ b/api/external_oauth.go
@@ -7,6 +7,7 @@ import (
 
 	"github.com/mrjones/oauth"
 	"github.com/netlify/gotrue/api/provider"
+	"github.com/netlify/gotrue/logger"
 	"github.com/netlify/gotrue/storage"
 	"github.com/sirupsen/logrus"
 )
@@ -66,7 +67,7 @@ func (a *API) oAuthCallback(ctx context.Context, r *http.Request, providerType s
 		return nil, badRequestError("Unsupported provider: %+v", err).WithInternalError(err)
 	}
 
-	log := getLogEntry(r)
+	log := logger.GetLogEntry(r)
 	log.WithFields(logrus.Fields{
 		"provider": providerType,
 		"code":     oauthCode,
diff --git a/api/instance.go b/api/instance.go
index f15d4858..178584cb 100644
--- a/api/instance.go
+++ b/api/instance.go
@@ -8,6 +8,7 @@ import (
 	"github.com/go-chi/chi"
 	"github.com/gofrs/uuid"
 	"github.com/netlify/gotrue/conf"
+	"github.com/netlify/gotrue/logger"
 	"github.com/netlify/gotrue/models"
 	"github.com/pkg/errors"
 )
@@ -17,7 +18,7 @@ func (a *API) loadInstance(w http.ResponseWriter, r *http.Request) (context.Cont
 	if err != nil {
 		return nil, badRequestError("Invalid instance ID")
 	}
-	logEntrySetField(r, "instance_id", instanceID)
+	logger.LogEntrySetField(r, "instance_id", instanceID)
 
 	i, err := models.GetInstance(a.db, instanceID)
 	if err != nil {
diff --git a/api/invite.go b/api/invite.go
index 53da7f20..494f7b38 100644
--- a/api/invite.go
+++ b/api/invite.go
@@ -56,7 +56,7 @@ func (a *API) Invite(w http.ResponseWriter, r *http.Request) error {
 			}
 		}
 
-		if terr := models.NewAuditLogEntry(tx, instanceID, adminUser, models.UserInvitedAction, "", map[string]interface{}{
+		if terr := models.NewAuditLogEntry(r, tx, instanceID, adminUser, models.UserInvitedAction, "", map[string]interface{}{
 			"user_id":    user.ID,
 			"user_email": user.Email,
 		}); terr != nil {
diff --git a/api/logout.go b/api/logout.go
index 38e298cf..f6465d3c 100644
--- a/api/logout.go
+++ b/api/logout.go
@@ -21,7 +21,7 @@ func (a *API) Logout(w http.ResponseWriter, r *http.Request) error {
 	}
 
 	err = a.db.Transaction(func(tx *storage.Connection) error {
-		if terr := models.NewAuditLogEntry(tx, instanceID, u, models.LogoutAction, "", nil); terr != nil {
+		if terr := models.NewAuditLogEntry(r, tx, instanceID, u, models.LogoutAction, "", nil); terr != nil {
 			return terr
 		}
 		return models.Logout(tx, instanceID, u.ID)
diff --git a/api/magic_link.go b/api/magic_link.go
index 3cff58e9..60e95e37 100644
--- a/api/magic_link.go
+++ b/api/magic_link.go
@@ -97,7 +97,7 @@ func (a *API) MagicLink(w http.ResponseWriter, r *http.Request) error {
 	}
 
 	err = a.db.Transaction(func(tx *storage.Connection) error {
-		if terr := models.NewAuditLogEntry(tx, instanceID, user, models.UserRecoveryRequestedAction, "", nil); terr != nil {
+		if terr := models.NewAuditLogEntry(r, tx, instanceID, user, models.UserRecoveryRequestedAction, "", nil); terr != nil {
 			return terr
 		}
 
diff --git a/api/mail.go b/api/mail.go
index acea6c29..02725332 100644
--- a/api/mail.go
+++ b/api/mail.go
@@ -79,7 +79,7 @@ func (a *API) GenerateLink(w http.ResponseWriter, r *http.Request) error {
 		var terr error
 		switch params.Type {
 		case magicLinkVerification, recoveryVerification:
-			if terr = models.NewAuditLogEntry(tx, instanceID, user, models.UserRecoveryRequestedAction, "", nil); terr != nil {
+			if terr = models.NewAuditLogEntry(r, tx, instanceID, user, models.UserRecoveryRequestedAction, "", nil); terr != nil {
 				return terr
 			}
 			user.RecoveryToken = hashedToken
@@ -102,7 +102,7 @@ func (a *API) GenerateLink(w http.ResponseWriter, r *http.Request) error {
 					return terr
 				}
 			}
-			if terr = models.NewAuditLogEntry(tx, instanceID, adminUser, models.UserInvitedAction, "", map[string]interface{}{
+			if terr = models.NewAuditLogEntry(r, tx, instanceID, adminUser, models.UserInvitedAction, "", map[string]interface{}{
 				"user_id":    user.ID,
 				"user_email": user.Email,
 			}); terr != nil {
diff --git a/api/middleware.go b/api/middleware.go
index a010e70a..98d68429 100644
--- a/api/middleware.go
+++ b/api/middleware.go
@@ -10,6 +10,7 @@ import (
 	"strings"
 	"time"
 
+	"github.com/netlify/gotrue/logger"
 	"github.com/netlify/gotrue/security"
 	"github.com/sirupsen/logrus"
 
@@ -111,8 +112,8 @@ func (a *API) loadInstanceConfig(w http.ResponseWriter, r *http.Request) (contex
 		return nil, badRequestError("Instance ID is not a valid UUID")
 	}
 
-	logEntrySetField(r, "instance_id", instanceID)
-	logEntrySetField(r, "netlify_id", claims.NetlifyID)
+	logger.LogEntrySetField(r, "instance_id", instanceID)
+	logger.LogEntrySetField(r, "netlify_id", claims.NetlifyID)
 	instance, err := models.GetInstance(a.db, instanceID)
 	if err != nil {
 		if models.IsNotFoundError(err) {
@@ -129,7 +130,7 @@ func (a *API) loadInstanceConfig(w http.ResponseWriter, r *http.Request) (contex
 	if claims.SiteURL != "" {
 		config.SiteURL = claims.SiteURL
 	}
-	logEntrySetField(r, "site_url", config.SiteURL)
+	logger.LogEntrySetField(r, "site_url", config.SiteURL)
 
 	ctx = withNetlifyID(ctx, claims.NetlifyID)
 	ctx = withFunctionHooks(ctx, claims.FunctionHooks)
diff --git a/api/otp.go b/api/otp.go
index 80a17be6..8a204314 100644
--- a/api/otp.go
+++ b/api/otp.go
@@ -140,7 +140,7 @@ func (a *API) SmsOtp(w http.ResponseWriter, r *http.Request) error {
 	}
 
 	err = a.db.Transaction(func(tx *storage.Connection) error {
-		if err := models.NewAuditLogEntry(tx, instanceID, user, models.UserRecoveryRequestedAction, "", nil); err != nil {
+		if err := models.NewAuditLogEntry(r, tx, instanceID, user, models.UserRecoveryRequestedAction, "", nil); err != nil {
 			return err
 		}
 		smsProvider, terr := sms_provider.GetSmsProvider(*config)
diff --git a/api/reauthenticate.go b/api/reauthenticate.go
index 6debc67e..85853149 100644
--- a/api/reauthenticate.go
+++ b/api/reauthenticate.go
@@ -51,7 +51,7 @@ func (a *API) Reauthenticate(w http.ResponseWriter, r *http.Request) error {
 	}
 
 	err = a.db.Transaction(func(tx *storage.Connection) error {
-		if terr := models.NewAuditLogEntry(tx, instanceID, user, models.UserReauthenticateAction, "", nil); terr != nil {
+		if terr := models.NewAuditLogEntry(r, tx, instanceID, user, models.UserReauthenticateAction, "", nil); terr != nil {
 			return terr
 		}
 		if email != "" {
diff --git a/api/recover.go b/api/recover.go
index b2679b13..1292940b 100644
--- a/api/recover.go
+++ b/api/recover.go
@@ -46,7 +46,7 @@ func (a *API) Recover(w http.ResponseWriter, r *http.Request) error {
 	}
 
 	err = a.db.Transaction(func(tx *storage.Connection) error {
-		if terr := models.NewAuditLogEntry(tx, instanceID, user, models.UserRecoveryRequestedAction, "", nil); terr != nil {
+		if terr := models.NewAuditLogEntry(r, tx, instanceID, user, models.UserRecoveryRequestedAction, "", nil); terr != nil {
 			return terr
 		}
 		mailer := a.Mailer(ctx)
diff --git a/api/signup.go b/api/signup.go
index 2cbef93e..a57cde1e 100644
--- a/api/signup.go
+++ b/api/signup.go
@@ -113,7 +113,7 @@ func (a *API) Signup(w http.ResponseWriter, r *http.Request) error {
 
 		if params.Provider == "email" && !user.IsConfirmed() {
 			if config.Mailer.Autoconfirm {
-				if terr = models.NewAuditLogEntry(tx, instanceID, user, models.UserSignedUpAction, "", map[string]interface{}{
+				if terr = models.NewAuditLogEntry(r, tx, instanceID, user, models.UserSignedUpAction, "", map[string]interface{}{
 					"provider": params.Provider,
 				}); terr != nil {
 					return terr
@@ -127,7 +127,7 @@ func (a *API) Signup(w http.ResponseWriter, r *http.Request) error {
 			} else {
 				mailer := a.Mailer(ctx)
 				referrer := a.getReferrer(r)
-				if terr = models.NewAuditLogEntry(tx, instanceID, user, models.UserConfirmationRequestedAction, "", map[string]interface{}{
+				if terr = models.NewAuditLogEntry(r, tx, instanceID, user, models.UserConfirmationRequestedAction, "", map[string]interface{}{
 					"provider": params.Provider,
 				}); terr != nil {
 					return terr
@@ -143,7 +143,7 @@ func (a *API) Signup(w http.ResponseWriter, r *http.Request) error {
 			}
 		} else if params.Provider == "phone" && !user.IsPhoneConfirmed() {
 			if config.Sms.Autoconfirm {
-				if terr = models.NewAuditLogEntry(tx, instanceID, user, models.UserSignedUpAction, "", map[string]interface{}{
+				if terr = models.NewAuditLogEntry(r, tx, instanceID, user, models.UserSignedUpAction, "", map[string]interface{}{
 					"provider": params.Provider,
 				}); terr != nil {
 					return terr
@@ -155,7 +155,7 @@ func (a *API) Signup(w http.ResponseWriter, r *http.Request) error {
 					return internalServerError("Database error updating user").WithInternalError(terr)
 				}
 			} else {
-				if terr = models.NewAuditLogEntry(tx, instanceID, user, models.UserConfirmationRequestedAction, "", map[string]interface{}{
+				if terr = models.NewAuditLogEntry(r, tx, instanceID, user, models.UserConfirmationRequestedAction, "", map[string]interface{}{
 					"provider": params.Provider,
 				}); terr != nil {
 					return terr
@@ -179,7 +179,7 @@ func (a *API) Signup(w http.ResponseWriter, r *http.Request) error {
 		}
 		if errors.Is(err, UserExistsError) {
 			err = a.db.Transaction(func(tx *storage.Connection) error {
-				if terr := models.NewAuditLogEntry(tx, instanceID, user, models.UserRepeatedSignUpAction, "", map[string]interface{}{
+				if terr := models.NewAuditLogEntry(r, tx, instanceID, user, models.UserRepeatedSignUpAction, "", map[string]interface{}{
 					"provider": params.Provider,
 				}); terr != nil {
 					return terr
@@ -206,7 +206,7 @@ func (a *API) Signup(w http.ResponseWriter, r *http.Request) error {
 		var token *AccessTokenResponse
 		err = a.db.Transaction(func(tx *storage.Connection) error {
 			var terr error
-			if terr = models.NewAuditLogEntry(tx, instanceID, user, models.LoginAction, "", map[string]interface{}{
+			if terr = models.NewAuditLogEntry(r, tx, instanceID, user, models.LoginAction, "", map[string]interface{}{
 				"provider": params.Provider,
 			}); terr != nil {
 				return terr
diff --git a/api/token.go b/api/token.go
index 53259638..d6d72d1e 100644
--- a/api/token.go
+++ b/api/token.go
@@ -219,7 +219,7 @@ func (a *API) ResourceOwnerPasswordGrant(ctx context.Context, w http.ResponseWri
 	var token *AccessTokenResponse
 	err = a.db.Transaction(func(tx *storage.Connection) error {
 		var terr error
-		if terr = models.NewAuditLogEntry(tx, instanceID, user, models.LoginAction, "", map[string]interface{}{
+		if terr = models.NewAuditLogEntry(r, tx, instanceID, user, models.LoginAction, "", map[string]interface{}{
 			"provider": provider,
 		}); terr != nil {
 			return terr
@@ -321,12 +321,12 @@ func (a *API) RefreshTokenGrant(ctx context.Context, w http.ResponseWriter, r *h
 
 	err = a.db.Transaction(func(tx *storage.Connection) error {
 		var terr error
-		if terr = models.NewAuditLogEntry(tx, instanceID, user, models.TokenRefreshedAction, "", nil); terr != nil {
+		if terr = models.NewAuditLogEntry(r, tx, instanceID, user, models.TokenRefreshedAction, "", nil); terr != nil {
 			return terr
 		}
 
 		if newToken == nil {
-			newToken, terr = models.GrantRefreshTokenSwap(tx, user, token)
+			newToken, terr = models.GrantRefreshTokenSwap(r, tx, user, token)
 			if terr != nil {
 				return internalServerError(terr.Error())
 			}
@@ -488,7 +488,7 @@ func (a *API) IdTokenGrant(ctx context.Context, w http.ResponseWriter, r *http.R
 				return unauthorizedError("Error unverified email")
 			}
 
-			if terr := models.NewAuditLogEntry(tx, instanceID, user, models.UserSignedUpAction, "", map[string]interface{}{
+			if terr := models.NewAuditLogEntry(r, tx, instanceID, user, models.UserSignedUpAction, "", map[string]interface{}{
 				"provider": params.Provider,
 			}); terr != nil {
 				return terr
@@ -502,7 +502,7 @@ func (a *API) IdTokenGrant(ctx context.Context, w http.ResponseWriter, r *http.R
 				return internalServerError("Error updating user").WithInternalError(terr)
 			}
 		} else {
-			if terr := models.NewAuditLogEntry(tx, instanceID, user, models.LoginAction, "", map[string]interface{}{
+			if terr := models.NewAuditLogEntry(r, tx, instanceID, user, models.LoginAction, "", map[string]interface{}{
 				"provider": params.Provider,
 			}); terr != nil {
 				return terr
diff --git a/api/user.go b/api/user.go
index 7a89eea6..445153dd 100644
--- a/api/user.go
+++ b/api/user.go
@@ -6,6 +6,7 @@ import (
 
 	"github.com/gofrs/uuid"
 	"github.com/netlify/gotrue/api/sms_provider"
+	"github.com/netlify/gotrue/logger"
 	"github.com/netlify/gotrue/models"
 	"github.com/netlify/gotrue/storage"
 )
@@ -76,7 +77,7 @@ func (a *API) UserUpdate(w http.ResponseWriter, r *http.Request) error {
 		return internalServerError("Database error finding user").WithInternalError(err)
 	}
 
-	log := getLogEntry(r)
+	log := logger.GetLogEntry(r)
 	log.Debugf("Checking params for token %v", params)
 
 	err = a.db.Transaction(func(tx *storage.Connection) error {
@@ -161,7 +162,7 @@ func (a *API) UserUpdate(w http.ResponseWriter, r *http.Request) error {
 			}
 		}
 
-		if terr = models.NewAuditLogEntry(tx, instanceID, user, models.UserModifiedAction, "", nil); terr != nil {
+		if terr = models.NewAuditLogEntry(r, tx, instanceID, user, models.UserModifiedAction, "", nil); terr != nil {
 			return internalServerError("Error recording audit log entry").WithInternalError(terr)
 		}
 
diff --git a/api/verify.go b/api/verify.go
index f84b765e..1900ebbb 100644
--- a/api/verify.go
+++ b/api/verify.go
@@ -12,6 +12,7 @@ import (
 	"strings"
 	"time"
 
+	"github.com/netlify/gotrue/logger"
 	"github.com/netlify/gotrue/models"
 	"github.com/netlify/gotrue/storage"
 	"github.com/sethvargo/go-password/password"
@@ -101,11 +102,11 @@ func (a *API) verifyGet(w http.ResponseWriter, r *http.Request) error {
 
 		switch params.Type {
 		case signupVerification, inviteVerification:
-			user, terr = a.signupVerify(ctx, tx, user)
+			user, terr = a.signupVerify(r, ctx, tx, user)
 		case recoveryVerification, magicLinkVerification:
-			user, terr = a.recoverVerify(ctx, tx, user)
+			user, terr = a.recoverVerify(r, ctx, tx, user)
 		case emailChangeVerification:
-			user, terr = a.emailChangeVerify(ctx, tx, params, user)
+			user, terr = a.emailChangeVerify(r, ctx, tx, params, user)
 			if user == nil && terr == nil {
 				// when double confirmation is required
 				rurl := a.prepRedirectURL(singleConfirmationAccepted, params.RedirectTo)
@@ -191,11 +192,11 @@ func (a *API) verifyPost(w http.ResponseWriter, r *http.Request) error {
 
 		switch params.Type {
 		case signupVerification, inviteVerification:
-			user, terr = a.signupVerify(ctx, tx, user)
+			user, terr = a.signupVerify(r, ctx, tx, user)
 		case recoveryVerification, magicLinkVerification:
-			user, terr = a.recoverVerify(ctx, tx, user)
+			user, terr = a.recoverVerify(r, ctx, tx, user)
 		case emailChangeVerification:
-			user, terr = a.emailChangeVerify(ctx, tx, params, user)
+			user, terr = a.emailChangeVerify(r, ctx, tx, params, user)
 			if user == nil && terr == nil {
 				return sendJSON(w, http.StatusOK, map[string]string{
 					"msg":  singleConfirmationAccepted,
@@ -203,7 +204,7 @@ func (a *API) verifyPost(w http.ResponseWriter, r *http.Request) error {
 				})
 			}
 		case smsVerification, phoneChangeVerification:
-			user, terr = a.smsVerify(ctx, tx, user, params.Type)
+			user, terr = a.smsVerify(r, ctx, tx, user, params.Type)
 		default:
 			return unprocessableEntityError("Unsupported verification type")
 		}
@@ -229,7 +230,7 @@ func (a *API) verifyPost(w http.ResponseWriter, r *http.Request) error {
 	return sendJSON(w, http.StatusOK, token)
 }
 
-func (a *API) signupVerify(ctx context.Context, conn *storage.Connection, user *models.User) (*models.User, error) {
+func (a *API) signupVerify(r *http.Request, ctx context.Context, conn *storage.Connection, user *models.User) (*models.User, error) {
 	instanceID := getInstanceID(ctx)
 	config := a.getConfig(ctx)
 
@@ -249,7 +250,7 @@ func (a *API) signupVerify(ctx context.Context, conn *storage.Connection, user *
 			}
 		}
 
-		if terr = models.NewAuditLogEntry(tx, instanceID, user, models.UserSignedUpAction, "", nil); terr != nil {
+		if terr = models.NewAuditLogEntry(r, tx, instanceID, user, models.UserSignedUpAction, "", nil); terr != nil {
 			return terr
 		}
 
@@ -268,7 +269,7 @@ func (a *API) signupVerify(ctx context.Context, conn *storage.Connection, user *
 	return user, nil
 }
 
-func (a *API) recoverVerify(ctx context.Context, conn *storage.Connection, user *models.User) (*models.User, error) {
+func (a *API) recoverVerify(r *http.Request, ctx context.Context, conn *storage.Connection, user *models.User) (*models.User, error) {
 	instanceID := getInstanceID(ctx)
 	config := a.getConfig(ctx)
 
@@ -278,7 +279,7 @@ func (a *API) recoverVerify(ctx context.Context, conn *storage.Connection, user
 			return terr
 		}
 		if !user.IsConfirmed() {
-			if terr = models.NewAuditLogEntry(tx, instanceID, user, models.UserSignedUpAction, "", nil); terr != nil {
+			if terr = models.NewAuditLogEntry(r, tx, instanceID, user, models.UserSignedUpAction, "", nil); terr != nil {
 				return terr
 			}
 
@@ -289,7 +290,7 @@ func (a *API) recoverVerify(ctx context.Context, conn *storage.Connection, user
 				return terr
 			}
 		} else {
-			if terr = models.NewAuditLogEntry(tx, instanceID, user, models.LoginAction, "", nil); terr != nil {
+			if terr = models.NewAuditLogEntry(r, tx, instanceID, user, models.LoginAction, "", nil); terr != nil {
 				return terr
 			}
 			if terr = triggerEventHooks(ctx, tx, LoginEvent, user, instanceID, config); terr != nil {
@@ -305,13 +306,13 @@ func (a *API) recoverVerify(ctx context.Context, conn *storage.Connection, user
 	return user, nil
 }
 
-func (a *API) smsVerify(ctx context.Context, conn *storage.Connection, user *models.User, otpType string) (*models.User, error) {
+func (a *API) smsVerify(r *http.Request, ctx context.Context, conn *storage.Connection, user *models.User, otpType string) (*models.User, error) {
 	instanceID := getInstanceID(ctx)
 	config := a.getConfig(ctx)
 
 	err := conn.Transaction(func(tx *storage.Connection) error {
 		var terr error
-		if terr = models.NewAuditLogEntry(tx, instanceID, user, models.UserSignedUpAction, "", nil); terr != nil {
+		if terr = models.NewAuditLogEntry(r, tx, instanceID, user, models.UserSignedUpAction, "", nil); terr != nil {
 			return terr
 		}
 
@@ -339,7 +340,7 @@ func (a *API) smsVerify(ctx context.Context, conn *storage.Connection, user *mod
 func (a *API) prepErrorRedirectURL(err *HTTPError, r *http.Request, rurl string) string {
 	q := url.Values{}
 
-	log := getLogEntry(r)
+	log := logger.GetLogEntry(r)
 	log.Error(err.Message)
 
 	if str, ok := oauthErrorMap[err.Code]; ok {
@@ -356,7 +357,7 @@ func (a *API) prepRedirectURL(message string, rurl string) string {
 	return rurl + "#" + q.Encode()
 }
 
-func (a *API) emailChangeVerify(ctx context.Context, conn *storage.Connection, params *VerifyParams, user *models.User) (*models.User, error) {
+func (a *API) emailChangeVerify(r *http.Request, ctx context.Context, conn *storage.Connection, params *VerifyParams, user *models.User) (*models.User, error) {
 	instanceID := getInstanceID(ctx)
 	config := a.getConfig(ctx)
 
@@ -383,7 +384,7 @@ func (a *API) emailChangeVerify(ctx context.Context, conn *storage.Connection, p
 	err := conn.Transaction(func(tx *storage.Connection) error {
 		var terr error
 
-		if terr = models.NewAuditLogEntry(tx, instanceID, user, models.UserModifiedAction, "", nil); terr != nil {
+		if terr = models.NewAuditLogEntry(r, tx, instanceID, user, models.UserModifiedAction, "", nil); terr != nil {
 			return terr
 		}
 
diff --git a/api/log.go b/logger/log.go
similarity index 78%
rename from api/log.go
rename to logger/log.go
index c51af906..8f5c14a9 100644
--- a/api/log.go
+++ b/logger/log.go
@@ -1,4 +1,4 @@
-package api
+package logger
 
 import (
 	"fmt"
@@ -9,7 +9,10 @@ import (
 	"github.com/sirupsen/logrus"
 )
 
-func newStructuredLogger(logger *logrus.Logger) func(next http.Handler) http.Handler {
+func NewStructuredLogger(logger *logrus.Logger) func(next http.Handler) http.Handler {
+	logger.Formatter = &logrus.JSONFormatter{
+		DisableTimestamp: true,
+	}
 	return chimiddleware.RequestLogger(&structuredLogger{logger})
 }
 
@@ -25,10 +28,11 @@ func (l *structuredLogger) NewLogEntry(r *http.Request) chimiddleware.LogEntry {
 		"path":        r.URL.Path,
 		"remote_addr": r.RemoteAddr,
 		"referer":     r.Referer(),
+		"timestamp":   time.Now().UTC().Format(time.RFC3339),
 	}
 
-	if reqID := getRequestID(r.Context()); reqID != "" {
-		logFields["request_id"] = reqID
+	if reqID := r.Context().Value("request_id"); reqID != nil {
+		logFields["request_id"] = reqID.(string)
 	}
 
 	entry.Logger = entry.Logger.WithFields(logFields)
@@ -56,7 +60,7 @@ func (l *structuredLoggerEntry) Panic(v interface{}, stack []byte) {
 	}).Panic("unhandled request panic")
 }
 
-func getLogEntry(r *http.Request) logrus.FieldLogger {
+func GetLogEntry(r *http.Request) logrus.FieldLogger {
 	entry, _ := chimiddleware.GetLogEntry(r).(*structuredLoggerEntry)
 	if entry == nil {
 		return logrus.NewEntry(logrus.StandardLogger())
@@ -64,7 +68,7 @@ func getLogEntry(r *http.Request) logrus.FieldLogger {
 	return entry.Logger
 }
 
-func logEntrySetField(r *http.Request, key string, value interface{}) logrus.FieldLogger {
+func LogEntrySetField(r *http.Request, key string, value interface{}) logrus.FieldLogger {
 	if entry, ok := r.Context().Value(chimiddleware.LogEntryCtxKey).(*structuredLoggerEntry); ok {
 		entry.Logger = entry.Logger.WithField(key, value)
 		return entry.Logger
@@ -72,7 +76,7 @@ func logEntrySetField(r *http.Request, key string, value interface{}) logrus.Fie
 	return nil
 }
 
-func logEntrySetFields(r *http.Request, fields logrus.Fields) logrus.FieldLogger {
+func LogEntrySetFields(r *http.Request, fields logrus.Fields) logrus.FieldLogger {
 	if entry, ok := r.Context().Value(chimiddleware.LogEntryCtxKey).(*structuredLoggerEntry); ok {
 		entry.Logger = entry.Logger.WithFields(fields)
 		return entry.Logger
diff --git a/models/audit_log_entry.go b/models/audit_log_entry.go
index 7187a694..40bca6d6 100644
--- a/models/audit_log_entry.go
+++ b/models/audit_log_entry.go
@@ -3,9 +3,11 @@ package models
 import (
 	"bytes"
 	"fmt"
+	"net/http"
 	"time"
 
 	"github.com/gofrs/uuid"
+	"github.com/netlify/gotrue/logger"
 	"github.com/netlify/gotrue/storage"
 	"github.com/pkg/errors"
 	"github.com/sirupsen/logrus"
@@ -35,7 +37,7 @@ const (
 	user    auditLogType = "user"
 )
 
-var actionLogTypeMap = map[AuditAction]auditLogType{
+var ActionLogTypeMap = map[AuditAction]auditLogType{
 	LoginAction:                     account,
 	LogoutAction:                    account,
 	InviteAcceptedAction:            account,
@@ -64,7 +66,7 @@ func (AuditLogEntry) TableName() string {
 	return tableName
 }
 
-func NewAuditLogEntry(tx *storage.Connection, instanceID uuid.UUID, actor *User, action AuditAction, ipAddress string, traits map[string]interface{}) error {
+func NewAuditLogEntry(r *http.Request, tx *storage.Connection, instanceID uuid.UUID, actor *User, action AuditAction, ipAddress string, traits map[string]interface{}) error {
 	id, err := uuid.NewV4()
 	if err != nil {
 		return errors.Wrap(err, "Error generating unique id")
@@ -76,19 +78,23 @@ func NewAuditLogEntry(tx *storage.Connection, instanceID uuid.UUID, actor *User,
 		username = actor.GetPhone()
 	}
 
+	payload := map[string]interface{}{
+		"actor_id":       actor.ID,
+		"actor_username": username,
+		"action":         action,
+		"log_type":       ActionLogTypeMap[action],
+	}
 	l := AuditLogEntry{
 		InstanceID: instanceID,
 		ID:         id,
-		Payload: JSONMap{
-			"timestamp":      time.Now().UTC().Format(time.RFC3339),
-			"actor_id":       actor.ID,
-			"actor_username": username,
-			"action":         action,
-			"log_type":       actionLogTypeMap[action],
-		},
-		IPAddress: ipAddress,
+		Payload:    JSONMap(payload),
+		IPAddress:  ipAddress,
 	}
 
+	logger.LogEntrySetFields(r, logrus.Fields{
+		"auth_event": logrus.Fields(payload),
+	})
+
 	if name, ok := actor.UserMetaData["full_name"]; ok {
 		l.Payload["actor_name"] = name
 	}
@@ -101,7 +107,6 @@ func NewAuditLogEntry(tx *storage.Connection, instanceID uuid.UUID, actor *User,
 		return errors.Wrap(err, "Database error creating audit log entry")
 	}
 
-	logrus.Infof("{\"actor_id\": %v, \"action\": %v, \"timestamp\": %v, \"log_type\": %v, \"ip_address\": %v}", actor.ID, action, l.Payload["timestamp"], actionLogTypeMap[action], ipAddress)
 	return nil
 }
 
diff --git a/models/refresh_token.go b/models/refresh_token.go
index ea73da36..127d2f01 100644
--- a/models/refresh_token.go
+++ b/models/refresh_token.go
@@ -2,6 +2,7 @@ package models
 
 import (
 	"database/sql"
+	"net/http"
 	"time"
 
 	"github.com/gobuffalo/pop/v5"
@@ -38,11 +39,11 @@ func GrantAuthenticatedUser(tx *storage.Connection, user *User) (*RefreshToken,
 }
 
 // GrantRefreshTokenSwap swaps a refresh token for a new one, revoking the provided token.
-func GrantRefreshTokenSwap(tx *storage.Connection, user *User, token *RefreshToken) (*RefreshToken, error) {
+func GrantRefreshTokenSwap(r *http.Request, tx *storage.Connection, user *User, token *RefreshToken) (*RefreshToken, error) {
 	var newToken *RefreshToken
 	err := tx.Transaction(func(rtx *storage.Connection) error {
 		var terr error
-		if terr = NewAuditLogEntry(tx, user.InstanceID, user, TokenRevokedAction, "", nil); terr != nil {
+		if terr = NewAuditLogEntry(r, tx, user.InstanceID, user, TokenRevokedAction, "", nil); terr != nil {
 			return errors.Wrap(terr, "error creating audit log entry")
 		}
 


Test patch:
diff --git a/api/token_test.go b/api/token_test.go
index 972702b8..8da27934 100644
--- a/api/token_test.go
+++ b/api/token_test.go
@@ -158,9 +158,9 @@ func (ts *TokenTestSuite) TestTokenRefreshTokenRotation() {
 	require.NoError(ts.T(), ts.API.db.Create(u), "Error saving foo user")
 	first, err := models.GrantAuthenticatedUser(ts.API.db, u)
 	require.NoError(ts.T(), err)
-	second, err := models.GrantRefreshTokenSwap(ts.API.db, u, first)
+	second, err := models.GrantRefreshTokenSwap(&http.Request{}, ts.API.db, u, first)
 	require.NoError(ts.T(), err)
-	third, err := models.GrantRefreshTokenSwap(ts.API.db, u, second)
+	third, err := models.GrantRefreshTokenSwap(&http.Request{}, ts.API.db, u, second)
 	require.NoError(ts.T(), err)
 
 	cases := []struct {
diff --git a/hack/test.env b/hack/test.env
index ceebc2ad..f76624d6 100644
--- a/hack/test.env
+++ b/hack/test.env
@@ -87,7 +87,7 @@ GOTRUE_EXTERNAL_SAML_METADATA_URL=
 GOTRUE_EXTERNAL_SAML_API_BASE=http://localhost
 GOTRUE_EXTERNAL_SAML_NAME=TestSamlName
 GOTRUE_RATE_LIMIT_VERIFY="100000"
-GOTRUE_RATE_LIMIT_TOKEN_REFRESH="100000"
+GOTRUE_RATE_LIMIT_TOKEN_REFRESH="30"
 GOTRUE_TRACING_ENABLED=false
 GOTRUE_TRACING_HOST=127.0.0.1
 GOTRUE_TRACING_PORT=8126
diff --git a/models/refresh_token_test.go b/models/refresh_token_test.go
index e5e8790d..cef3771b 100644
--- a/models/refresh_token_test.go
+++ b/models/refresh_token_test.go
@@ -1,6 +1,7 @@
 package models
 
 import (
+	"net/http"
 	"testing"
 
 	"github.com/gofrs/uuid"
@@ -49,7 +50,7 @@ func (ts *RefreshTokenTestSuite) TestGrantRefreshTokenSwap() {
 	r, err := GrantAuthenticatedUser(ts.db, u)
 	require.NoError(ts.T(), err)
 
-	s, err := GrantRefreshTokenSwap(ts.db, u, r)
+	s, err := GrantRefreshTokenSwap(&http.Request{}, ts.db, u, r)
 	require.NoError(ts.T(), err)
 
 	_, nr, err := FindUserWithRefreshToken(ts.db, r.Token)