fix: improve post registration hook log and audit messages

selfservice/flow/login/error.go

@@ -48,7 +48,8 @@ type (
 	}
 )
 
-func NewFlowExpiredError(ago time.Duration) *FlowExpiredError {
+func NewFlowExpiredError(at time.Time) *FlowExpiredError {
+	ago := time.Since(at)
 	return &FlowExpiredError{
 		ago: ago,
 		DefaultError: herodot.ErrBadRequest.

selfservice/flow/login/error_test.go

@@ -81,6 +81,8 @@ func TestHandleError(t *testing.T) {
 		return sse.Payload.Errors, nil
 	}
 
+	anHourAgo := time.Now().Add(-time.Hour)
+
 	t.Run("case=error with nil flow defaults to error ui redirect", func(t *testing.T) {
 		t.Cleanup(reset)
 
@@ -113,7 +115,7 @@ func TestHandleError(t *testing.T) {
 			t.Cleanup(reset)
 
 			loginFlow = newFlow(t, time.Minute, flow.TypeAPI)
-			flowError = login.NewFlowExpiredError(time.Hour)
+			flowError = login.NewFlowExpiredError(anHourAgo)
 			ct = identity.CredentialsTypePassword
 
 			res, err := ts.Client().Do(testhelpers.NewHTTPGetJSONRequest(t, ts.URL+"/error"))
@@ -198,7 +200,7 @@ func TestHandleError(t *testing.T) {
 			t.Cleanup(reset)
 
 			loginFlow = &login.Flow{Type: flow.TypeBrowser}
-			flowError = login.NewFlowExpiredError(time.Hour)
+			flowError = login.NewFlowExpiredError(anHourAgo)
 			ct = identity.CredentialsTypePassword
 
 			lf, _ := expectLoginUI(t)

selfservice/flow/login/flow.go

@@ -135,7 +135,7 @@ func (f Flow) TableName() string {
 
 func (f *Flow) Valid() error {
 	if f.ExpiresAt.Before(time.Now()) {
-		return errors.WithStack(NewFlowExpiredError(time.Since(f.ExpiresAt)))
+		return errors.WithStack(NewFlowExpiredError(f.ExpiresAt))
 	}
 	return nil
 }

selfservice/flow/login/handler.go

@@ -5,9 +5,10 @@ import (
 	"time"
 
 	"github.com/julienschmidt/httprouter"
-	"github.com/ory/x/urlx"
 	"github.com/pkg/errors"
 
+	"github.com/ory/x/urlx"
+
 	"github.com/ory/kratos/driver/configuration"
 	"github.com/ory/kratos/selfservice/errorx"
 	"github.com/ory/kratos/selfservice/flow"

selfservice/flow/registration/hook.go

@@ -84,13 +84,34 @@ func NewHookExecutor(d executorDependencies, c configuration.Provider) *HookExec
 }
 
 func (e *HookExecutor) PostRegistrationHook(w http.ResponseWriter, r *http.Request, ct identity.CredentialsType, a *Flow, i *identity.Identity) error {
-	for _, executor := range e.d.PostRegistrationPrePersistHooks(ct) {
+	e.d.Logger().
+		WithRequest(r).
+		WithField("identity_id", i.ID).
+		WithField("flow_method",ct).
+		Debug("Running PostRegistrationPrePersistHooks.")
+	for k, executor := range e.d.PostRegistrationPrePersistHooks(ct) {
 		if err := executor.ExecutePostRegistrationPrePersistHook(w, r, a, i); err != nil {
 			if errors.Is(err, ErrHookAbortFlow) {
+				e.d.Logger().
+					WithRequest(r).
+					WithField("executor", fmt.Sprintf("%T", executor)).
+					WithField("executor_position", k).
+					WithField("executors", PostHookPostPersistExecutorNames(e.d.PostRegistrationPostPersistHooks(ct))).
+					WithField("identity_id", i.ID).
+					WithField("flow_method",ct).
+					Debug("A ExecutePostRegistrationPrePersistHook hook aborted early.")
 				return nil
 			}
 			return err
 		}
+
+		e.d.Logger().WithRequest(r).
+			WithField("executor", fmt.Sprintf("%T", executor)).
+			WithField("executor_position", k).
+			WithField("executors", PostHookPostPersistExecutorNames(e.d.PostRegistrationPostPersistHooks(ct))).
+			WithField("identity_id", i.ID).
+			WithField("flow_method",ct).
+			Debug("ExecutePostRegistrationPrePersistHook completed successfully.")
 	}
 
 	// We need to make sure that the identity has a valid schema before passing it down to the identity pool.
@@ -104,13 +125,17 @@ func (e *HookExecutor) PostRegistrationHook(w http.ResponseWriter, r *http.Reque
 		}
 		return err
 	}
-
 	e.d.Audit().
 		WithRequest(r).
 		WithField("identity_id", i.ID).
-		Info("A new identity has registered using self-service registration. Running post execution hooks.")
+		Info("A new identity has registered using self-service registration.")
 
 	s := session.NewActiveSession(i, e.c, time.Now().UTC())
+	e.d.Logger().
+		WithRequest(r).
+		WithField("identity_id", i.ID).
+		WithField("flow_method",ct).
+		Debug("Running PostRegistrationPostPersistHooks.")
 	for k, executor := range e.d.PostRegistrationPostPersistHooks(ct) {
 		if err := executor.ExecutePostRegistrationPostPersistHook(w, r, a, s); err != nil {
 			if errors.Is(err, ErrHookAbortFlow) {
@@ -120,7 +145,8 @@ func (e *HookExecutor) PostRegistrationHook(w http.ResponseWriter, r *http.Reque
 					WithField("executor_position", k).
 					WithField("executors", PostHookPostPersistExecutorNames(e.d.PostRegistrationPostPersistHooks(ct))).
 					WithField("identity_id", i.ID).
-					Debug("Post registration execution hooks aborted early.")
+					WithField("flow_method",ct).
+					Debug("A ExecutePostRegistrationPostPersistHook hook aborted early.")
 				return nil
 			}
 			return err
@@ -131,11 +157,13 @@ func (e *HookExecutor) PostRegistrationHook(w http.ResponseWriter, r *http.Reque
 			WithField("executor_position", k).
 			WithField("executors", PostHookPostPersistExecutorNames(e.d.PostRegistrationPostPersistHooks(ct))).
 			WithField("identity_id", i.ID).
-			Debug("Successfully ran post registration executor.")
+			WithField("flow_method",ct).
+			Debug("ExecutePostRegistrationPostPersistHook completed successfully.")
 	}
 
 	e.d.Logger().
 		WithRequest(r).
+		WithField("flow_method",ct).
 		WithField("identity_id", i.ID).
 		Debug("Post registration execution hooks completed successfully.")