package verificationimp import ( "context" "errors" "strings" "time" "github.com/tech/sendico/pkg/db/repository" "github.com/tech/sendico/pkg/db/repository/builder" "github.com/tech/sendico/pkg/db/verification" "github.com/tech/sendico/pkg/merrors" "github.com/tech/sendico/pkg/model" mutil "github.com/tech/sendico/pkg/mutil/db" "github.com/tech/sendico/pkg/mutil/mzap" "go.mongodb.org/mongo-driver/v2/bson" "go.uber.org/zap" ) func (db *verificationDB) Consume( ct context.Context, accountRef bson.ObjectID, purpose model.VerificationPurpose, rawToken string, ) (*model.VerificationToken, error) { now := time.Now().UTC() accountScoped := accountRef != bson.NilObjectID accountRefHex := "" if accountScoped { accountRefHex = accountRef.Hex() } trimmedRawToken := strings.TrimSpace(rawToken) db.Logger.Debug("Verification consume started", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), zap.Time("now_utc", now), zap.Int("raw_token_len", len(rawToken)), zap.Int("raw_token_trimmed_len", len(trimmedRawToken)), zap.Bool("raw_token_digits_only", tokenIsDigitsOnly(rawToken)), zap.Bool("raw_token_has_edge_whitespace", rawToken != trimmedRawToken), zap.String("raw_token_hash_prefix", hashPreview(tokenHash(rawToken))), ) t, e := db.tf.CreateTransaction().Execute( ct, func(ctx context.Context) (any, error) { scopeFilter := repository.Query().And( scopeFilters(accountScoped, accountRef, purpose)..., ) db.Logger.Debug("Verification consume scope filter prepared", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), ) // 1) Fast path for magic-link tokens: hash is deterministic and globally unique. var token *model.VerificationToken magicFilter := repository.Query().And( append( scopeFilters(accountScoped, accountRef, purpose), repository.Filter("verifyTokenHash", tokenHash(rawToken)), )..., ) db.Logger.Debug("Verification consume magic path lookup", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), ) var direct model.VerificationToken err := db.DBImp.FindOne(ctx, magicFilter, &direct) switch { case err == nil: token = &direct db.Logger.Debug("Verification consume matched by magic hash path", append([]zap.Field{ zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), }, tokenStateFields(token)..., )..., ) case errors.Is(err, merrors.ErrNoData): db.Logger.Debug("Verification consume no direct magic match", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), ) default: db.Logger.Warn("Verification consume magic path lookup failed", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), zap.Error(err), ) return nil, err } // If account is unknown, do not scan OTP candidates globally. if token == nil && !accountScoped { db.Logger.Debug("Verification consume rejected unscoped OTP scan", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), ) return nil, verification.ErorrTokenNotFound() } // 2) OTP path (and fallback): load purpose/account scoped tokens and compare hash with per-token salt. if token == nil { db.Logger.Debug("Verification consume OTP fallback lookup started", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), zap.Any("scope_filter", scopeFilter.BuildQuery()), ) tokens, err := mutil.GetObjects[model.VerificationToken]( ctx, db.Logger, scopeFilter, nil, db.DBImp.Repository, ) if err != nil { if errors.Is(err, merrors.ErrNoData) { db.Logger.Debug("Verification consume OTP fallback found no scoped tokens", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), ) return nil, verification.ErorrTokenNotFound() } db.Logger.Warn("Verification consume OTP fallback query failed", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), zap.Error(err), ) return nil, err } db.Logger.Debug("Verification consume OTP fallback loaded candidates", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), zap.Int("candidate_count", len(tokens)), ) for i := range tokens { t := &tokens[i] hash := hasherFor(t).Hash(rawToken, t) match := hash == t.VerifyTokenHash db.Logger.Debug("Verification consume OTP candidate evaluated", zap.Int("candidate_index", i), zap.Int("candidate_total", len(tokens)), mzap.ObjRef("candidate_ref", t.ID), zap.Bool("candidate_has_salt", t.Salt != nil), zap.Bool("candidate_used", t.UsedAt != nil), zap.Time("candidate_expires_at", t.ExpiresAt), zap.Int("candidate_attempts", t.Attempts), zap.Bool("candidate_has_max_retries", t.MaxRetries != nil), zap.String("candidate_stored_hash_prefix", hashPreview(t.VerifyTokenHash)), zap.String("candidate_computed_hash_prefix", hashPreview(hash)), zap.Bool("candidate_match", match), ) if match { token = t break } } if token == nil { // wrong code/token → increment attempts for active (not used, not expired) scoped tokens activeFilter := repository.Query().And( append( scopeFilters(accountScoped, accountRef, purpose), repository.Filter("usedAt", nil), repository.Query().Comparison(repository.Field("expiresAt"), builder.Gt, now), )..., ) db.Logger.Debug("Verification consume no OTP candidate matched, incrementing attempts for active scoped tokens", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), ) incremented, patchErr := db.DBImp.PatchMany( ctx, activeFilter, repository.Patch().Inc(repository.Field("attempts"), 1), ) if patchErr != nil { db.Logger.Warn("Verification consume failed to increment attempts for unmatched token", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), zap.Error(patchErr), ) } else { db.Logger.Debug("Verification consume attempts increment for unmatched token executed", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), zap.Int("updated_count", incremented), zap.String("transaction_note", "this update occurs inside transaction and will roll back when not_found error is returned"), ) } return nil, verification.ErorrTokenNotFound() } } // 3) Static checks if token.UsedAt != nil { db.Logger.Debug("Verification consume static check failed: token already used", append([]zap.Field{ zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), }, tokenStateFields(token)..., )..., ) return nil, verification.ErorrTokenAlreadyUsed() } if !token.ExpiresAt.After(now) { db.Logger.Debug("Verification consume static check failed: token expired", append([]zap.Field{ zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), zap.Time("now_utc", now), }, tokenStateFields(token)..., )..., ) return nil, verification.ErorrTokenExpired() } if token.MaxRetries != nil && token.Attempts >= *token.MaxRetries { db.Logger.Debug("Verification consume static check failed: attempts exceeded", append([]zap.Field{ zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), }, tokenStateFields(token)..., )..., ) return nil, verification.ErrorTokenAttemptsExceeded() } db.Logger.Debug("Verification consume static checks passed", append([]zap.Field{ zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), }, tokenStateFields(token)..., )..., ) // 4) Atomic consume consumeFilters := []builder.Query{ repository.IDFilter(token.ID), repository.Filter("purpose", purpose), repository.Filter("usedAt", nil), repository.Query().Comparison(repository.Field("expiresAt"), builder.Gt, now), } if accountScoped { consumeFilters = append(consumeFilters, repository.Filter("accountRef", accountRef)) } if token.MaxRetries != nil { consumeFilters = append(consumeFilters, repository.Query().Comparison(repository.Field("attempts"), builder.Lt, *token.MaxRetries)) } consumeFilter := repository.Query().And(consumeFilters...) db.Logger.Debug("Verification consume atomic update attempt", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), mzap.StorableRef(token), ) updated, err := db.DBImp.PatchMany( ctx, consumeFilter, repository.Patch().Set(repository.Field("usedAt"), now), ) if err != nil { db.Logger.Warn("Verification consume atomic update failed", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), mzap.StorableRef(token), zap.Error(err), ) return nil, err } db.Logger.Debug("Verification consume atomic update result", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), mzap.StorableRef(token), zap.Int("updated_count", updated), ) if updated == 1 { token.UsedAt = &now db.Logger.Debug("Verification consume succeeded", append([]zap.Field{ zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), }, tokenStateFields(token)..., )..., ) return token, nil } // 5) Consume failed → increment attempts incremented, incrementErr := db.DBImp.PatchMany( ctx, repository.IDFilter(token.ID), repository.Patch().Inc(repository.Field("attempts"), 1), ) if incrementErr != nil { db.Logger.Warn("Verification consume failed to increment attempts after atomic update miss", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), mzap.StorableRef(token), zap.Error(incrementErr), ) } else { db.Logger.Debug("Verification consume incremented attempts after atomic update miss", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), mzap.StorableRef(token), zap.Int("updated_count", incremented), zap.String("transaction_note", "this update occurs inside transaction and may roll back depending on returned error"), ) } // 6) Re-check state var fresh model.VerificationToken if err := db.DBImp.FindOne(ctx, repository.IDFilter(token.ID), &fresh); err != nil { db.Logger.Warn("Verification consume failed to re-check token state", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), mzap.StorableRef(token), zap.Error(err), ) return nil, merrors.Internal("failed to re-check token state") } db.Logger.Debug("Verification consume re-checked token state after atomic miss", append([]zap.Field{ zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), mzap.StorableRef(token), }, tokenStateFields(&fresh)..., )..., ) if fresh.UsedAt != nil { db.Logger.Debug("Verification consume final decision: already used after re-check", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), mzap.StorableRef(token), ) return nil, verification.ErorrTokenAlreadyUsed() } if !fresh.ExpiresAt.After(now) { db.Logger.Debug("Verification consume final decision: expired after re-check", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), mzap.StorableRef(token), zap.Time("now_utc", now), zap.Time("token_expires_at", fresh.ExpiresAt), ) return nil, verification.ErorrTokenExpired() } if fresh.MaxRetries != nil && fresh.Attempts >= *fresh.MaxRetries { db.Logger.Debug("Verification consume final decision: attempts exceeded after re-check", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), mzap.StorableRef(token), zap.Int("token_attempts", fresh.Attempts), zap.Int("token_max_retries", *fresh.MaxRetries), ) return nil, verification.ErrorTokenAttemptsExceeded() } db.Logger.Debug("Verification consume final decision: token not found after re-check", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), mzap.StorableRef(token), ) return nil, verification.ErorrTokenNotFound() }, ) if e != nil { db.Logger.Debug("Verification consume finished with error", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), zap.Error(e), ) return nil, e } res, ok := t.(*model.VerificationToken) if !ok { db.Logger.Warn("Verification consume returned unexpected result type", zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), zap.String("result_type", ""), ) return nil, merrors.Internal("unexpected token type") } db.Logger.Debug("Verification consume finished successfully", append([]zap.Field{ zap.String("purpose", string(purpose)), zap.Bool("account_scoped", accountScoped), zap.String("account_ref", accountRefHex), }, tokenStateFields(res)..., )..., ) return res, nil } const hashPreviewChars = 12 func hashPreview(value string) string { if value == "" { return "" } if len(value) <= hashPreviewChars { return value } return value[:hashPreviewChars] + "..." } func tokenIsDigitsOnly(value string) bool { if value == "" { return false } for _, ch := range value { if ch < '0' || ch > '9' { return false } } return true } func tokenStateFields(token *model.VerificationToken) []zap.Field { fields := []zap.Field{ mzap.StorableRef(token), mzap.ObjRef("token_account_ref", token.AccountRef), zap.String("token_purpose", string(token.Purpose)), zap.Bool("token_has_target", strings.TrimSpace(token.Target) != ""), zap.Bool("token_has_idempotency_key", token.IdempotencyKey != nil), zap.String("token_verify_hash_prefix", hashPreview(token.VerifyTokenHash)), zap.Bool("token_has_salt", token.Salt != nil), zap.Bool("token_used", token.UsedAt != nil), zap.Time("token_expires_at", token.ExpiresAt), zap.Int("token_attempts", token.Attempts), zap.Bool("token_has_max_retries", token.MaxRetries != nil), } if token.Salt != nil { fields = append(fields, zap.String("token_salt_prefix", hashPreview(*token.Salt))) } if token.UsedAt != nil { fields = append(fields, zap.Time("token_used_at", *token.UsedAt)) } if token.MaxRetries != nil { fields = append(fields, zap.Int("token_max_retries", *token.MaxRetries)) } if token.IdempotencyKey != nil { fields = append(fields, zap.String("token_idempotency_key_prefix", hashPreview(*token.IdempotencyKey))) } return fields } func scopeFilters(accountScoped bool, accountRef bson.ObjectID, purpose model.VerificationPurpose) []builder.Query { filters := []builder.Query{ repository.Filter("purpose", purpose), } if accountScoped { filters = append(filters, repository.Filter("accountRef", accountRef)) } return filters }