diff --git a/CHANGELOG.md b/CHANGELOG.md
index 321e802a8e04f0968922da340c12a7099a23d48f..562caf6dd630276a0d1b45553dcd455b90b55814 100644
--- a/CHANGELOG.md
+++ b/CHANGELOG.md
@@ -6,7 +6,7 @@ TBD
- Fix MFA login failure when the totp `dict`'s attempted codes list changes size while being processed ([Merge Request](https://gitlab.com/crafty-controller/crafty-4/-/merge_requests/899))
- Resolve additional json being appended to downloaded files ([Merge Request](https://gitlab.com/crafty-controller/crafty-4/-/merge_requests/902))
### Tweaks
-TBD
+- Add extended debug logging to help troubleshoot MFA issues ([Merge Request](https://gitlab.com/crafty-controller/crafty-4/-/merge_requests/898))
### Lang
TBD
diff --git a/app/classes/controllers/totp_controller.py b/app/classes/controllers/totp_controller.py
index 057fd0042ee82239a427492a0f8d0b6d49060e98..777e7ebfc82c11bc62def39bdeb8f7fcc1de8fdf 100644
--- a/app/classes/controllers/totp_controller.py
+++ b/app/classes/controllers/totp_controller.py
@@ -62,11 +62,14 @@ class TOTPController:
_type_: _description_
"""
user = HelperUsers.get_by_id(user_id)
+ logger.debug("Validating TOTP entry for user %s", user.username)
authenticated = False
# Iterate through just in case a user has multiple 2FA methods
now = datetime.now(tz=timezone.utc)
+ logger.debug("TOTP sequence: current time is %s", now)
# Check to see if someone is trying to reuse a key in the 60 second window
+ logger.debug("TOTP sequence: checking for reused code.")
if str(user_id) in self.used_totp_codes:
if str(totp_code) in self.used_totp_codes[
str(user_id)
@@ -78,14 +81,17 @@ class TOTPController:
)
return authenticated
else:
+ logger.debug("TOTP sequence: No previous code dict found. Creating one")
self.used_totp_codes[str(user_id)] = {} # Init empty dict if not in there
+ logger.debug("TOTP sequence: reused code check passed. Validating user code")
# Store OTP as used for 60 seconds
self.used_totp_codes[str(user_id)][str(totp_code)] = now
self.clear_stale_entries()
for totp in user.totp_user:
+ logger.debug("TOTP sequence: Starting TOTP factory initialization")
totp_factory = pyotp.TOTP(totp.totp_secret)
if totp_factory.verify(
totp_code,
@@ -94,16 +100,20 @@ class TOTPController:
):
logger.info("Successfully verified user MFA %s", user_id)
authenticated = True
+ if not authenticated:
+ logger.error("TOTP sequence: Code validation failed. Code is not valid.")
return authenticated
def clear_stale_entries(self):
"""clears out totp codes older than 1 minute when one is sent"""
now = datetime.now(tz=timezone.utc)
# Clean up expired entries reclaim some memory
+ logger.debug("Checking for used codes entries older than 1 minute")
for key, totp_dict in list(self.used_totp_codes.items()):
# Iterate over copy of dict (list) to prevent size change during iteration
for item, timestamp in list(totp_dict.items()):
if now - timestamp > timedelta(seconds=60):
+ logger.debug("Found saved code older than one minute. Deleting...")
# needs to ref the self var to remove expired entries
del self.used_totp_codes[ # pylint: disable=unnecessary-dict-index-lookup
key