Merge pull request #14 from ral-facilities/11_add_logging

Add Logging

.gitignore

@@ -1,3 +1,4 @@
 venv/
 .idea/
 *.pyc
+logs.log

common/database_helpers.py

@@ -1,44 +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
 
-
-def get_record_by_id(table, id):
-    """
-    Gets a row from the dummy data credential database
-    :param table: the table class mapping
-    :param id: the id to find
-    :return: the row from the table
-    """
-    session = get_db_session()
-    result = session.query(table).filter(table.ID == id).first()
-    if result is not None:
-        session.close()
-        return result
-    session.close()
-    raise MissingRecordError()
-
-
-def get_db_session():
-    """
-    Gets a session in the dummy data database, currently used for credentials until Authentication is understood
-    :return: the dummy data DB session
-    """
-    engine = create_engine("mysql+pymysql://root:root@localhost:3306/icatdummy")
-    Session = sessionmaker(bind=engine)
-    session = Session()
-    return session
+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()
@@ -50,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()
 
 
@@ -63,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)
@@ -72,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()
 
 
@@ -82,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()
@@ -97,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
@@ -115,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()
@@ -151,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()))
 
@@ -162,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))
 
 
@@ -172,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]
 
 
@@ -182,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))

common/logger_setup.py

@@ -0,0 +1,27 @@
+import logging.config
+
+
+log_level = "DEBUG"
+LOG_FILE_NAME = "../logs.log"
+logger_config = {
+    "version": 1,
+    "formatters": {"default": {
+        "format": "[%(asctime)s] {%(module)s:%(filename)s:%(funcName)s:%(lineno)d} %(levelname)s -%(message)s  ",
+    }},
+    "handlers": {"default": {
+        "level": "DEBUG",
+        "formatter": "default",
+        "class": "logging.handlers.RotatingFileHandler",
+        "filename": LOG_FILE_NAME,
+        "maxBytes": 5000000,
+        "backupCount": 10
+    }},
+    "root": {
+        "level": log_level,
+        "handlers": ["default"]
+    }
+}
+
+
+def setup_logger():
+    logging.config.dictConfig(logger_config)

src/main.py

@@ -1,6 +1,7 @@
 from flask import Flask
 from flask_restful import Api
 
+from common.logger_setup import setup_logger
 from src.resources.entities.dataset_type_endpoints import *
 from src.resources.entities.applications_endpoints import *
 from src.resources.entities.datacollection_datafiles_endpoints import *
@@ -45,6 +46,8 @@
 api = Api(app)
 
 
+setup_logger()
+
 api.add_resource(Applications, "/applications")
 api.add_resource(ApplicationsWithID, "/applications/<string:id>")
 api.add_resource(ApplicationsCount, "/applications/count")