Merge pull request #175 from ral-facilities/feature/improve-logging-i…

…cat-backend-#164

Improve 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

@@ -41,6 +41,7 @@ def __init__(self):
         pass
 
     def login(self, credentials):
+        log.info("Logging in to get session ID")
         client = create_client()
 
         # Syntax for Python ICAT
@@ -56,17 +57,20 @@ def login(self, credentials):
 
     @requires_session_id
     def get_session_details(self, session_id, **kwargs):
+        log.info("Getting session details for session: %s", session_id)
         client = kwargs["client"] if kwargs["client"] else create_client()
         return get_session_details_helper(client)
 
     @requires_session_id
     def refresh(self, session_id, **kwargs):
+        log.info("Refreshing session: %s", session_id)
         client = kwargs["client"] if kwargs["client"] else create_client()
         return refresh_client_session(client)
 
     @requires_session_id
     @queries_records
     def logout(self, session_id, **kwargs):
+        log.info("Logging out of the Python ICAT client")
         client = kwargs["client"] if kwargs["client"] else create_client()
         return logout_icat_client(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

@@ -106,7 +106,6 @@ def logout_icat_client(client):
     :param client: ICAT client containing an authenticated user
     :type client: :class:`icat.client.Client`
     """
-
     client.logout()
 
 
@@ -141,6 +140,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()
@@ -234,6 +234,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
@@ -263,7 +265,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)
 
@@ -282,6 +284,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
@@ -497,6 +500,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":
@@ -562,7 +566,7 @@ def get_facility_cycles_for_instrument(
 
     query_aggregate = "COUNT:DISTINCT" if count_query else "DISTINCT"
     query = ICATQuery(
-        client, "FacilityCycle", aggregate=query_aggregate, isis_endpoint=True
+        client, "FacilityCycle", aggregate=query_aggregate
     )
 
     instrument_id_check = PythonICATWhereFilter(
@@ -647,7 +651,7 @@ def get_investigations_for_instrument_in_facility_cycle(
 
     query_aggregate = "COUNT:DISTINCT" if count_query else "DISTINCT"
     query = ICATQuery(
-        client, "Investigation", aggregate=query_aggregate, isis_endpoint=True
+        client, "Investigation", aggregate=query_aggregate
     )
 
     instrument_id_check = PythonICATWhereFilter(

common/icat/query.py

@@ -21,7 +21,6 @@ def __init__(
         conditions=None,
         aggregate=None,
         includes=None,
-        isis_endpoint=False,
     ):
         """
         Create a Query object within Python ICAT 
@@ -39,12 +38,6 @@ def __init__(
         :param includes: List of related entity names to add to the query so related
             entities (and their data) can be returned with the query result
         :type includes: :class:`str` or iterable of :class:`str`
-        :param isis_endpoint: Flag to determine if the instance will be used for an ISIS
-            specific endpoint. These endpoints require the use of the DISTINCT aggregate
-            which is different to the distinct field filter implemented in this API, so
-            this flag prevents code related to the filter from executing (because it
-            doesn't need to be on a DISTINCT aggregate)
-        :type isis_endpoint: :class:`bool`
         :return: Query object from Python ICAT
         :raises PythonICATError: If a ValueError is raised when creating a Query(), 500
             will be returned as a response
@@ -65,7 +58,6 @@ def __init__(
                 " suggesting an invalid argument"
             )
 
-        self.isis_endpoint = isis_endpoint
 
     def execute_query(self, client, return_json_formattable=False):
         """
@@ -99,23 +91,24 @@ 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"
             and not count_query
-            and not self.isis_endpoint
         ):
             log.info("Extracting the distinct fields from query's conditions")
             # Check query's conditions for the ones created by the distinct filter
             distinct_attributes = self.iterate_query_conditions_for_distinctiveness()
-            mapped_distinct_fields = self.map_distinct_attributes_to_entity_names(
-                distinct_attributes, flat_query_includes
-            )
-            log.debug(
-                "Attribute names used in the distinct filter, mapped to the entity they"
-                " are a part of: %s",
-                mapped_distinct_fields,
-            )
+            if distinct_attributes != []:
+                mapped_distinct_fields = self.map_distinct_attributes_to_entity_names(
+                    distinct_attributes, flat_query_includes
+                )
+                log.debug(
+                    "Attribute names used in the distinct filter, mapped to the entity they"
+                    " are a part of: %s",
+                    mapped_distinct_fields,
+                )
 
         if return_json_formattable:
             log.info("Query results will be returned in a JSON format")
@@ -275,8 +268,7 @@ def map_distinct_attributes_to_entity_names(self, distinct_fields, included_fiel
         """
 
         # Mapping which entities have distinct fields
-        distinct_field_dict = {}
-        distinct_field_dict["base"] = []
+        distinct_field_dict = {"base": []}
 
         for field in distinct_fields:
             split_fields = field.split(".")