495 lines
17 KiB
Go
495 lines
17 KiB
Go
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 := "<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(
|
|
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", "<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{
|
|
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
|
|
}
|