Initial version of structured logging for API srver

Setup in config.py

Author: c-simpson

src/server/alembic/generate_rfm_mapping.py

@@ -1,5 +1,6 @@
 import itertools
-
+import structlog
+logger = structlog.get_logger()
 
 def get_all_combinations(chars):
     yield from itertools.product(*([chars] * 3))
@@ -71,7 +72,7 @@ def start():
             f.write("%s\n" % item)
 
 
-    print('done')
+    logger.debug('Completed generate_rfm_mapping')
 
 
 start()

src/server/api/API_ingest/dropbox_handler.py

@@ -1,18 +1,20 @@
 import dropbox
+import structlog
+logger = structlog.get_logger()
 
 try:
     from secrets_dict import DROPBOX_APP
 except ImportError:
     # Not running locally
-    print("Couldn't get DROPBOX_APP from file, trying environment **********")
+    logger.debug("Couldn't get DROPBOX_APP from file, trying environment **********")
     from os import environ
 
     try:
         DROPBOX_APP = environ['DROPBOX_APP']
     except KeyError:
         # Not in environment
         # You're SOL for now
-        print("Couldn't get DROPBOX_APP from file or environment")
+        logger.error("Couldn't get DROPBOX_APP from file or environment")
 
 
 class TransferData:

src/server/api/API_ingest/ingest_sources_from_api.py

@@ -1,7 +1,9 @@
 from api.API_ingest import shelterluv_api_handler
+import structlog
+logger = structlog.get_logger()
 
 def start(conn):
-    print("Start Fetching raw data from different API sources")
+    logger.debug("Start Fetching raw data from different API sources")
     #Run each source to store the output in dropbox and in the container as a CSV
     shelterluv_api_handler.store_shelterluv_people_all(conn)
-    print("Finish Fetching raw data from different API sources")
+    logger.debug("Finish Fetching raw data from different API sources")

src/server/api/API_ingest/shelterluv_api_handler.py

@@ -7,20 +7,22 @@
 from api.API_ingest.dropbox_handler import upload_file_to_dropbox
 from constants import RAW_DATA_PATH
 from models import ShelterluvPeople
+import structlog
+logger = structlog.get_logger()
 
 try:
     from secrets_dict import SHELTERLUV_SECRET_TOKEN
 except ImportError:
     # Not running locally
-    print("Couldn't get SHELTERLUV_SECRET_TOKEN from file, trying environment **********")
+    logger.debug("Couldn't get SHELTERLUV_SECRET_TOKEN from file, trying environment **********")
     from os import environ
 
     try:
         SHELTERLUV_SECRET_TOKEN = environ['SHELTERLUV_SECRET_TOKEN']
     except KeyError:
         # Not in environment
         # You're SOL for now
-        print("Couldn't get SHELTERLUV_SECRET_TOKEN from file or environment")
+        logger.error("Couldn't get SHELTERLUV_SECRET_TOKEN from file or environment")
 
 
 def write_csv(json_data):
@@ -68,7 +70,7 @@ def store_shelterluv_people_all(conn):
     has_more = True
     shelterluv_people = []
 
-    print("Start getting shelterluv contacts from people table")
+    logger.debug("Start getting shelterluv contacts from people table")
 
     while has_more:
         r = requests.get("http://shelterluv.com/api/v1/people?limit={}&offset={}".format(LIMIT, offset),
@@ -78,9 +80,9 @@ def store_shelterluv_people_all(conn):
         has_more = response["has_more"]
         offset += 100
 
-    print("Finish getting shelterluv contacts from people table")
+    logger.debug("Finish getting shelterluv contacts from people table")
 
-    print("Start storing latest shelterluvpeople results to container")
+    logger.debug("Start storing latest shelterluvpeople results to container")
     if os.listdir(RAW_DATA_PATH):
         for file_name in os.listdir(RAW_DATA_PATH):
             file_path = os.path.join(RAW_DATA_PATH, file_name)
@@ -90,11 +92,11 @@ def store_shelterluv_people_all(conn):
                 os.remove(file_path)
 
     file_path = write_csv(shelterluv_people)
-    print("Finish storing latest shelterluvpeople results to container")
+    logger.debug("Finish storing latest shelterluvpeople results to container")
 
-    print("Start storing " + '/shelterluv/' + "results to dropbox")
+    logger.debug("Start storing " + '/shelterluv/' + "results to dropbox")
     upload_file_to_dropbox(file_path, '/shelterluv/' + file_path.split('/')[-1])
-    print("Finish storing " + '/shelterluv/' + "results to dropbox")
+    logger.debug("Finish storing " + '/shelterluv/' + "results to dropbox")
 
-    print("Uploading shelterluvpeople csv to database")
+    logger.debug("Uploading shelterluvpeople csv to database")
     ShelterluvPeople.insert_from_df(pd.read_csv(file_path, dtype="string"), conn)

src/server/api/admin_api.py

@@ -16,6 +16,10 @@
 from api import jwt_ops
 from config import RAW_DATA_PATH
 
+import structlog
+logger = structlog.get_logger()
+
+
 ALLOWED_EXTENSIONS = {"csv", "xlsx"}
 
 
@@ -32,7 +36,7 @@ def upload_csv():
             try:
                 validate_and_arrange_upload(file)
             except Exception as e:
-                current_app.logger.exception(e)
+                logger.exception(e)
             finally:
                 file.close()
 
@@ -44,7 +48,7 @@ def upload_csv():
 def list_current_files():
     result = None
 
-    current_app.logger.info("Start returning file list")
+    logger.info("Start returning file list")
     file_list_result = os.listdir(RAW_DATA_PATH)
 
     if len(file_list_result) > 0:
@@ -56,9 +60,9 @@ def list_current_files():
 @admin_api.route("/api/execute", methods=["POST"])
 @jwt_ops.admin_required
 def execute():
-    current_app.logger.info("Execute flow")
+    logger.info("Execute flow")
     job_outcome = flow_script.start_flow() # 'busy', 'completed', or 'nothing to do'
-    current_app.logger.info("Job outcome: " + str(job_outcome))
+    logger.info("Job outcome: %s", str(job_outcome))
 
 
     # --------   Skip update if 'busy' or 'nothing to do' as nothing changed ? ------
@@ -87,8 +91,8 @@ def execute():
         try:
             connection.execute(upsert)
         except Exception as e:
-            current_app.logger.error("Insert/Update failed on Last Execution stats")
-            current_app.logger.exception(e)
+            logger.error("Insert/Update failed on Last Execution stats")
+            logger.error(e)
     # -------------------------------------------------------------------------------
 
     if job_outcome == 'busy':
@@ -127,7 +131,7 @@ def get_statistics():
 @jwt_ops.admin_required
 def list_statistics():
     """ Pull Last Execution stats from DB. """
-    current_app.logger.info("list_statistics() request")
+    logger.info("list_statistics() request")
     last_execution_details = '{}'  # Empty but valid JSON
 
     engine.dispose() # we don't want other process's conn pool
@@ -143,7 +147,7 @@ def list_statistics():
                 last_execution_details = result.fetchone()[0]
 
         except Exception as e:
-            current_app.logger.error("Failure reading Last Execution stats from DB - OK on first run")
+            logger.error("Failure reading Last Execution stats from DB - OK on first run")
         # Will happen on first run, shouldn't after 
 
     return last_execution_details
@@ -220,10 +224,10 @@ def start_job():
 
     if running_job :
         # There was a running job already
-        current_app.logger.info("Request to start job, but job_id " + str(running_job) + " already executing")
+        logger.warn("Request to start job, but job_id " + str(running_job) + " already executing")
         return None
     else:
-        current_app.logger.info("Assigned job_id " + job_id )
+        logger.info("Assigned job_id " + job_id )
         return job_id
 
 
@@ -269,7 +273,7 @@ def  import_rfm_csv():
     with open('C:\\Projects\\paws-stuff\\score_tuples.csv', 'r') as csvfile:
         reader = csv.reader(csvfile, delimiter=',')
         hdr = next(reader)
-        print('Skipping header: ', hdr)
+        logger.debug('Skipping header: %s', hdr)
         for row in reader:
             score_list.append(row)
 
@@ -302,14 +306,14 @@ def write_rfm_edges(rfm_dict : dict) :
             try:
                 connection.execute(upsert)
             except Exception as e:
-                current_app.logger.error("Insert/Update failed on rfm edge ")
-                current_app.logger.exception(e)
+                logger.error("Insert/Update failed on rfm edge ")
+                logger.error(e)
                 return None
 
         return 0
 
     else :   # Malformed dict
-        current_app.logger.error("Received rfm_edge dictionary with " + str(len(rfm_dict)) + " entries - expected 3")
+        logger.error("Received rfm_edge dictionary with " + str(len(rfm_dict)) + " entries - expected 3")
         return None
 
 
@@ -321,14 +325,14 @@ def read_rfm_edges() :
     with engine.begin() as connection:   # BEGIN TRANSACTION
         q_result = connection.execute(q)
         if q_result.rowcount == 0:
-            current_app.logger.error("No rfm_edge entry found in DB")
+            logger.error("No rfm_edge entry found in DB")
             return None
         else:
             edge_string = q_result.fetchone()[0]
             try:
                 edge_dict = json.loads(edge_string)   # Convert stored string to dict
             except json.decoder.JSONDecodeError:
-                current_app.logger.error("rfm_edge entry found in DB was malformed")
+                logger.error("rfm_edge entry found in DB was malformed")
                 return None
 
             return edge_dict
@@ -380,9 +384,9 @@ def generate_dummy_rfm_scores():
 
     #   return jsonify(sfd_list)  # enable if using endpoint, but it returns a lot of data
 
-    current_app.logger.debug("Inserting dummy scores...")
+    logger.debug("Inserting dummy scores...")
     count = insert_rfm_scores(dummy_scores)
-    current_app.logger.debug("Finished inserting")
+    logger.debug("Finished inserting")
 
 
     return count

src/server/api/common_api.py

@@ -6,19 +6,22 @@
 import time
 from datetime import datetime
 
+import structlog
+logger = structlog.get_logger()
+
+
 from api.fake_data import sl_mock_data
 
 try:
     from secrets_dict import SHELTERLUV_SECRET_TOKEN
 except ImportError:
     # Not running locally
-    print("Couldn't get SHELTERLUV_SECRET_TOKEN from file, trying environment **********")
+    logger.debug("Couldn't get SHELTERLUV_SECRET_TOKEN from file, trying environment **********")
     from os import getenv
 
     SHELTERLUV_SECRET_TOKEN = getenv('SHELTERLUV_SECRET_TOKEN')
     if not SHELTERLUV_SECRET_TOKEN:
-        print("Couldn't get secrets from file or environment",
-            "Defaulting to Fake Data")
+        logger.warn("Couldn't get secrets from file or environment - defaulting to Fake Data")
 
 from api import jwt_ops
 
@@ -262,7 +265,7 @@ def get_support_oview(matching_id):
                 if row['source_id'].isalnum():
                     id_list.append(row['source_id'])
                 else:
-                    current_app.logger.warn("salesforcecontacts source_id " + row['source_id'] + "has non-alphanumeric characters; will not be used")
+                    logger.warn("salesforcecontacts source_id %s has non-alphanumeric characters; will not be used",  str(row['source_id']))
 
             if len(id_list) == 0: # No ids to query
                 oview_fields['number_of_gifts'] = 0    # Marker for no support data
@@ -379,7 +382,7 @@ def get_support_oview(matching_id):
 
 
         else:   # len(rows) == 0
-            current_app.logger.debug('No SF contact IDs found for matching_id ' + str(matching_id))
+            logger.warn('No SF contact IDs found for matching_id ' + str(matching_id))
             oview_fields['number_of_gifts'] = 0  # Marker for no data
             return jsonify(oview_fields)
 

src/server/api/file_uploader.py

@@ -6,11 +6,14 @@
 from shifts_importer import validate_import_vs
 from werkzeug.utils import secure_filename
 
+import structlog
+logger = structlog.get_logger()
+
 SUCCESS_MSG = "Uploaded Successfully!"
 
 
 def validate_and_arrange_upload(file):
-    current_app.logger.info("Start uploading file: " + file.filename)
+    logger.info("Start uploading file: " + file.filename)
     filename = secure_filename(file.filename)
     file_extension = filename.rpartition(".")[2]
     with engine.begin() as conn:
@@ -23,18 +26,22 @@ def determine_upload_type(file, file_extension, conn):
     # automatically pulling from vendor APIs directly, in which case we'd know
     # what kind of data we had.
     if file_extension == "csv":
+        logger.debug("File extension is CSV")
         df = pd.read_csv(file, dtype="string")
 
         if {"salesforcecontacts", "volgistics", "shelterluvpeople"}.issubset(df.columns):
+            logger.debug("File appears to be salesforcecontacts, volgistics, or shelterluvpeople (manual)")
             ManualMatches.insert_from_df(df, conn)
             return
         elif {"Animal_ids", "Internal-ID"}.issubset(df.columns):
+            logger.debug("File appears to be shelterluvpeople")
             ShelterluvPeople.insert_from_df(df, conn)
             return
 
     if file_extension == "xlsx":
         excel_file = pd.ExcelFile(file)
         if {"Master", "Service"}.issubset(excel_file.sheet_names):
+            logger.debug("File appears to be Volgistics")
             # Volgistics
             validate_import_vs(file, conn)
             Volgistics.insert_from_file(excel_file, conn)
@@ -45,11 +52,13 @@ def determine_upload_type(file, file_extension, conn):
             # Salesforce something-or-other
             if "Amount" in df.columns:
                 # Salesforce donations
+                logger.debug("File appears to be Salesforce donations")
                 validate_import_sfd(file, conn)
                 return
             else:
                 # Salesforce contacts
+                logger.debug("File appears to be Salesforce contacts")
                 SalesForceContacts.insert_from_file_df(df, conn)
                 return
 
-    current_app.logger.error(f"Don't know how to process file {file.filename}")
+    logger.error("Don't know how to process file: %s",  file.filename)

src/server/api/internal_api.py

@@ -5,6 +5,9 @@
 from api.API_ingest import ingest_sources_from_api
 from rfm_funcs.create_scores import create_scores
 
+import structlog
+logger = structlog.get_logger()
+
 ###   Internal API endpoints can only be accessed from inside the cluster;
 ###   they are blocked by location rule in NGINX config
 
@@ -28,14 +31,14 @@ def ingest_raw_data():
         with engine.begin() as conn:
             ingest_sources_from_api.start(conn)
     except Exception as e:
-        current_app.logger.exception(e)
+        logger.error(e)
 
     return jsonify({'outcome': 'OK'}), 200
 
 
 @internal_api.route("/api/internal/create_scores", methods=["GET"])
 def hit_create_scores():
-    current_app.logger.info("Hitting create_scores() ")
+    logger.info("Hitting create_scores() ")
     tuple_count = create_scores()
-    current_app.logger.info("create_scores()  processed " + str(tuple_count) + " scores")
+    logger.info("create_scores()  processed " + str(tuple_count) + " scores")
     return jsonify(200)