separated quotation and payments

api/pkg/db/internal/mongo/verificationimp/consume.go

@@ -3,6 +3,7 @@ package verificationimp
 import (
 	"context"
 	"errors"
+	"strings"
 	"time"
 
 	"github.com/tech/sendico/pkg/db/repository"
@@ -12,6 +13,7 @@ import (
 	"github.com/tech/sendico/pkg/model"
 	mutil "github.com/tech/sendico/pkg/mutil/db"
 	"go.mongodb.org/mongo-driver/v2/bson"
+	"go.uber.org/zap"
 )
 
 func (db *verificationDB) Consume(
@@ -23,54 +25,144 @@ func (db *verificationDB) Consume(
 
 	now := time.Now().UTC()
 	accountScoped := accountRef != bson.NilObjectID
+	accountRefHex := "<nil>"
+	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(
-				repository.Filter("purpose", purpose),
+				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),
+				zap.Any("scope_filter", scopeFilter.BuildQuery()),
 			)
-			if accountScoped {
-				scopeFilter = scopeFilter.And(repository.Filter("accountRef", accountRef))
-			}
 
 			// 1) Fast path for magic-link tokens: hash is deterministic and globally unique.
 			var token *model.VerificationToken
-			magicFilter := scopeFilter.And(
-				repository.Filter("verifyTokenHash", tokenHash(rawToken)),
+			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),
+				zap.Any("magic_filter", magicFilter.BuildQuery()),
 			)
 			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)
-					if hash == t.VerifyTokenHash {
+					match := hash == t.VerifyTokenHash
+					db.Logger.Debug("Verification consume OTP candidate evaluated",
+						zap.Int("candidate_index", i),
+						zap.Int("candidate_total", len(tokens)),
+						zap.String("candidate_id", t.ID.Hex()),
+						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
 					}
@@ -78,47 +170,110 @@ func (db *verificationDB) Consume(
 
 				if token == nil {
 					// wrong code/token → increment attempts for active (not used, not expired) scoped tokens
-					activeFilter := scopeFilter.And(
-						repository.Filter("usedAt", nil),
-						repository.Query().Comparison(repository.Field("expiresAt"), builder.Gt, now),
+					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),
+						zap.Any("active_filter", activeFilter.BuildQuery()),
 					)
 
-					_, _ = db.DBImp.PatchMany(
+					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
-			consumeFilter := repository.Query().And(
+			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 {
-				consumeFilter = consumeFilter.And(repository.Filter("accountRef", accountRef))
+				consumeFilters = append(consumeFilters, repository.Filter("accountRef", accountRef))
 			}
-
 			if token.MaxRetries != nil {
-				consumeFilter = consumeFilter.And(
-					repository.Query().Comparison(repository.Field("attempts"), builder.Lt, *token.MaxRetries),
-				)
+				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),
+				zap.String("token_id", token.ID.Hex()),
+				zap.Any("consume_filter", consumeFilter.BuildQuery()),
+			)
 
 			updated, err := db.DBImp.PatchMany(
 				ctx,
@@ -126,48 +281,217 @@ func (db *verificationDB) Consume(
 				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),
+					zap.String("token_id", token.ID.Hex()),
+					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),
+				zap.String("token_id", token.ID.Hex()),
+				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
-			_, _ = db.DBImp.PatchMany(
+			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),
+					zap.String("token_id", token.ID.Hex()),
+					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),
+					zap.String("token_id", token.ID.Hex()),
+					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),
+					zap.String("token_id", token.ID.Hex()),
+					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),
+					zap.String("token_id", token.ID.Hex()),
+				}, 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),
+					zap.String("token_id", token.ID.Hex()),
+				)
 				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),
+					zap.String("token_id", token.ID.Hex()),
+					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),
+					zap.String("token_id", token.ID.Hex()),
+					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),
+				zap.String("token_id", token.ID.Hex()),
+			)
 			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", "<non-verification-token>"),
+		)
 		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{
+		zap.String("token_id", token.ID.Hex()),
+		zap.String("token_account_ref", token.AccountRef.Hex()),
+		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
+}