Skip to content

Commit e72624c

Browse files
maxdinechclaude
andcommitted
debug(otp): add detailed logging to OTP protection
Add debug logging to track: - Token type mapping in getTokenTypeForVerification - Invalidation checks in checkOTPTokenInvalidated - Attempt recording in recordOTPAttempt - SQL query execution and results This will help diagnose why OTP brute force protection isn't triggering in staging environment. 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude <noreply@anthropic.com>
1 parent e0eaf04 commit e72624c

File tree

1 file changed

+39
-0
lines changed

1 file changed

+39
-0
lines changed

internal/api/verify.go

Lines changed: 39 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -730,8 +730,17 @@ func (a *API) verifyUserAndToken(conn *storage.Connection, params *VerifyParams,
730730

731731
// OTP Protection: Check if token is invalidated before attempting verification
732732
tokenType := getTokenTypeForVerification(params.Type)
733+
logrus.WithFields(logrus.Fields{
734+
"params_type": params.Type,
735+
"token_type": tokenType,
736+
"user_id": user.ID.String(),
737+
}).Debug("OTP Protection: Getting token type for verification")
733738
if tokenType != "" {
734739
invalidated, err := checkOTPTokenInvalidated(conn, user.ID.String(), tokenType)
740+
logrus.WithFields(logrus.Fields{
741+
"invalidated": invalidated,
742+
"error": err,
743+
}).Debug("OTP Protection: Checked if token is invalidated")
735744
if err == nil && invalidated {
736745
return nil, apierrors.NewForbiddenError(apierrors.ErrorCodeOTPExpired, "Token has been invalidated due to too many failed attempts. Please request a new verification code.")
737746
}
@@ -786,9 +795,16 @@ func (a *API) verifyUserAndToken(conn *storage.Connection, params *VerifyParams,
786795

787796
// OTP Protection: Record attempt
788797
if tokenType != "" {
798+
logrus.WithFields(logrus.Fields{
799+
"user_id": user.ID.String(),
800+
"token_type": tokenType,
801+
"is_valid": isValid,
802+
}).Debug("OTP Protection: Recording OTP attempt")
789803
if err := recordOTPAttempt(conn, user.ID.String(), tokenType, isValid); err != nil {
790804
// Log error but don't fail the request
791805
logrus.WithError(err).Warn("Failed to record OTP attempt")
806+
} else {
807+
logrus.Debug("OTP Protection: Successfully recorded OTP attempt")
792808
}
793809
}
794810

@@ -877,17 +893,30 @@ func checkOTPTokenInvalidated(conn *storage.Connection, userID string, tokenType
877893

878894
// recordOTPAttempt records a failed OTP verification attempt and invalidates token after max failures
879895
func recordOTPAttempt(conn *storage.Connection, userID string, tokenType string, isValid bool) error {
896+
logrus.WithFields(logrus.Fields{
897+
"user_id": userID,
898+
"token_type": tokenType,
899+
"is_valid": isValid,
900+
}).Debug("recordOTPAttempt called")
901+
880902
// If token is valid, reset attempts
881903
if isValid {
904+
logrus.Debug("Token valid - resetting attempt count")
882905
err := conn.RawQuery(`
883906
UPDATE auth.one_time_tokens
884907
SET attempt_count = 0, invalidated_at = NULL
885908
WHERE user_id = $1 AND token_type = $2::auth.one_time_token_type
886909
`, userID, tokenType).Exec()
910+
if err != nil {
911+
logrus.WithError(err).Error("Failed to reset attempt count")
912+
} else {
913+
logrus.Debug("Successfully reset attempt count")
914+
}
887915
return err
888916
}
889917

890918
// Token is invalid - increment attempt count
919+
logrus.Debug("Token invalid - incrementing attempt count")
891920
var attemptCount int
892921
err := conn.RawQuery(`
893922
UPDATE auth.one_time_tokens
@@ -897,19 +926,29 @@ func recordOTPAttempt(conn *storage.Connection, userID string, tokenType string,
897926
`, userID, tokenType).First(&attemptCount)
898927

899928
if err != nil {
929+
logrus.WithError(err).Error("Failed to increment attempt count")
900930
return err
901931
}
902932

933+
logrus.WithField("attempt_count", attemptCount).Debug("Incremented attempt count")
934+
903935
// If max attempts reached, invalidate the token
904936
if attemptCount >= maxOTPVerificationAttempts {
937+
logrus.Warn("Max attempts reached - invalidating token")
905938
err = conn.RawQuery(`
906939
UPDATE auth.one_time_tokens
907940
SET invalidated_at = NOW()
908941
WHERE user_id = $1 AND token_type = $2::auth.one_time_token_type
909942
`, userID, tokenType).Exec()
943+
if err != nil {
944+
logrus.WithError(err).Error("Failed to invalidate token")
945+
} else {
946+
logrus.Debug("Successfully invalidated token")
947+
}
910948
return err
911949
}
912950

951+
logrus.Debug("Attempt recorded successfully")
913952
return nil
914953
}
915954

0 commit comments

Comments
 (0)