#164: Add logging throughout Python ICAT backend

common/filter_order_handler.py

@@ -49,6 +49,7 @@ def merge_python_icat_limit_skip_filters(self):
         When there are both limit and skip filters in a request, merge them into the
         limit filter and remove the skip filter from the instance
         """
+        log.info("Merging a PythonICATSkipFilter and PythonICATLimitFilter together")
 
         if any(
             isinstance(icat_filter, PythonICATSkipFilter)
@@ -81,6 +82,7 @@ def clear_python_icat_order_filters(self):
         A reset is required because Python ICAT overwrites (as opposed to appending to
         it) the query's order list every time one is added to the query.
         """
+        log.debug("Resetting result order for the order filter")
 
         if any(
             isinstance(icat_filter, PythonICATOrderFilter)

common/icat/backend.py

@@ -46,6 +46,7 @@ def __init__(self):
         )
 
     def login(self, credentials):
+        log.info("Logging in to get session ID")
         # Client object is re-created here so session IDs aren't overwritten in the
         # database
         self.client = icat.client.Client(
@@ -65,11 +66,13 @@ def login(self, credentials):
 
     @requires_session_id
     def get_session_details(self, session_id):
+        log.info("Getting session details for session: %s", session_id)
         self.client.sessionId = session_id
         return get_session_details_helper(self.client)
 
     @requires_session_id
     def refresh(self, session_id):
+        log.info("Refreshing session: %s", session_id)
         self.client.sessionId = session_id
         return refresh_client_session(self.client)
 

common/icat/filters.py

@@ -47,7 +47,7 @@ def apply_filter(self, query):
 
         log.debug("ICAT Where Filter: %s", where_filter)
         try:
-            log.info("Adding ICAT where filter to query")
+            log.info("Adding ICAT where filter (for %s) to query", self.value)
             query.addConditions(where_filter)
         except ValueError:
             raise FilterError(
@@ -124,7 +124,7 @@ def apply_filter(self, query):
         log.debug("Result Order: %s", PythonICATOrderFilter.result_order)
 
         try:
-            log.info("Adding order filter")
+            log.info("Adding order filter (for %s)", self.field)
             query.setOrder(PythonICATOrderFilter.result_order)
         except ValueError as e:
             # Typically either invalid attribute(s) or attribute(s) contains 1-many
@@ -165,6 +165,7 @@ def icat_set_limit(query, skip_number, limit_number):
     """
     try:
         query.setLimit((skip_number, limit_number))
+        log.debug("Current limit/skip values assigned to query: %s", query.limit)
     except TypeError as e:
         # Not a two element tuple as managed by Python ICAT's setLimit()
         raise FilterError(e)
@@ -192,6 +193,7 @@ def _extract_filter_fields(self, field):
         :type field: :class:`str` or :class:`list` or :class:`dict`
         """
         if isinstance(field, str):
+            log.debug("Adding %s to include filter", field)
             self.included_filters.append(field)
         elif isinstance(field, dict):
             for key, value in field.items():

common/icat/helpers.py

@@ -84,7 +84,7 @@ def logout_icat_client(client):
     :param client: ICAT client containing an authenticated user
     :type client: :class:`icat.client.Client`
     """
-
+    log.info("Logging out of the Python ICAT client")
     client.logout()
 
 
@@ -119,6 +119,7 @@ def get_python_icat_entity_name(client, database_table_name, camel_case_output=F
         Python ICAT
     :raises BadRequestError: If the entity cannot be found
     """
+    log.debug("Python ICAT entity name camel case flag: %s", camel_case_output)
 
     if camel_case_output:
         entity_names = getTypeMap(client).keys()
@@ -208,6 +209,8 @@ def get_entity_by_id(
     :return: The record of the specified ID from the given entity
     :raises: MissingRecordError: If Python ICAT cannot find a record of the specified ID
     """
+    log.info("Getting %s of the ID %s", table_name, id_)
+    log.debug("Return related entities set to: %s", return_related_entities)
 
     selected_entity_name = get_python_icat_entity_name(client, table_name)
     # Set query condition for the selected ID
@@ -237,7 +240,7 @@ def delete_entity_by_id(client, table_name, id_):
     :param id_: ID number of the entity to delete
     :type id_: :class:`int`
     """
-
+    log.info("Deleting %s of ID %s", table_name, id_)
     entity_id_data = get_entity_by_id(client, table_name, id_, False)
     client.delete(entity_id_data)
 
@@ -256,6 +259,7 @@ def update_entity_by_id(client, table_name, id_, new_data):
         the specified ID
     :return: The updated record of the specified ID from the given entity
     """
+    log.info("Updating %s of ID %s", table_name, id_)
 
     entity_id_data = get_entity_by_id(
         client, table_name, id_, False, return_related_entities=True
@@ -428,6 +432,7 @@ def create_entities(client, table_name, data):
         )
 
         for attribute_name, value in result.items():
+            log.debug("Preparing data for %s", attribute_name)
             try:
                 entity_info = new_entity.getAttrInfo(client, attribute_name)
                 if entity_info.relType.lower() == "attribute":

common/icat/query.py

@@ -99,6 +99,7 @@ def execute_query(self, client, return_json_formattable=False):
         if self.query.aggregate is not None:
             if "COUNT" in self.query.aggregate:
                 count_query = True
+                log.debug("This ICATQuery is used for COUNT purposes")
 
         if (
             self.query.aggregate == "DISTINCT"

src/main.py

@@ -55,6 +55,7 @@ def handle_error(e):
 app.register_blueprint(swaggerui_blueprint, url_prefix="/")
 
 setup_logger()
+log.info("Logging now setup")
 
 initialise_spec(spec)
 
@@ -104,6 +105,7 @@ def handle_error(e):
 
 # Reorder paths (e.g. get, patch, post) so openapi.yaml only changes when there's a
 # change to the Swagger docs, rather than changing on each startup
+log.debug("Reordering OpenAPI docs to alphabetical order")
 for entity_data in spec._paths.values():
     for endpoint_name in sorted(entity_data.keys()):
         entity_data.move_to_end(endpoint_name)