Refactor logging (#53)

ea-mtenhoor · jayckaiser · web-flow · commit 9815aa0748ec · 2026-02-23T16:43:12.000-06:00
* Refactor logging

* Configure root logger to original logging handler format if no root logger has been defined at the application-level.

* Fix indendation.

* Add note to README about default logging handlers.

---------

Co-authored-by: jayckaiser &lt;jayckaiser@gmail.com&gt;
diff --git a/README.md b/README.md
@@ -61,7 +61,7 @@ If either `client_key` or `client_secret` are empty, a session with the ODS will
 
 
 All code examples in this document use verbose-logging to more-explicitly show interactions with the API.
-It is recommended to set `verbose=True` while working interactively with the API.
+It is recommended to set `verbose=True` while working interactively with the API. If logging handlers have not been configured before enabling verbose-logging, default package handlers will be used.
 
 ```python
 >>> from edfi_api_client import EdFiClient
diff --git a/edfi_api_client/__init__.py b/edfi_api_client/__init__.py
@@ -1,2 +1,6 @@
+import logging
+
 from edfi_api_client.edfi_client import EdFiClient
 from edfi_api_client.util import camel_to_snake, snake_to_camel, url_join
+
+logging.getLogger("edfi_api_client").addHandler(logging.NullHandler())
diff --git a/edfi_api_client/edfi_client.py b/edfi_api_client/edfi_client.py
@@ -9,13 +9,10 @@
 from edfi_api_client.session import EdFiSession
 from edfi_api_client.token_cache import BaseTokenCache
 
-
 import logging
-logging.basicConfig(
-    level="WARNING",
-    format='[%(asctime)s] %(levelname)s: %(message)s',
-    datefmt='%Y-%m-%d %H:%M:%S',
-)
+
+logger = logging.getLogger(__name__)
+
 
 class EdFiClient:
     """
@@ -49,9 +46,17 @@ def __init__(self,
         token_cache: Optional[BaseTokenCache] = None,
         **kwargs
     ):
-        # Update logger first
+        # Update package logger level when verbose mode is enabled
         if verbose:
-            logging.getLogger().setLevel(logging.INFO)
+            logging.getLogger("edfi_api_client").setLevel(logging.INFO)
+
+            # If no logger is enabled at the application level, enable it here.
+            if not logging.getLogger().handlers:
+                logging.basicConfig(
+                    level=logging.INFO,
+                    format='[%(asctime)s] %(levelname)s: %(message)s',
+                    datefmt='%Y-%m-%d %H:%M:%S',
+                )
 
         self.base_url = base_url
         self.client_key = client_key
@@ -188,7 +193,7 @@ def _set_swagger(self, component: str):
         :return:
         """
         if self.swaggers.get(component) is None:
-            logging.info(f"[Get {component.title()} Swagger] Retrieving Swagger into memory...")
+            logger.info(f"[Get {component.title()} Swagger] Retrieving Swagger into memory...")
             self.get_swagger(component)
 
 
@@ -296,7 +301,7 @@ def get_token_info(self) -> dict:
         https://edfi.atlassian.net/wiki/spaces/ODSAPIS3V520/pages/25100511/Authorization
         """
         token_info_url = util.url_join(self.base_url, "oauth/token_info")
-        logging.info(f"[Get Token Info] Endpoint: {token_info_url}")
+        logger.info(f"[Get Token Info] Endpoint: {token_info_url}")
 
         token_response = self.session.post_response(
             token_info_url,
@@ -314,7 +319,7 @@ def get_newest_change_version(self) -> int:
         :return:
         """
         change_version_url = util.url_join(self.base_url, 'changeQueries/v1', self.instance_locator, 'availableChangeVersions')
-        logging.info(f"[Get Newest Change Version] Endpoint: {change_version_url}")
+        logger.info(f"[Get Newest Change Version] Endpoint: {change_version_url}")
 
         res = self.session.get_response(change_version_url)
         if not res.ok:
diff --git a/edfi_api_client/edfi_endpoint.py b/edfi_api_client/edfi_endpoint.py
@@ -11,6 +11,8 @@
 if TYPE_CHECKING:
     from edfi_api_client.edfi_client import EdFiClient
 
+logger = logging.getLogger(__name__)
+
 
 class EdFiEndpoint:
     """
@@ -75,7 +77,7 @@ def _parse_names(client: 'EdFiClient', namespace: str, name: str) -> Tuple[str,
         elif len(name) == 2:
             return name
         else:
-            logging.error("Arguments `namespace` and `name` must be passed explicitly, or as a `(namespace, name)` tuple.")
+            logger.error("Arguments `namespace` and `name` must be passed explicitly, or as a `(namespace, name)` tuple.")
 
     @property
     def raw(self) -> str:
@@ -109,7 +111,7 @@ def ping(self, *, params: Optional[dict] = None, **kwargs) -> requests.Response:
 
         :return:
         """
-        logging.info(f"[Ping {self.component}] Endpoint: {self.url}")
+        logger.info(f"[Ping {self.component}] Endpoint: {self.url}")
 
         # Override init params if passed
         params = EdFiParams(params or self.params).copy()
@@ -129,14 +131,14 @@ def get(self, limit: Optional[int] = None, *, params: Optional[dict] = None, **k
 
         :return:
         """
-        logging.info(f"[Get {self.component}] Endpoint: {self.url}")
+        logger.info(f"[Get {self.component}] Endpoint: {self.url}")
 
         # Override init params if passed
         params = EdFiParams(params or self.params).copy()
         if limit:  # Override limit if passed
             params['limit'] = limit
 
-        logging.info(f"[Get {self.component}] Parameters: {params}")
+        logger.info(f"[Get {self.component}] Parameters: {params}")
         return self.client.session.get_response(self.url, params=params, **kwargs).json()
 
 
@@ -202,42 +204,42 @@ def get_pages(self,
 
         ### Prepare pagination variables, depending on type of pagination being used
         if step_change_version and reverse_paging:
-            logging.info(f"[Paged Get {self.component}] Pagination Method: Change Version Stepping with Reverse-Offset Pagination")
+            logger.info(f"[Paged Get {self.component}] Pagination Method: Change Version Stepping with Reverse-Offset Pagination")
             paged_params.init_page_by_change_version_step(change_version_step_size)
             total_count = self.get_total_count(params=paged_params, **kwargs)
             paged_params.init_reverse_page_by_offset(total_count, page_size)
 
         elif step_change_version:
-            logging.info(f"[Paged Get {self.component}] Pagination Method: Change Version Stepping")
+            logger.info(f"[Paged Get {self.component}] Pagination Method: Change Version Stepping")
             paged_params.init_page_by_offset(page_size)
             paged_params.init_page_by_change_version_step(change_version_step_size)
 
         else:
-            logging.info(f"[Paged Get {self.component}] Pagination Method: Offset Pagination")
+            logger.info(f"[Paged Get {self.component}] Pagination Method: Offset Pagination")
             paged_params.init_page_by_offset(page_size)
 
         # Begin pagination-loop
         while True:
 
             ### GET from the API and yield the resulting JSON payload
             paged_rows = self.get(params=paged_params, **kwargs)
-            logging.info(f"[Get {self.component}] Retrieved {len(paged_rows)} rows.")
+            logger.info(f"[Get {self.component}] Retrieved {len(paged_rows)} rows.")
             yield paged_rows
 
             ### Paginate, depending on the method specified in arguments
             # Reverse offset pagination is only applicable during change-version stepping.
             if step_change_version and reverse_paging:
-                logging.info(f"[Paged Get {self.component}] @ Reverse-paginating offset...")
+                logger.info(f"[Paged Get {self.component}] @ Reverse-paginating offset...")
                 try:
                     paged_params.reverse_page_by_offset()
                 except StopIteration:
-                    logging.info(f"[Paged Get {self.component}] @ Reverse-paginated into negatives. Stepping change version...")
+                    logger.info(f"[Paged Get {self.component}] @ Reverse-paginated into negatives. Stepping change version...")
                     try:
                         paged_params.page_by_change_version_step()  # This raises a StopIteration if max change version is exceeded.
                         total_count = self.get_total_count(params=paged_params, **kwargs)
                         paged_params.init_reverse_page_by_offset(total_count, page_size)
                     except StopIteration:
-                        logging.info(f"[Paged Get {self.component}] @ Change version exceeded max. Ending pagination.")
+                        logger.info(f"[Paged Get {self.component}] @ Change version exceeded max. Ending pagination.")
                         break
 
             else:
@@ -246,18 +248,18 @@ def get_pages(self,
 
                     if step_change_version:
                         try:
-                            logging.info(f"[Paged Get {self.component}] @ Stepping change version...")
+                            logger.info(f"[Paged Get {self.component}] @ Stepping change version...")
                             paged_params.page_by_change_version_step()  # This raises a StopIteration if max change version is exceeded.
                         except StopIteration:
-                            logging.info(f"[Paged Get {self.component}] @ Change version exceeded max. Ending pagination.")
+                            logger.info(f"[Paged Get {self.component}] @ Change version exceeded max. Ending pagination.")
                             break
                     else:
-                        logging.info(f"[Paged Get {self.component}] @ Retrieved zero rows. Ending pagination.")
+                        logger.info(f"[Paged Get {self.component}] @ Retrieved zero rows. Ending pagination.")
                         break
 
                 # Otherwise, paginate offset.
                 else:
-                    logging.info(f"@ Paginating offset...")
+                    logger.info(f"@ Paginating offset...")
                     paged_params.page_by_offset()
 
 
@@ -269,19 +271,19 @@ def get_total_count(self, *, params: Optional[dict] = None, **kwargs) -> int:
 
         :return:
         """
-        logging.info(f"[Get Total Count {self.component}] Endpoint: {self.url}")
+        logger.info(f"[Get Total Count {self.component}] Endpoint: {self.url}")
 
         # Override init params if passed
         params = EdFiParams(params or self.params).copy()
         params['totalCount'] = True
         params['limit'] = 0
 
-        logging.info(f"[Get Total Count {self.component}] Parameters: {params}")
+        logger.info(f"[Get Total Count {self.component}] Parameters: {params}")
         res = self.client.session.get_response(self.url, params, **kwargs)
         return int(res.headers.get('Total-Count'))
 
     def total_count(self, *args, **kwargs) -> int:
-        logging.warning("`EdFiEndpoint.total_count()` is deprecated. Use `EdFiEndpoint.get_total_count()` instead.")
+        logger.warning("`EdFiEndpoint.total_count()` is deprecated. Use `EdFiEndpoint.get_total_count()` instead.")
         return self.get_total_count(*args, **kwargs)
 
 
@@ -331,7 +333,7 @@ def __init__(self, *args, **kwargs):
         super().__init__(*args, **kwargs)
 
         if self.get_deletes:
-            logging.warning("Descriptors do not have /deletes endpoints. Argument `get_deletes` has been ignored.")
+            logger.warning("Descriptors do not have /deletes endpoints. Argument `get_deletes` has been ignored.")
 
 
 class EdFiComposite(EdFiEndpoint):
@@ -356,9 +358,9 @@ def __init__(self,
         super().__init__(*args, **kwargs)
 
         if self.get_deletes:
-            logging.warning("Composites do not have /deletes endpoints. Argument `get_deletes` has been ignored.")
+            logger.warning("Composites do not have /deletes endpoints. Argument `get_deletes` has been ignored.")
         if self.get_key_changes:
-            logging.warning("Composites do not have /keyChanges endpoints. Argument `get_key_changes` has been ignored.")
+            logger.warning("Composites do not have /keyChanges endpoints. Argument `get_key_changes` has been ignored.")
 
 
     def __repr__(self):
@@ -414,10 +416,10 @@ def get_pages(self, *, params: Optional[dict] = None, page_size: int = 100, **kw
         :return:
         """
         if kwargs.get('step_change_version'):
-            logging.warning("Change versions are not implemented in composites! Change version stepping arguments are ignored.")
+            logger.warning("Change versions are not implemented in composites! Change version stepping arguments are ignored.")
 
-        logging.info(f"[Paged Get {self.component}] Endpoint: {self.url}")
-        logging.info(f"[Paged Get {self.component}] Pagination Method: Offset Pagination")
+        logger.info(f"[Paged Get {self.component}] Endpoint: {self.url}")
+        logger.info(f"[Paged Get {self.component}] Pagination Method: Offset Pagination")
 
         # Reset pagination parameters
         paged_params = EdFiParams(params or self.params).copy()
@@ -431,13 +433,13 @@ def get_pages(self, *, params: Optional[dict] = None, page_size: int = 100, **kw
 
             # If rows have been returned, there may be more to ingest.
             if res.json():
-                logging.info(f"[Paged Get {self.component}] Retrieved {len(res.json())} rows.")
+                logger.info(f"[Paged Get {self.component}] Retrieved {len(res.json())} rows.")
                 yield res.json()
 
-                logging.info(f"    @ Paginating offset...")
+                logger.info(f"    @ Paginating offset...")
                 paged_params.page_by_offset(page_size)
 
             # If no rows are returned, end pagination.
             else:
-                logging.info(f"[Paged Get {self.component}] @ Retrieved zero rows. Ending pagination.")
+                logger.info(f"[Paged Get {self.component}] @ Retrieved zero rows. Ending pagination.")
                 break
diff --git a/edfi_api_client/edfi_params.py b/edfi_api_client/edfi_params.py
@@ -5,6 +5,8 @@
 
 from edfi_api_client import util
 
+logger = logging.getLogger(__name__)
+
 
 class EdFiParams(dict):
     """
@@ -69,17 +71,17 @@ def __get_duplicates(list_: List[str]):
         cc_kwargs = [util.snake_to_camel(key) for key in _kwargs.keys()]
 
         for key in __get_duplicates(cc_params):
-            logging.warning(f"Duplicate key `{key}` found in `params`! The last will be used.")
+            logger.warning(f"Duplicate key `{key}` found in `params`! The last will be used.")
 
         for key in __get_duplicates(cc_kwargs):
-            logging.warning(f"Duplicate key `{key}` found in `kwargs`! The last will be used.")
+            logger.warning(f"Duplicate key `{key}` found in `kwargs`! The last will be used.")
 
 
         # Make sure the user does not pass in duplicates between params and kwargs.
         cc_kwargs_params = list(set(cc_params)) + list(set(cc_kwargs))
 
         for key in __get_duplicates(cc_kwargs_params):
-            logging.warning(f"Duplicate key `{key}` found between `params` and `kwargs`! The kwarg will be used.")
+            logger.warning(f"Duplicate key `{key}` found between `params` and `kwargs`! The kwarg will be used.")
 
         # Populate the final parameters.
         final_params = {}
@@ -104,7 +106,7 @@ def init_page_by_offset(self, page_size: int):
         self.page_size = page_size
 
         if 'limit' in self or 'offset' in self:
-            logging.warning("The previously-defined limit and offset will be reset for paging.")
+            logger.warning("The previously-defined limit and offset will be reset for paging.")
 
         self['limit'] = self.page_size
         self['offset'] = 0
diff --git a/edfi_api_client/session.py b/edfi_api_client/session.py
@@ -15,6 +15,8 @@
 if TYPE_CHECKING:
     from edfi_api_client.edfi_params import EdFiParams
 
+logger = logging.getLogger(__name__)
+
 
 class EdFiSession:
     """
@@ -125,7 +127,7 @@ def authenticate(self) -> dict:
         # Only re-authenticate when necessary.
         if self.authenticated_at:
             if self.refresh_at < int(time.time()):
-                logging.info("Session authentication is expired. Attempting reconnection...")
+                logger.info("Session authentication is expired. Attempting reconnection...")
             else:
                 return self.auth_headers
 
@@ -137,7 +139,7 @@ def authenticate(self) -> dict:
         self._last_auth_payload = auth_payload
 
         self._access_token = auth_payload.get('access_token', '')
-        logging.info(f'Using token starting with {self._access_token[:5]}')
+        logger.info(f'Using token starting with {self._access_token[:5]}')
 
         # Update headers
         self.auth_headers.update({
@@ -165,7 +167,7 @@ def _load_or_update_token_from_cache(self, force_write_lock: bool = False):
                 return self._load_or_update_token_from_cache(force_write_lock=True)
         
         else:
-            logging.info('Token cache is stale; attempting to get write lock')
+            logger.info('Token cache is stale; attempting to get write lock')
 
             with self.token_cache.get_write_lock():
                 auth_payload = None
@@ -261,7 +263,7 @@ def wrapped(self,
                 except RequestsWarning as retry_warning:
                     # If an API call fails, it may be due to rate-limiting.
                     sleep_secs = min((2 ** n_tries) * 2, max_wait)
-                    logging.warning(f"{retry_warning} Sleeping for {sleep_secs} seconds before retry number {n_tries + 1}...")
+                    logger.warning(f"{retry_warning} Sleeping for {sleep_secs} seconds before retry number {n_tries + 1}...")
                     self.safe_sleep(sleep_secs)
 
             # This block is reached only if max_retries has been reached.
diff --git a/edfi_api_client/token_cache.py b/edfi_api_client/token_cache.py
@@ -12,6 +12,8 @@
 if TYPE_CHECKING:
     from edfi_api_client.session import EdFiSession
 
+logger = logging.getLogger(__name__)
+
 
 class TokenCacheError(Exception):
     pass
@@ -128,7 +130,7 @@ def get_last_modified(self) -> int:
     def load(self) -> dict: 
         """Loads value from cache"""
         try:
-            logging.info(f'Loading cache from {self.cache_path}')
+            logger.info(f'Loading cache from {self.cache_path}')
             with open(self.cache_path, 'r') as fp:
                 value = json.loads(fp.read())
         except json.JSONDecodeError:
@@ -141,7 +143,7 @@ def load(self) -> dict:
     def update(self, value: dict):
         """Updates cache with new value"""
         with open(self.cache_path, 'w') as fp:
-            logging.info(f'Writing cache to {self.cache_path}')
+            logger.info(f'Writing cache to {self.cache_path}')
             fp.write(json.dumps(value))
 
     @contextlib.contextmanager
@@ -161,7 +163,7 @@ def get_write_lock(self):
                         lockfile_age = time.time() - os.path.getmtime(self.lockfile_path)
                         if lockfile_age > self.write_lock_staleness_threshold: 
                             # assume another client died while holding the lock
-                            logging.info(f'Lockfile at {self.lockfile_path} touched more than {self.write_lock_staleness_threshold}s ago. Removing lockfile.')
+                            logger.info(f'Lockfile at {self.lockfile_path} touched more than {self.write_lock_staleness_threshold}s ago. Removing lockfile.')
                             os.remove(self.lockfile_path)
                     
                     with open(self.lockfile_path, 'x') as f:
