Add logging support to auth module and improve debug information (#989)

Author: nicozanf

apps/_scaffold/common.py

@@ -37,6 +37,11 @@
 # #######################################################
 logger = make_logger("py4web:" + settings.APP_NAME, settings.LOGGERS)
 
+# this export the logger to the auth module
+# so that it can be used in auth plugins
+import py4web.utils.auth as auth_module
+auth_module.logger = logger
+
 # #######################################################
 # connect to db
 # #######################################################
@@ -133,7 +138,7 @@
 if settings.USE_LDAP:
     from py4web.utils.auth_plugins.ldap_plugin import LDAPPlugin
 
-    auth.register_plugin(LDAPPlugin(db=db, groups=groups, **settings.LDAP_SETTINGS))
+    auth.register_plugin(LDAPPlugin(db=db, groups=groups, logger=logger, **settings.LDAP_SETTINGS))
 
 if settings.OAUTH2GOOGLE_CLIENT_ID:
     from py4web.utils.auth_plugins.oauth2google import OAuth2Google  # TESTED

py4web/utils/auth.py

@@ -6,6 +6,7 @@
 import re
 import time
 import uuid
+import logging
 
 import jwt
 
@@ -37,6 +38,18 @@
 [ ] Force new password every x days.
 """
 
+# Allow logger to be set externally before importing this module
+try:
+    logger  # type: ignore  # pylance: ignore undefined
+except NameError:
+    # If not set, define a default logger
+    logger = logging.getLogger("py4web.auth")
+    if not logger.hasHandlers():
+        handler = logging.StreamHandler()
+        formatter = logging.Formatter("%(asctime)s - %(levelname)s - %(message)s")
+        handler.setFormatter(formatter)
+        logger.addHandler(handler)
+
 
 def b16e(text):
     """convert unicode to b16 unicode"""
@@ -124,6 +137,7 @@ def on_request(self, context):
             message = self.auth.param.messages["flash"].get("login-required")
             self.goto_login(message=message)
 
+        user = self.auth.session.get("user")
         if callable(self.condition) and not self.condition(user):
             self.abort_or_redirect("not-authorized", "User not authorized")
 
@@ -153,7 +167,7 @@ class Auth(Fixture):
             "user-logout": "User logout",
             "email-verified": "Email verified",
             "link-expired": "Link invalid or expired",
-            "login-required": "Login required,",
+            "login-required": "Login required",
         },
         "labels": {
             "username": "Username",
@@ -675,18 +689,20 @@ def login(self, email, password):
         for plugin in self.plugins.values():
             if not hasattr(plugin, "get_login_url"):
                 prevent_db_lookup = True
+                logger.debug(f"Trying plugin: {plugin.name}, mode: {getattr(plugin, 'mode', None)}")
                 if plugin.check_credentials(email, password):
-                    # if the credentials are independently validated
-                    # get or create the user (if does not exist)
+                    logger.debug(f"Plugin {plugin.name} accepted credentials for {email}")
                     user_info = {}
                     user_info["sso_id"] = plugin.name + ":" + email
                     if self.use_username or "@" not in email:
                         user_info["username"] = email
                     if "@" in email:
                         user_info["email"] = email
                     else:
+                        logger.debug(f"Constructing email from username: {email}@example.com")
                         user_info["email"] = email + "@example.com"
                     user = self.get_or_register_user(user_info)
+                    logger.debug(f"User after get_or_register_user: {user}")
                     break
 
         # else check against database
@@ -1278,7 +1294,10 @@ def login(auth):
         # Prioritize PAM or LDAP logins if enabled
         if "pam" in auth.plugins or "ldap" in auth.plugins:
             plugin_name = "pam" if "pam" in auth.plugins else "ldap"
-            check = auth.plugins[plugin_name].check_credentials(username, password)
+            plugin = auth.plugins[plugin_name]
+            logger.debug(f"AuthAPI.login: Trying plugin {plugin_name} for user {username}")
+            check = plugin.check_credentials(username, password)
+            logger.debug(f"AuthAPI.login: plugin.check_credentials returned {check}")
             if check:
                 data = {
                     "username": username,
@@ -1287,10 +1306,13 @@ def login(auth):
                 }
                 # and register the user if we have one, just in case
                 if auth.db:
+                    logger.debug(f"AuthAPI.login: Calling get_or_register_user with data={data}")
                     user = auth.get_or_register_user(data)
+                    logger.debug(f"AuthAPI.login: User after get_or_register_user: {user}")
                     auth.store_user_in_session(user["id"])
                 # else: if we're here - check is OK, but user is not in the session - is it right?
             else:
+                logger.debug(f"AuthAPI.login: plugin.check_credentials failed for {username}")
                 data = auth._error(
                     auth.param.messages["errors"].get("invalid_credentials")
                 )