chore: improve tracing for selfservice strategies (#4061)

driver/config/config_test.go

@@ -993,15 +993,13 @@ func TestIdentitySchemaValidation(t *testing.T) {
 	}
 
 	t.Run("case=skip invalid schema validation", func(t *testing.T) {
-		ctx := ctx
 		_, err := config.New(ctx, logrusx.New("", ""), os.Stderr, &contextx.Default{},
 			configx.WithConfigFiles("stub/.kratos.invalid.identities.yaml"),
 			configx.SkipValidation())
 		assert.NoError(t, err)
 	})
 
 	t.Run("case=invalid schema should throw error", func(t *testing.T) {
-		ctx := ctx
 		var stdErr bytes.Buffer
 		_, err := config.New(ctx, logrusx.New("", ""), &stdErr, &contextx.Default{},
 			configx.WithConfigFiles("stub/.kratos.invalid.identities.yaml"))
@@ -1011,27 +1009,24 @@ func TestIdentitySchemaValidation(t *testing.T) {
 	})
 
 	t.Run("case=must fail on loading unreachable schemas", func(t *testing.T) {
-		ctx = config.SetValidateIdentitySchemaResilientClientOptions(ctx, []httpx.ResilientOptions{
+		// we make sure that the test runs into DNS issues instead of the context being canceled
+		ctx := config.SetValidateIdentitySchemaResilientClientOptions(ctx, []httpx.ResilientOptions{
 			httpx.ResilientClientWithMaxRetry(0),
-			httpx.ResilientClientWithConnectionTimeout(time.Nanosecond),
+			httpx.ResilientClientWithConnectionTimeout(5 * time.Second),
 		})
 
-		ctx, cancel := context.WithTimeout(ctx, time.Second*30)
-		t.Cleanup(cancel)
-
-		err := make(chan error, 1)
+		err := make(chan error)
 		go func(err chan error) {
 			_, e := config.New(ctx, logrusx.New("", ""), os.Stderr, &contextx.Default{},
 				configx.WithConfigFiles("stub/.kratos.mock.identities.yaml"))
 			err <- e
 		}(err)
 
 		select {
-		case <-ctx.Done():
-			panic("the test could not complete as the context timed out before the identity schema loader timed out")
+		case <-time.After(5 * time.Second):
+			t.Fatal("the test could not complete as the context timed out before the identity schema loader timed out")
 		case e := <-err:
-			assert.Error(t, e)
-			assert.Contains(t, e.Error(), "Client.Timeout")
+			assert.ErrorContains(t, e, "no such host")
 		}
 	})
 

go.mod

@@ -70,7 +70,7 @@ require (
 	github.com/ory/jsonschema/v3 v3.0.8
 	github.com/ory/mail/v3 v3.0.0
 	github.com/ory/nosurf v1.2.7
-	github.com/ory/x v0.0.647
+	github.com/ory/x v0.0.655
 	github.com/peterhellberg/link v1.2.0
 	github.com/phayes/freeport v0.0.0-20220201140144-74d24b5ae9f5
 	github.com/pkg/errors v0.9.1

go.sum

@@ -645,8 +645,8 @@ github.com/ory/pop/v6 v6.2.0 h1:hRFOGAOEHw91kUHQ32k5NHqCkcHrRou/romvrJP1w0E=
 github.com/ory/pop/v6 v6.2.0/go.mod h1:okVAYKGtgunD/wbW3NGhZTndJCS+6FqO+cA89rQ4doc=
 github.com/ory/sessions v1.2.2-0.20220110165800-b09c17334dc2 h1:zm6sDvHy/U9XrGpixwHiuAwpp0Ock6khSVHkrv6lQQU=
 github.com/ory/sessions v1.2.2-0.20220110165800-b09c17334dc2/go.mod h1:dk2InVEVJ0sfLlnXv9EAgkf6ecYs/i80K/zI+bUmuGM=
-github.com/ory/x v0.0.647 h1:DVKgA3ykMB9qXuMdSl5C8SFWr3yw7Xe8jpSm0+iqGeU=
-github.com/ory/x v0.0.647/go.mod h1:M+0EAXo7DT7Z2/Yrzvh4mgxOoV1fGI1jOKyAJ72d4Qs=
+github.com/ory/x v0.0.655 h1:P+uwq8GE2YoB9sEyo/8nxuPwdHzBvXE/Xnkyujl7HeQ=
+github.com/ory/x v0.0.655/go.mod h1:M+0EAXo7DT7Z2/Yrzvh4mgxOoV1fGI1jOKyAJ72d4Qs=
 github.com/pelletier/go-toml v1.9.5 h1:4yBQzkHv+7BHq2PQUZF3Mx0IYxG7LsP222s7Agd3ve8=
 github.com/pelletier/go-toml v1.9.5/go.mod h1:u1nR/EPcESfeI/szUZKdtJ0xRNbUoANCkoOuaOx1Y+c=
 github.com/pelletier/go-toml/v2 v2.2.2 h1:aYUidT7k73Pcl9nb2gScu7NSrKCSHIDE89b3+6Wq+LM=

selfservice/flow/request.go

@@ -9,6 +9,9 @@ import (
 	"net/http"
 	"strings"
 
+	"go.opentelemetry.io/otel/attribute"
+	"go.opentelemetry.io/otel/trace"
+
 	"github.com/ory/kratos/driver/config"
 	"github.com/ory/kratos/selfservice/strategy"
 	"github.com/ory/x/decoderx"
@@ -100,8 +103,9 @@ func MethodEnabledAndAllowedFromRequest(r *http.Request, flow FlowName, expected
 	return MethodEnabledAndAllowed(r.Context(), flow, expected, method.Method, d)
 }
 
-func MethodEnabledAndAllowed(ctx context.Context, flowName FlowName, expected, actual string, d config.Provider) error {
+func MethodEnabledAndAllowed(ctx context.Context, _ FlowName, expected, actual string, d config.Provider) error {
 	if actual != expected {
+		trace.SpanFromContext(ctx).SetAttributes(attribute.String("not_responsible_reason", "method mismatch"))
 		return errors.WithStack(ErrStrategyNotResponsible)
 	}
 

selfservice/strategy/code/strategy_login.go

@@ -176,7 +176,7 @@ func (s *Strategy) methodEnabledAndAllowedFromRequest(r *http.Request, f *login.
 }
 
 func (s *Strategy) Login(w http.ResponseWriter, r *http.Request, f *login.Flow, sess *session.Session) (_ *identity.Identity, err error) {
-	ctx, span := s.deps.Tracer(r.Context()).Tracer().Start(r.Context(), "selfservice.strategy.code.strategy.Login")
+	ctx, span := s.deps.Tracer(r.Context()).Tracer().Start(r.Context(), "selfservice.strategy.code.Strategy.Login")
 	defer otelx.End(span, &err)
 
 	if s.deps.Config().SelfServiceCodeStrategy(ctx).PasswordlessEnabled {
@@ -193,10 +193,12 @@ func (s *Strategy) Login(w http.ResponseWriter, r *http.Request, f *login.Flow,
 
 	if p, err := s.methodEnabledAndAllowedFromRequest(r, f); errors.Is(err, flow.ErrStrategyNotResponsible) {
 		if !s.deps.Config().SelfServiceCodeStrategy(ctx).MFAEnabled {
+			span.SetAttributes(attribute.String("not_responsible_reason", "MFA is not enabled"))
 			return nil, err
 		}
 
 		if p == nil || len(p.Address) == 0 {
+			span.SetAttributes(attribute.String("not_responsible_reason", "method not set or address not set"))
 			return nil, err
 		}
 

selfservice/strategy/code/strategy_recovery.go

@@ -91,7 +91,7 @@ type updateRecoveryFlowWithCodeMethod struct {
 	TransientPayload json.RawMessage `json:"transient_payload,omitempty" form:"transient_payload"`
 }
 
-func (s Strategy) isCodeFlow(f *recovery.Flow) bool {
+func (s *Strategy) isCodeFlow(f *recovery.Flow) bool {
 	value, err := f.Active.Value()
 	if err != nil {
 		return false
@@ -100,11 +100,12 @@ func (s Strategy) isCodeFlow(f *recovery.Flow) bool {
 }
 
 func (s *Strategy) Recover(w http.ResponseWriter, r *http.Request, f *recovery.Flow) (err error) {
-	ctx, span := s.deps.Tracer(r.Context()).Tracer().Start(r.Context(), "selfservice.strategy.code.strategy.Recover")
+	ctx, span := s.deps.Tracer(r.Context()).Tracer().Start(r.Context(), "selfservice.strategy.code.Strategy.Recover")
 	span.SetAttributes(attribute.String("selfservice_flows_recovery_use", s.deps.Config().SelfServiceFlowRecoveryUse(ctx)))
 	defer otelx.End(span, &err)
 
 	if !s.isCodeFlow(f) {
+		span.SetAttributes(attribute.String("not_responsible_reason", "not code flow"))
 		return errors.WithStack(flow.ErrStrategyNotResponsible)
 	}
 

selfservice/strategy/code/strategy_registration.go

@@ -130,7 +130,7 @@ func (s *Strategy) validateAndGetCredentialsFromTraits(ctx context.Context, i *i
 }
 
 func (s *Strategy) Register(w http.ResponseWriter, r *http.Request, f *registration.Flow, i *identity.Identity) (err error) {
-	ctx, span := s.deps.Tracer(r.Context()).Tracer().Start(r.Context(), "selfservice.strategy.code.strategy.Register")
+	ctx, span := s.deps.Tracer(r.Context()).Tracer().Start(r.Context(), "selfservice.strategy.code.Strategy.Register")
 	defer otelx.End(span, &err)
 
 	if err := flow.MethodEnabledAndAllowedFromRequest(r, f.GetFlowName(), s.ID().String(), s.deps); err != nil {

selfservice/strategy/code/strategy_verification.go

@@ -135,7 +135,7 @@ func (body *updateVerificationFlowWithCodeMethod) getMethod() verification.Verif
 }
 
 func (s *Strategy) Verify(w http.ResponseWriter, r *http.Request, f *verification.Flow) (err error) {
-	ctx, span := s.deps.Tracer(r.Context()).Tracer().Start(r.Context(), "selfservice.strategy.code.strategy.Verify")
+	ctx, span := s.deps.Tracer(r.Context()).Tracer().Start(r.Context(), "selfservice.strategy.code.Strategy.Verify")
 	span.SetAttributes(attribute.String("selfservice_flows_verification_use", s.deps.Config().SelfServiceFlowVerificationUse(ctx)))
 	defer otelx.End(span, &err)
 

selfservice/strategy/idfirst/strategy_login.go

@@ -6,6 +6,8 @@ package idfirst
 import (
 	"net/http"
 
+	"go.opentelemetry.io/otel/attribute"
+
 	"github.com/ory/x/otelx"
 
 	"github.com/ory/kratos/schema"
@@ -45,10 +47,12 @@ func (s *Strategy) Login(w http.ResponseWriter, r *http.Request, f *login.Flow,
 	defer otelx.End(span, &err)
 
 	if !s.d.Config().SelfServiceLoginFlowIdentifierFirstEnabled(ctx) {
+		span.SetAttributes(attribute.String("not_responsible_reason", "strategy is not enabled"))
 		return nil, errors.WithStack(flow.ErrStrategyNotResponsible)
 	}
 
 	if err := login.CheckAAL(f, identity.AuthenticatorAssuranceLevel1); err != nil {
+		span.SetAttributes(attribute.String("not_responsible_reason", "requested AAL is not sufficient"))
 		return nil, err
 	}
 

selfservice/strategy/link/strategy_recovery.go

@@ -241,7 +241,7 @@ type updateRecoveryFlowWithLinkMethod struct {
 }
 
 func (s *Strategy) Recover(w http.ResponseWriter, r *http.Request, f *recovery.Flow) (err error) {
-	ctx, span := s.d.Tracer(r.Context()).Tracer().Start(r.Context(), "selfservice.strategy.link.strategy.Recover")
+	ctx, span := s.d.Tracer(r.Context()).Tracer().Start(r.Context(), "selfservice.strategy.link.Strategy.Recover")
 	span.SetAttributes(attribute.String("selfservice_flows_recovery_use", s.d.Config().SelfServiceFlowRecoveryUse(ctx)))
 	defer otelx.End(span, &err)
 

selfservice/strategy/link/strategy_verification.go

@@ -32,10 +32,10 @@ func (s *Strategy) VerificationStrategyID() string {
 	return string(verification.VerificationStrategyLink)
 }
 
-func (s *Strategy) RegisterPublicVerificationRoutes(public *x.RouterPublic) {
+func (s *Strategy) RegisterPublicVerificationRoutes(_ *x.RouterPublic) {
 }
 
-func (s *Strategy) RegisterAdminVerificationRoutes(admin *x.RouterAdmin) {
+func (s *Strategy) RegisterAdminVerificationRoutes(_ *x.RouterAdmin) {
 }
 
 func (s *Strategy) PopulateVerificationMethod(r *http.Request, f *verification.Flow) error {
@@ -129,7 +129,7 @@ type updateVerificationFlowWithLinkMethod struct {
 }
 
 func (s *Strategy) Verify(w http.ResponseWriter, r *http.Request, f *verification.Flow) (err error) {
-	ctx, span := s.d.Tracer(r.Context()).Tracer().Start(r.Context(), "selfservice.strategy.link.strategy.Verify")
+	ctx, span := s.d.Tracer(r.Context()).Tracer().Start(r.Context(), "selfservice.strategy.link.Strategy.Verify")
 	span.SetAttributes(attribute.String("selfservice_flows_verification_use", s.d.Config().SelfServiceFlowVerificationUse(ctx)))
 	defer otelx.End(span, &err)
 

selfservice/strategy/lookup/login.go

@@ -8,6 +8,8 @@ import (
 	"net/http"
 	"time"
 
+	"go.opentelemetry.io/otel/attribute"
+
 	"github.com/ory/x/otelx"
 
 	"github.com/ory/x/sqlcon"
@@ -90,11 +92,12 @@ type updateLoginFlowWithLookupSecretMethod struct {
 	Code string `json:"lookup_secret"`
 }
 
-func (s *Strategy) Login(w http.ResponseWriter, r *http.Request, f *login.Flow, sess *session.Session) (i *identity.Identity, err error) {
+func (s *Strategy) Login(_ http.ResponseWriter, r *http.Request, f *login.Flow, sess *session.Session) (i *identity.Identity, err error) {
 	ctx, span := s.d.Tracer(r.Context()).Tracer().Start(r.Context(), "selfservice.strategy.lookup.strategy.Login")
 	defer otelx.End(span, &err)
 
 	if err := login.CheckAAL(f, identity.AuthenticatorAssuranceLevel2); err != nil {
+		span.SetAttributes(attribute.String("not_responsible_reason", "requested AAL is not AAL2"))
 		return nil, err
 	}
 

selfservice/strategy/lookup/settings.go

@@ -9,6 +9,8 @@ import (
 	"net/http"
 	"time"
 
+	"go.opentelemetry.io/otel/attribute"
+
 	"github.com/ory/x/otelx"
 
 	"github.com/tidwall/gjson"
@@ -106,7 +108,7 @@ func (s *Strategy) Settings(w http.ResponseWriter, r *http.Request, f *settings.
 	var p updateSettingsFlowWithLookupMethod
 	ctxUpdate, err := settings.PrepareUpdate(s.d, w, r, f, ss, settings.ContinuityKey(s.SettingsStrategyID()), &p)
 	if errors.Is(err, settings.ErrContinuePreviousAction) {
-		return ctxUpdate, s.continueSettingsFlow(r, ctxUpdate, p)
+		return ctxUpdate, s.continueSettingsFlow(ctx, r, ctxUpdate, p)
 	} else if err != nil {
 		return ctxUpdate, s.handleSettingsError(w, r, ctxUpdate, p, err)
 	}
@@ -122,12 +124,13 @@ func (s *Strategy) Settings(w http.ResponseWriter, r *http.Request, f *settings.
 			return nil, s.handleSettingsError(w, r, ctxUpdate, p, err)
 		}
 	} else {
+		span.SetAttributes(attribute.String("not_responsible_reason", "neither reveal, regenerate, confirm, nor disable was set"))
 		return nil, errors.WithStack(flow.ErrStrategyNotResponsible)
 	}
 
 	// This does not come from the payload!
 	p.Flow = ctxUpdate.Flow.ID.String()
-	if err := s.continueSettingsFlow(r, ctxUpdate, p); err != nil {
+	if err := s.continueSettingsFlow(ctx, r, ctxUpdate, p); err != nil {
 		return ctxUpdate, s.handleSettingsError(w, r, ctxUpdate, p, err)
 	}
 
@@ -146,8 +149,7 @@ func (s *Strategy) decodeSettingsFlow(r *http.Request, dest interface{}) error {
 	)
 }
 
-func (s *Strategy) continueSettingsFlow(r *http.Request, ctxUpdate *settings.UpdateContext, p updateSettingsFlowWithLookupMethod) error {
-	ctx := r.Context()
+func (s *Strategy) continueSettingsFlow(ctx context.Context, r *http.Request, ctxUpdate *settings.UpdateContext, p updateSettingsFlowWithLookupMethod) error {
 	if p.ConfirmLookup || p.RevealLookup || p.RegenerateLookup || p.DisableLookup {
 		if err := flow.MethodEnabledAndAllowed(ctx, flow.SettingsFlow, s.SettingsStrategyID(), s.SettingsStrategyID(), s.d); err != nil {
 			return err