Add logging

Author: kcagran

requirements-build.txt

@@ -486,6 +486,7 @@ django==5.2.8 \
     #   django-crum
     #   django-filter
     #   django-generate-series
+    #   django-guid
     #   django-solo
     #   django-weasyprint
     #   djangorestframework
@@ -509,6 +510,10 @@ django-generate-series==0.5.0 \
     --hash=sha256:54e33e5aba69be75f591bda970421dee9f1c5feeb84c20d8cee634bcc0e249bc \
     --hash=sha256:8cced6473ba75aed5e1e2ecd6f5426d11d33926e86d2630dabe9c424b7a6da8a
     # via -r requirements-pinned.txt
+django-guid==3.5.2 \
+    --hash=sha256:0f812a837579031c7db8524b07e498f65b5fcf191857c1f7fb5414a0ceb584fa \
+    --hash=sha256:cadbc929bfa2b19c6f9e847da3e095ebebe1124adef92f0af317f963ee51a6cb
+    # via -r requirements-pinned.txt
 django-solo==2.4.0 \
     --hash=sha256:62e9c7d929620a61848515839833750ca142840051595cf5c8e617dcefc9e5cf \
     --hash=sha256:ec92dc00aec75034a3f93b3a85152e57c4b03d7987f8cfd0ea8a47cc6e3c2084
@@ -676,6 +681,7 @@ packaging==25.0 \
     --hash=sha256:d443872c98d677bf60f6a1f2f8c1cb748e8fe762d2bf9d3148b5599295b0fc4f
     # via
     #   ansible-runner
+    #   django-guid
     #   pytest
 pexpect==4.9.0 \
     --hash=sha256:7236d1e080e4936be2dc3e326cec0af72acf9212a7e1d060210e70a47e253523 \

requirements-pinned.txt

@@ -8,6 +8,7 @@ django-ansible-base==2025.10.20
 django-cors-headers==4.9.0
 django-filter==25.2
 django-generate-series==0.5.0
+django-guid==3.5.2
 django-solo==2.4.0
 django-weasyprint==2.4.0
 djangorestframework==3.16.1

requirements.txt

@@ -8,6 +8,7 @@ django-ansible-base==2025.10.20
 django-cors-headers==4.9.0
 django-filter==25.2
 django-generate-series==0.5.0
+django-guid==3.5.2
 django-solo==2.4.0
 django-weasyprint==2.4.0
 djangorestframework==3.16.1

src/backend/apps/aap_auth/aap_auth.py

@@ -13,7 +13,7 @@
 from backend.apps.users.models import User
 from backend.apps.users.schemas import UserResponseSchema
 
-logger = logging.getLogger("automation-dashboard")
+logger = logging.getLogger("automation-dashboard.aap_auth")
 
 
 def memoize(func):
@@ -35,8 +35,9 @@ class AAPAuth:
     # Handles AAP authentication and user management
 
     def __init__(self):
-        # Initialize authentication settings from config
+        logger.info("Initializing AAPAuth")
         auth_settings = AAPAuthSettings(**settings.AAP_AUTH_PROVIDER)
+        logger.debug(f"Auth settings: {auth_settings}")
         setting_url = auth_settings.url[:-1] if auth_settings.url.endswith('/') else auth_settings.url
 
         self.name = auth_settings.name
@@ -50,59 +51,65 @@ def __init__(self):
         self.user_data_uri = user_data_uri
         self.check_ssl = auth_settings.check_ssl
 
+        logger.info("Fetching OAuth endpoints")
         o_endpoints = self.get_o_endpoints()
+        logger.debug(f"OAuth endpoints: {o_endpoints}")
 
         self.authorize_uri = o_endpoints["authorize_uri"]
         self.token_uri = o_endpoints["token_uri"]
         self.revoke_token_uri = o_endpoints["revoke_token_uri"]
 
-        # Optionally suppress urllib3 SSL warnings
         if not settings.SHOW_URLLIB3_INSECURE_REQUEST_WARNING:
             urllib3.disable_warnings(urllib3.exceptions.InsecureRequestWarning)
-
+        logger.info("AAPAuth initialized successfully")
 
     def ping(self, url: str) -> Response:
-        logger.info(f"Try to obtain OAuth endpoint {url}")
+        logger.info(f"Trying to obtain OAuth endpoint: {url}")
         try:
             response = requests.get(
                 url=url,
                 verify=self.check_ssl,
                 allow_redirects=False,
                 timeout=3)
+            logger.debug(f"Ping response status: {response.status_code}")
         except requests.exceptions.HTTPError as e:
-            logger.error(f'GET request {url} failed with exception {e}')
+            logger.error(f'GET request {url} failed: {e}')
             raise AuthenticationFailed(f"Failed request to {url}")
         if response.ok:
-            logger.info(f"Successfully obtained OAuth endpoint {url}")
+            logger.info(f"Successfully obtained OAuth endpoint: {url}")
         return response
 
-    # Cache the OAuth endpoints to avoid pinging the server on every call
     @memoize
     def get_o_endpoints(self):
+        logger.info("Getting OAuth endpoints")
         url = f"{self.url}/o/"
         response = self.ping(url)
+        logger.debug(f"First endpoint response: {response.ok}")
         if response.ok:
             result = {
                 'authorize_uri': '/o/authorize/',
                 'token_uri': '/o/token/',
                 'revoke_token_uri': '/o/revoke_token/'
             }
+            logger.info("OAuth endpoints found at /o/")
             return result
 
         url = f"{self.url}/api/o/"
         response = self.ping(url)
+        logger.debug(f"Second endpoint response: {response.ok}")
         if response.ok:
             result = {
                 'authorize_uri': '/api/o/authorize/',
                 'token_uri': '/api/o/token/',
                 'revoke_token_uri': '/api/o/revoke_token/'
             }
+            logger.info("OAuth endpoints found at /api/o/")
             return result
         logger.error("Failed to obtain OAuth endpoints after multiple attempts.")
         raise AuthenticationFailed("Authorization failed: Unable to find a valid OAuth endpoint.")
 
     def ui_data(self) -> dict[str, str]:
-        # Returns data needed for UI authorization flow
+        logger.debug("Preparing UI data for authorization flow")
         return {
             'name': self.name,
             'url': f'{self.url}{self.authorize_uri}',
@@ -113,28 +120,33 @@ def ui_data(self) -> dict[str, str]:
         }
 
     def _aap_authorize(self, params: dict[str, str]) -> AAPToken:
-        # Requests an AAP token using provided parameters
+        logger.info("Requesting AAP token")
+        logger.debug(f"Token request params: {params}")
         response = requests.post(
             url=f"{self.url}{self.token_uri}",
             data=params,
             verify=self.check_ssl,
             allow_redirects=False,
             timeout=30,
         )
+        logger.debug(f"AAP token response status: {response.status_code}")
         if not response.ok:
-            logger.error("An error occurred obtaining AAP token. %s", response.content)
+            logger.error("Error obtaining AAP token: %s", response.content)
             raise AuthenticationFailed("Obtaining of AAP token failed. An error occurred connecting to AAP authorization server.")
 
         token_result = response.json()
+        logger.debug(f"Token result: {token_result}")
         access_token = token_result.get("access_token", None)
         refresh_token = token_result.get("refresh_token", None)
 
         if access_token is None or refresh_token is None:
+            logger.error("Invalid token response from AAP")
             raise AuthenticationFailed("Obtaining of AAP token failed. Invalid response from AAP.")
         return AAPToken(**token_result)
 
     def authorize(self, code: str, redirect_uri: str) -> dict[str, JwtUserToken | JwtUserRefreshToken]:
-        # Exchanges authorization code for tokens and user info
+        logger.info("Authorizing user")
+        logger.debug(f"Authorization code: {code}, redirect_uri: {redirect_uri}")
         token_params = {
             "client_id": self.client_id,
             "client_secret": self.client_secret,
@@ -145,10 +157,12 @@ def authorize(self, code: str, redirect_uri: str) -> dict[str, JwtUserToken | Jw
         aap_token = self._aap_authorize(token_params)
         user = self.get_user_data(aap_token)
         jwt_token = JWTToken()
+        logger.info("User authorized successfully")
         return jwt_token.acquire_token_pair(aap_token=aap_token, user=user)
 
     def get_user_data(self, aap_token: AAPToken) -> User:
-        # Fetches user data from AAP using the access token
+        logger.info("Fetching user data from AAP")
+        logger.debug(f"Access token: {aap_token.access_token}")
         headers = {
             'Authorization': f'{aap_token.token_type} {aap_token.access_token}',
             'Content-Type': 'application/json',
@@ -163,26 +177,31 @@ def get_user_data(self, aap_token: AAPToken) -> User:
                 timeout=30,
                 headers=headers
             )
+            logger.debug(f"User data response status: {user_response.status_code}")
             user_response.raise_for_status()
         except requests.exceptions.HTTPError as e:
-            logger.error("An error occurred obtaining AAP user. %s", e.response.content)
+            logger.error("Error obtaining AAP user: %s", e.response.content)
             raise AuthenticationFailed("An error occurred obtaining AAP user.")
         except requests.exceptions.RequestException as e:
             logger.error(f"Failed to validate token with AAP: {str(e)}")
             raise ValueError("Failed to validate token with AAP")
 
         users = UserResponseSchema(**user_response.json())
+        logger.debug(f"User response schema: {users}")
         if users.count != 1:
-            logger.error(f"Failed to retrieve AAP user. {str(users)}")
+            logger.error(f"Failed to retrieve AAP user: {str(users)}")
             raise ValueError("Failed to retrieve AAP user.")
+        logger.info("User data fetched successfully")
         return User.create_or_update_aap_user(users.results[0])
 
     def refresh_token(self, refresh_token: str) -> dict[str, JwtUserToken | JwtUserRefreshToken]:
-        # Refreshes JWT tokens using the AAP refresh token
+        logger.info("Refreshing JWT token")
+        logger.debug(f"Refresh token: {refresh_token}")
         jwt_token = JWTToken()
         refresh_token = jwt_token.decode_refresh_token(token=refresh_token)
 
         if refresh_token is None:
+            logger.error("Refresh token is invalid")
             raise NotAuthenticated("Refresh token is invalid.")
 
         token_params = {
@@ -195,17 +214,19 @@ def refresh_token(self, refresh_token: str) -> dict[str, JwtUserToken | JwtUserR
         user = self.get_user_data(aap_token)
 
         refresh_token.revoke_token()
-
+        logger.info("JWT token refreshed successfully")
         return jwt_token.acquire_token_pair(aap_token=aap_token, user=user)
 
     def logout(self, access_token: str) -> dict[str, any]:
-        # Revokes the AAP token and logs out the user
+        logger.info("Logging out user")
+        logger.debug(f"Access token: {access_token}")
         token = JwtUserToken.get_user_token(access_token)
         result = {
             "success": True,
             "message": "",
         }
         if token is None or token.id is None:
+            logger.error("Invalid token for logout")
             raise AuthenticationFailed("Invalid token.")
 
         token_params = {
@@ -221,14 +242,16 @@ def logout(self, access_token: str) -> dict[str, any]:
             allow_redirects=False,
             timeout=30,
         )
+        logger.debug(f"Logout response status: {response.status_code}")
 
         if not response.ok:
-            logger.error("An error occurred revoking AAP token. %s", response.content)
+            logger.error("Error revoking AAP token: %s", response.content)
             result["success"] = False
             result["message"] = response.content
             result["status_code"] = response.status_code
             return result
 
         token.revoke_token()
+        logger.info("User logged out successfully")
         result["success"] = True
         return result

src/backend/apps/aap_auth/authentication.py

@@ -7,42 +7,52 @@
 
 from backend.apps.aap_auth.jwt_token import JWTToken
 
-logger = logging.getLogger("automation-dashboard")
+logger = logging.getLogger("automation-dashboard.auth")
 
 
 def enforce_csrf(request):
     """
     Enforce CSRF validation.
     """
+    logger.info("Starting CSRF validation.")
     check = CSRFCheck(request)
     check.process_request(request)
     reason = check.process_view(request, None, (), {})
     if reason:
+        logger.error('CSRF Failed: %s' % reason)
         raise exceptions.PermissionDenied('CSRF Failed: %s' % reason)
 
 
 class AAPAuthentication(BaseAuthentication):
     def authenticate(self, request: Request):
+        logger.info("Starting authentication process")
         token = request.COOKIES.get(settings.AUTH_COOKIE_ACCESS_TOKEN_NAME) or None
+        logger.debug(f"Token from cookies: {token}")
 
         if token is None:
+            logger.info("No token found in cookies")
             return None
 
-        if len(token) < 10:  # Basic length check
+        if len(token) < 10:
+            logger.warning("Token length is too short")
             return None
 
+        logger.debug("Attempting to decode token")
         jwt_token = JWTToken()
         db_token = jwt_token.decode_token(token)
 
         if db_token is None:
+            logger.warning("Failed to decode token")
             return None
 
         if not db_token.user.is_active:
+            logger.warning("User is not active")
             return None
 
         enforce_csrf(request)
-
+        logger.info("Authentication successful")
         return db_token.user, token
 
     def authenticate_header(self, request: Request) -> str:
+        logger.debug("Returning authentication header")
         return "Bearer"