Add logging for expiration, discovery and caching. Remove some debug logs

fence/resources/ga4gh/passports.py

@@ -515,8 +515,8 @@ def put_gen3_usernames_for_passport_into_cache(
     )
 
     logger.debug(
-        f"Cached users {user_ids_from_passports} for provided passport in "
-        f"database cache and placed in in-memory cache. "
+        f"Cached {user_ids_from_passports} passport in "
+        f"database. "
         f"Expires: {expires_at}"
     )
 

fence/resources/google/utils.py

@@ -582,7 +582,9 @@ def _update_service_account_db_entry(
     return service_account_db_entry
 
 
-def get_or_create_proxy_group_id(expires=None, user_id=None, username=None, session=None, storage_manager=None):
+def get_or_create_proxy_group_id(
+    expires=None, user_id=None, username=None, session=None, storage_manager=None
+):
     """
     If no username returned from token or database, create a new proxy group
     for the given user. Also, add the access privileges.
@@ -598,17 +600,18 @@ def get_or_create_proxy_group_id(expires=None, user_id=None, username=None, sess
     db_session = session or current_app.scoped_session()
     manager = storage_manager or flask.current_app.storage_manager
 
-    logger.info(f"Proxy Group: {user_id}, {username}")
-    proxy_group_id = _get_proxy_group_id(user_id=user_id, username=username, session=db_session)
-    logger.info(f"{proxy_group_id}")
+    logger.info(f"Getting proxy group for: {user_id}, {username}")
+    proxy_group_id = _get_proxy_group_id(
+        user_id=user_id, username=username, session=db_session
+    )
     if not proxy_group_id:
         try:
+            logger.info(
+                f"No proxy group found for {user_id}, {username}... attempting to create one"
+            )
             user_by_id = query_for_user_by_id(db_session, user_id)
             logger.info(f"user_by_id: {user_by_id}")
-            user_by_username = query_for_user(
-                session=db_session, username=username
-            )
-            logger.info(f"user_by_username: {user_by_username}")
+            user_by_username = query_for_user(session=db_session, username=username)
         except Exception:
             user_by_id = None
             user_by_username = None
@@ -630,10 +633,8 @@ def get_or_create_proxy_group_id(expires=None, user_id=None, username=None, sess
 
         proxy_group_id = _create_proxy_group(user_id, username, session=db_session).id
 
-        privileges = (
-            db_session
-            .query(AccessPrivilege)
-            .filter(AccessPrivilege.user_id == user_id)
+        privileges = db_session.query(AccessPrivilege).filter(
+            AccessPrivilege.user_id == user_id
         )
 
         for p in privileges:

fence/resources/openid/idp_oauth2.py

@@ -92,6 +92,7 @@ def get_value_from_discovery_doc(self, key, default_value):
         using their discovery url.
         """
         if self.discovery_url:
+            self.logger.debug(f"Using {self.discovery_url} to get discovery doc")
             return_value = default_value
             if self.discovery_doc.status_code == requests.codes.ok:
                 return_value = self.discovery_doc.json().get(key)
@@ -125,6 +126,7 @@ def get_value_from_discovery_doc(self, key, default_value):
                 )
         # no `discovery_url`, try to use `discovery` config instead
         else:
+            self.logger.debug(f"Using discovery from fence settings")
             return_value = self.settings.get("discovery", {}).get(key, default_value)
 
         if not return_value:

fence/resources/openid/ras_oauth2.py

@@ -298,7 +298,9 @@ def update_user_authorization(self, user, pkey_cache, db_session=None):
         db_session = db_session or current_app.scoped_session()
         try:
             token_endpoint = self.get_value_from_discovery_doc("token_endpoint", "")
-
+            self.logger.info(
+                f"Using token_endpoint {token_endpoint} from discovery doc"
+            )
             # this get_access_token also persists the refresh token in the db
             token = self.get_access_token(user, token_endpoint, db_session)
             userinfo = self.get_userinfo(token)

fence/sync/passport_sync/ras_sync.py

@@ -62,6 +62,10 @@ def _parse_single_visa(self, user, encoded_visa, expires, parse_consent_code):
                     if permission_expiration and expires <= permission_expiration:
                         project[full_phsid] = privileges
                         info["tags"] = {"dbgap_role": permission.get("role", "")}
+                    else:
+                        self.logger.info(
+                            f"dbGaP permission for {full_phsid} expired at {permission_expiration}"
+                        )
         else:
             # Remove visas if its invalid or expired
             user.ga4gh_visas_v1 = []

fence/sync/sync_users.py

@@ -2521,7 +2521,6 @@ def sync_single_user_visas(
             )
 
         if user_projects:
-            self.logger.info("Sync to storage backend [sync_single_user_visas]")
             self.sync_to_storage_backend(
                 user_projects,
                 info,