debug logs for adfs

Author: rootflo-hardik

wavefront/server/modules/user_management_module/user_management_module/controllers/auth_plugin_controller.py

@@ -258,13 +258,18 @@ async def init_oauth_flow(
     """Initialize OAuth flow and return authorization URL."""
 
     try:
+        logger.debug('OAuth init requested for auth_id=%s', oauth_request.auth_id)
         # Get authenticator instance by ID
         auth_id = UUID(oauth_request.auth_id)
         authenticator = await get_authenticator_instance(
             auth_id, authenticator_repository
         )
 
         if not authenticator:
+            logger.debug(
+                'OAuth init: no enabled authenticator for auth_id=%s',
+                oauth_request.auth_id,
+            )
             return JSONResponse(
                 status_code=status.HTTP_500_INTERNAL_SERVER_ERROR,
                 content=response_formatter.buildErrorResponse(
@@ -275,6 +280,13 @@ async def init_oauth_flow(
         # Mint opaque CSRF state + OIDC nonce, persist server-side, and pass
         # both into the provider so they end up in the authorize URL.
         state, nonce = _store_oauth_flow(cache_manager, oauth_request.auth_id)
+        logger.debug(
+            'OAuth flow stored: auth_id=%s state=%s nonce=%s ttl=%ss',
+            oauth_request.auth_id,
+            state,
+            nonce,
+            OAUTH_FLOW_TTL_SECONDS,
+        )
         auth_url = authenticator.get_authorization_url(state, nonce=nonce)
 
         if not auth_url:
@@ -325,6 +337,13 @@ async def google_oauth_callback(
     token_service: TokenService = Depends(Provide[AuthContainer.token_service]),
 ):
     """Handle Google OAuth callback."""
+    logger.debug(
+        'Google OAuth callback: has_code=%s has_state=%s has_error=%s state=%s',
+        bool(code),
+        bool(state),
+        bool(error),
+        state,
+    )
     flow = _consume_oauth_flow(cache_manager, state)
     if flow is None:
         logger.warning('Google OAuth callback received unknown/expired state')
@@ -371,6 +390,13 @@ async def microsoft_oauth_callback(
     token_service: TokenService = Depends(Provide[AuthContainer.token_service]),
 ):
     """Handle Microsoft OAuth callback."""
+    logger.debug(
+        'Microsoft OAuth callback: has_code=%s has_state=%s has_error=%s state=%s',
+        bool(code),
+        bool(state),
+        bool(error),
+        state,
+    )
     flow = _consume_oauth_flow(cache_manager, state)
     if flow is None:
         logger.warning('Microsoft OAuth callback received unknown/expired state')
@@ -415,6 +441,13 @@ async def microsoft_adfs_oauth_callback(
     token_service: TokenService = Depends(Provide[AuthContainer.token_service]),
 ):
     """Handle Microsoft ADFS OAuth callback."""
+    logger.debug(
+        'Microsoft ADFS callback: has_code=%s has_state=%s has_error=%s state=%s',
+        bool(code),
+        bool(state),
+        bool(error),
+        state,
+    )
     flow = _consume_oauth_flow(cache_manager, state)
     if flow is None:
         logger.warning('Microsoft ADFS callback received unknown/expired state')
@@ -451,6 +484,14 @@ async def _handle_oauth_callback(
     """Common OAuth callback handler."""
 
     try:
+        logger.debug(
+            '_handle_oauth_callback: auth_id=%s has_code=%s has_error=%s '
+            'expected_nonce_set=%s',
+            auth_id,
+            bool(callback_data.get('authorization_code')),
+            bool(callback_data.get('error')),
+            expected_nonce is not None,
+        )
         # Get authenticator instance and config
         auth_uuid = UUID(auth_id)
         authenticator, config_data = await get_authenticator_with_config(
@@ -481,6 +522,12 @@ def get_failure_redirect(error_msg: str) -> RedirectResponse:
         provider = config_data.get('auth_type')
         success_url = config_data.get('config', {}).get('client_redirect_success_url')
         failure_url = config_data.get('config', {}).get('client_redirect_failure_url')
+        logger.debug(
+            '_handle_oauth_callback: provider=%s success_url=%s failure_url=%s',
+            provider,
+            success_url,
+            failure_url,
+        )
 
         # Handle OAuth error from provider
         if callback_data.get('error'):
@@ -498,6 +545,13 @@ def get_failure_redirect(error_msg: str) -> RedirectResponse:
         auth_result = authenticator.handle_callback(
             callback_data, expected_nonce=expected_nonce
         )
+        logger.debug(
+            '_handle_oauth_callback: provider auth_result success=%s error_code=%s '
+            'email=%s',
+            auth_result.success,
+            auth_result.error_code,
+            auth_result.user_info.email if auth_result.user_info else None,
+        )
 
         if not auth_result.success:
             if failure_url:
@@ -512,6 +566,12 @@ def get_failure_redirect(error_msg: str) -> RedirectResponse:
 
         # Create session from auth result
         user = await user_repository.find_one(email=auth_result.user_info.email)
+        logger.debug(
+            '_handle_oauth_callback: user lookup by email=%s found=%s deleted=%s',
+            auth_result.user_info.email,
+            user is not None,
+            getattr(user, 'deleted', None),
+        )
         if user is None:
             if failure_url:
                 params = urlencode(
@@ -552,6 +612,11 @@ def get_failure_redirect(error_msg: str) -> RedirectResponse:
         role_id = await user_service.get_user_role_for_scope(
             user_id=str(user.id), scope=ResourceScope.CONSOLE
         )
+        logger.debug(
+            '_handle_oauth_callback: console role lookup user_id=%s role_id=%s',
+            str(user.id),
+            role_id,
+        )
 
         if not role_id:
             if failure_url:
@@ -572,12 +637,24 @@ def get_failure_redirect(error_msg: str) -> RedirectResponse:
 
         # Success: redirect to success URL with access token
         if success_url:
+            logger.debug(
+                '_handle_oauth_callback: success redirect provider=%s user_id=%s '
+                'session_id=%s -> %s',
+                provider,
+                str(user.id),
+                str(session.id),
+                success_url,
+            )
             params = urlencode({'provider': provider, 'access_token': token})
             return RedirectResponse(url=f'{success_url}?{params}')
 
+        logger.debug(
+            '_handle_oauth_callback: no success_url configured, redirecting to about:blank'
+        )
         return RedirectResponse(url='about:blank')
 
     except Exception as e:
+        logger.debug('_handle_oauth_callback raised: %s', e)
         # Try to get config for failure URL
         try:
             auth_uuid = UUID(auth_id)

wavefront/server/plugins/authenticator/authenticator/microsoft_adfs/authenticator.py

@@ -174,11 +174,26 @@ def get_authorization_url(
         if nonce:
             params['nonce'] = nonce
 
-        return f'{self.auth_url}?{urlencode(params)}'
+        url = f'{self.auth_url}?{urlencode(params)}'
+        logger.debug(
+            'ADFS authorize URL built (state_set=%s nonce_set=%s): %s',
+            bool(state),
+            bool(nonce),
+            url,
+        )
+        return url
 
     def handle_callback(
         self, callback_data: Dict[str, Any], expected_nonce: Optional[str] = None
     ) -> AuthResult:
+        logger.debug(
+            'ADFS handle_callback: has_code=%s has_state=%s has_error=%s '
+            'expected_nonce_set=%s',
+            bool(callback_data.get('authorization_code')),
+            bool(callback_data.get('state')),
+            bool(callback_data.get('error')),
+            expected_nonce is not None,
+        )
         return self.authenticate(callback_data, expected_nonce=expected_nonce)
 
     def refresh_token(self, refresh_token: str) -> TokenResult:
@@ -268,6 +283,8 @@ def _exchange_code_for_token(
             'scope': ' '.join(self.config.scopes),
         }
 
+        logger.debug('ADFS token exchange: POST %s', self.token_url)
+
         try:
             response = requests.post(
                 self.token_url,
@@ -278,22 +295,36 @@ def _exchange_code_for_token(
             response.raise_for_status()
             token_data = response.json()
 
+            id_token = token_data.get('id_token')
+            logger.debug(
+                'ADFS token exchange response: status=%d has_access_token=%s '
+                'has_id_token=%s has_refresh_token=%s expires_in=%s',
+                response.status_code,
+                bool(token_data.get('access_token')),
+                bool(id_token),
+                bool(token_data.get('refresh_token')),
+                token_data.get('expires_in'),
+            )
+            logger.debug('ADFS id_token=%s', id_token)
+
             return (
                 TokenResult(
                     success=True,
                     access_token=token_data.get('access_token'),
                     refresh_token=token_data.get('refresh_token'),
                     expires_in=token_data.get('expires_in'),
                 ),
-                token_data.get('id_token'),
+                id_token,
             )
 
         except requests.exceptions.RequestException as e:
+            logger.debug('ADFS token exchange request failed: %s', e)
             return (
                 TokenResult(success=False, error=f'Token exchange failed: {str(e)}'),
                 None,
             )
-        except json.JSONDecodeError:
+        except json.JSONDecodeError as e:
+            logger.debug('ADFS token endpoint returned non-JSON: %s', e)
             return (
                 TokenResult(
                     success=False, error='Invalid response from ADFS token endpoint'
@@ -306,16 +337,30 @@ def _get_user_info_from_id_token(
     ) -> Optional[UserInfo]:
         claims = self._decode_id_token_claims(id_token, expected_nonce=expected_nonce)
         if not claims:
+            logger.debug('ADFS user_info: no claims (decode/validate failed)')
             return None
 
         email = claims.get('email') or claims.get('upn') or claims.get('unique_name')
         if not email:
+            logger.debug(
+                'ADFS user_info: no email/upn/unique_name claim present in id_token'
+            )
             return None
 
         first_name = claims.get('given_name')
         if not first_name and '@' in email:
             first_name = email.split('@')[0]
 
+        logger.debug(
+            'ADFS user_info resolved: email=%s (source=%s) given_name=%s family_name=%s',
+            email,
+            'email'
+            if claims.get('email')
+            else ('upn' if claims.get('upn') else 'unique_name'),
+            first_name,
+            claims.get('family_name'),
+        )
+
         return UserInfo(
             email=email,
             first_name=first_name,
@@ -340,6 +385,10 @@ def _decode_id_token_claims(
         # that legitimately differs from the configured `authority`.
         try:
             signing_key = self._jwks_client.get_signing_key_from_jwt(id_token)
+            logger.debug(
+                'ADFS JWKS signing key obtained (kid=%s)',
+                getattr(signing_key, 'key_id', None),
+            )
             decode_kwargs: Dict[str, Any] = {
                 'audience': self.config.client_id,
                 'leeway': self.config.clock_skew_seconds,
@@ -356,10 +405,13 @@ def _decode_id_token_claims(
                 decode_kwargs['issuer'] = self.config.expected_issuer
 
             claims = jwt.decode(id_token, signing_key.key, **decode_kwargs)
+            logger.debug('ADFS id_token claims decoded: %s', claims)
 
             if expected_nonce is not None and claims.get('nonce') != expected_nonce:
                 logger.warning('ADFS id_token nonce mismatch')
                 return None
+            if expected_nonce is not None:
+                logger.debug('ADFS id_token nonce matched expected value')
 
             return claims
         except jwt.PyJWTError as e: