#11: Add logging

common/database_helpers.py

@@ -1,19 +1,21 @@
 import datetime
+import logging
 
 from sqlalchemy import create_engine
 from sqlalchemy.orm import sessionmaker
 
 from common.constants import Constants
 from common.exceptions import MissingRecordError, BadFilterError, BadRequestError
 
-
+log = logging.getLogger()
 
 
 def get_icat_db_session():
     """
     Gets a session and connects with the ICAT database
     :return: the session object
     """
+    log.info(" Getting ICAT DB session")
     engine = create_engine(Constants.DATABASE_URL)
     Session = sessionmaker(bind=engine)
     session = Session()
@@ -25,9 +27,11 @@ def insert_row_into_table(row):
     Insert the given row into its table
     :param row: The row to be inserted
     """
+    log.info(f" Inserting row into table {row.__tablename__}")
     session = get_icat_db_session()
     session.add(row)
     session.commit()
+    log.info(" Closing DB session")
     session.close()
 
 
@@ -38,6 +42,7 @@ def create_row_from_json(table, json):
     :param json: the dictionary containing the values
     :return: nothing atm
     """
+    log.info(f" Creating row from json into table {table.__tablename__}")
     session = get_icat_db_session()
     record = table()
     record.update_from_dict(json)
@@ -47,6 +52,7 @@ def create_row_from_json(table, json):
     record.MOD_ID = "user"
     session.add(record)
     session.commit()
+    log.info(" Closing db session")
     session.close()
 
 
@@ -57,9 +63,11 @@ def get_row_by_id(table, id):
     :param id: the id of the record to find
     :return: the record retrieved
     """
+    log.info(f" Querying {table.__tablename__} for record with ID: {id}")
     session = get_icat_db_session()
     result = session.query(table).filter(table.ID == id).first()
     if result is not None:
+        log.info(" Record found, closing DB session")
         session.close()
         return result
     session.close()
@@ -72,10 +80,12 @@ def delete_row_by_id(table, id):
     :param table: the table to be searched
     :param id: the id of the record to delete
     """
+    log.info(f" Deleting row from {table.__tablename__} with ID: {id}")
     session = get_icat_db_session()
     result = get_row_by_id(table, id)
     if result is not None:
         session.delete(result)
+        log.info(" record deleted, closing DB session")
         session.commit()
         session.close()
         return
@@ -90,11 +100,13 @@ def update_row_from_id(table, id, new_values):
     :param id: The id of the record
     :param new_values: A JSON string containing what columns are to be updated
     """
+    log.info(f" Updating row with ID: {id} in {table.__tablename__}")
     session = get_icat_db_session()
     record = session.query(table).filter(table.ID == id).first()
     if record is not None:
         record.update_from_dict(new_values)
         session.commit()
+        log.info(" Record updated, closing DB session")
         session.close()
         return
     session.close()
@@ -126,6 +138,7 @@ def get_rows_by_filter(table, filters):
             base_query = base_query.limit(limit)
         else:
             raise BadFilterError()
+    log.info(" Closing DB session")
     session.close()
     return list(map(lambda x: x.to_dict(), base_query.all()))
 
@@ -137,6 +150,7 @@ def get_filtered_row_count(table, filters):
     :param filters: the filters to be applied to the query
     :return: int: the count of the rows
     """
+    log.info(f" Getting filtered row count for {table.__tablename__}")
     return len(get_rows_by_filter(table, filters))
 
 
@@ -147,6 +161,7 @@ def get_first_filtered_row(table, filters):
     :param filters: the filter to be applied to the query
     :return: the first row matching the filter
     """
+    log.info(f" Getting first filtered row for {table.__tablename__}")
     return get_rows_by_filter(table, filters)[0]
 
 
@@ -157,6 +172,7 @@ def patch_entities(table, json_list):
     :param json_list: the list of updated values or a dictionary
     :return: The list of updated rows.
     """
+    log.info(f" Patching entities in {table.__tablename__}")
     results = []
     if type(json_list) is dict:
         for key in json_list:

common/exceptions.py

@@ -1,18 +1,29 @@
+import logging
+
+log = logging.getLogger()
+
+
 class ApiError(Exception):
-    pass
+    def __init__(self):
+        log.info(" ApiError(): An error has been raised.")
 
 
 class MissingRecordError(ApiError):
-    pass
+    def __init__(self):
+        log.info(" MissingRecordError(): Record not found, DB session Closed")
+
 
 
 class BadFilterError(ApiError):
-    pass
+    def __init__(self):
+        log.info(" BadFilterError(): Bad filter supplied")
 
 
 class AuthenticationError(ApiError):
-    pass
+    def __init__(self):
+        log.info(" AuthenticationError(): Error authenticating consumer")
 
 
 class BadRequestError(ApiError):
-    pass
+    def __init__(self):
+        log.info(" BadRequestError(): Bad request by Consumer")

common/helpers.py

@@ -1,4 +1,5 @@
 import json
+import logging
 from functools import wraps
 
 from flask import request
@@ -10,26 +11,33 @@
 from common.models.db_models import SESSION
 
 
+log = logging.getLogger()
+
 def requires_session_id(method):
     """
     Decorator for endpoint resources that makes sure a valid session_id is provided in requests to that endpoint
     :param method: The method for the endpoint
     :returns a 403, "Forbidden" if a valid session_id is not provided with the request
     """
-
+    log.info("")
     @wraps(method)
     def wrapper_requires_session(*args, **kwargs):
+        log.info(" Authenticating consumer")
         try:
             session = get_icat_db_session()
             query = session.query(SESSION).filter(
                 SESSION.ID == get_session_id_from_auth_header()).first()
             if query is not None:
+                log.info(" Closing DB session")
+                session.close()
+                log.info(" Consumer authenticated")
                 return method(*args, **kwargs)
             else:
+                log.info(" Closing DB session")
+                session.close()
                 return "Forbidden", 403
         except AuthenticationError:
             return "Forbidden", 403
-
     return wrapper_requires_session
 
 
@@ -44,19 +52,25 @@ def queries_records(method):
     def wrapper_gets_records(*args, **kwargs):
         try:
             return method(*args, **kwargs)
-        except MissingRecordError:
+        except MissingRecordError as e:
+            log.error(e)
             return "No such record in table", 404
-        except BadFilterError:
+        except BadFilterError as e:
+            log.error(e)
             return "Invalid filter requested", 400
-        except ValueError:
+        except ValueError as e:
+            log.error(e)
             return "Bad request", 400
-        except TypeError:
+        except TypeError as e:
+            log.error(e)
             return "Bad request", 400
-        except IntegrityError:
+        except IntegrityError as e:
+            log.error(e)
             return "Bad request", 400
-        except BadRequestError:
+        except BadRequestError as e:
+            log.error(e)
             return "Bad request", 400
-            
+
     return wrapper_gets_records
 
 
@@ -65,6 +79,7 @@ def get_session_id_from_auth_header():
     Gets the sessionID from the Authorization header of a request
     :return: String: SessionID
     """
+    log.info(" Getting session Id from auth header")
     parser = reqparse.RequestParser()
     parser.add_argument("Authorization", location="headers")
     args = parser.parse_args()
@@ -90,5 +105,6 @@ def is_valid_json(string):
 
 
 def get_filters_from_query_string():
+    log.info( "Getting filters from query string")
     filters = request.args.getlist("filter")
     return list(map(lambda x: json.loads(x), filters))