Python logging to separate log files per experiment

apps/backend/.gitignore

@@ -1,6 +1,9 @@
 # Ignore docker container volume contents
 ExperimentFiles/
 
+# Ignore log files produced by the system
+logs/
+
 # Python
 __pycache__
 .venv

apps/backend/.pylintrc

@@ -8,3 +8,8 @@ disable=
     C0116, # missing-function-docstring
     C0115, # missing-class-docstring
     C0103, # we chose to use camel case to be consistent with our frontend code
+    W1203, # we want to use fstrings for log message readability, the performance cost is not significant enough for us to care. but, don't turn off W1201 because if the dev wants to use % syntax, they should use lazy logging since the syntax readability is equivalent
+
+# Load our own custom plugins
+load-plugins=
+    linters.no_print

apps/backend/app.py

@@ -5,6 +5,7 @@
 import sys
 import json
 import time
+import typing
 from flask import Flask, jsonify, request
 from flask_cors import CORS
 import firebase_admin
@@ -15,6 +16,7 @@
 from pymongo.errors import ConnectionFailure
 from bson.binary import Binary
 
+from modules.logging.gladosLogging import EXPERIMENT_LOGGER, SYSTEM_LOGGER, close_experiment_logger, configure_root_logger, open_experiment_logger
 from modules.runner import conduct_experiment
 from modules.exceptions import CustomFlaskError, GladosInternalError, ExperimentAbort
 from modules.output.plots import generateScatterPlot
@@ -33,7 +35,12 @@
 HAS_DOTENV_FILE = load_dotenv("./.env", override=True)
 
 ENV_FIREBASE_CREDENTIALS = "FIREBASE_KEY"
-DB_COLLECTION_EXPERIMENTS = 'Experiments'
+DB_COLLECTION_EXPERIMENTS = "Experiments"
+
+# set up logger
+configure_root_logger()
+explogger = logging.getLogger(SYSTEM_LOGGER)
+explogger = logging.getLogger(EXPERIMENT_LOGGER)
 
 FIREBASE_CREDENTIALS = os.environ.get(ENV_FIREBASE_CREDENTIALS)
 if FIREBASE_CREDENTIALS is None:
@@ -42,7 +49,7 @@
     else:
         raise AssertionError(f"Missing environment variable {ENV_FIREBASE_CREDENTIALS} - you need a `.env` file in this folder with it defined")
 else:
-    print("Loaded firebase credentials from environment variables")
+    explogger.info("Loaded firebase credentials from environment variables")
 
 firebaseCredentials = credentials.Certificate(json.loads(FIREBASE_CREDENTIALS))
 firebaseApp = firebase_admin.initialize_app(firebaseCredentials)
@@ -60,14 +67,16 @@
 MAX_WORKERS = 1
 runner = ProcessPoolExecutor(MAX_WORKERS)
 
-#setting up the Flask webserver (handles the uploaded experiment files)
+#setting up the Flask webserver (handles the signal to run an experiment)
 flaskApp = Flask(__name__)
 CORS(flaskApp)
 
+explogger.info("GLADOS Backend Started")
+
 
 @flaskApp.post("/experiment")
 def recv_experiment():
-    runner.submit(handle_exceptions_from_run, request.get_json())
+    runner.submit(handle_uncaught_exceptions_from_run, request.get_json())
     return 'OK'
 
 
@@ -82,47 +91,58 @@ def glados_custom_flask_error(error):
     return jsonify(error.to_dict()), error.status_code
 
 
-def handle_exceptions_from_run(data):
+def handle_uncaught_exceptions_from_run(data: typing.Any):
     try:
         run_batch(data)
     except Exception as err:
-        print(f"Unexpected exception while trying to run the experiment, this was not caught by our own code and needs to be handled better: {err}")
-        logging.exception(err)
+        explogger.error("Unexpected exception while trying to run the experiment, this was not caught by our own code and needs to be handled better.")
+        explogger.exception(err)
+        close_experiment_logger()  # TODO Unsafe to upload to firebase here (unknown expid), is there a workaround we can use? include expid in exceptions?
         raise err
 
 
-def run_batch(data):
-    print(f'Run_Batch starting with data {data}')
-    experiments = firebaseDb.collection(DB_COLLECTION_EXPERIMENTS)
+def run_batch(data: typing.Any):
+    explogger.info('Run_Batch starting with data %s', data)
 
     # Obtain most basic experiment info
     expId = data['experiment']['id']
-    print(f'received {expId}')
-    expRef = experiments.document(expId)
+    explogger.debug('received %s', expId)
+
+    open_experiment_logger(expId)
 
-    # Parsing the argument data
+    # Retrieve experiment details from firebase
+    # TODO handle errors from firebase
+    experiments = firebaseDb.collection(DB_COLLECTION_EXPERIMENTS)
+    expRef = experiments.document(expId)
     experimentData = expRef.get().to_dict()
 
+    #TODO @David does this still need to be here? doesn't parsing into datatype also check this?
     try:
         hyperparameters: "dict[str,Parameter]" = parseParams(json.loads(experimentData['hyperparameters'])['hyperparameters'])
     except KeyError as err:
         raise GladosInternalError("Error generating configs - hyperparameters not found in experiment object") from err
-    print(type(hyperparameters))
     experimentData['hyperparameters'] = hyperparameters
 
     #Parsing into Datatype
-    experiment = ExperimentData(**experimentData)
-    experiment.postProcess = experiment.scatter
+    try:
+        experiment = ExperimentData(**experimentData)
+        experiment.postProcess = experiment.scatter
+    except ValueError as err:
+        explogger.exception(err)
+        close_experiment_logger()  # TODO upload to firebase
+        return
+
     #Downloading Experiment File
+    # If the program errors here after you just deleted the ExperimentFiles on your dev machine, restart the docker container, seems to be volume mount weirdness
     os.makedirs(f'ExperimentFiles/{expId}')
     os.chdir(f'ExperimentFiles/{expId}')
     filepath = download_experiment_files(experiment)
 
     rawfiletype, filetype = determine_experiment_file_type(filepath)
     experiment.experimentType = filetype
-    print(f"Raw Filetype: {rawfiletype}\n Filtered Filetype: {filetype.value}")
+    explogger.info(f"Raw Filetype: {rawfiletype}\n Filtered Filetype: {filetype.value}")
 
-    print(f"Generating configs and downloading to ExperimentFiles/{expId}/configFiles")
+    explogger.info(f"Generating configs and downloading to ExperimentFiles/{expId}/configFiles")
 
     totalExperimentRuns = generate_config_files(experiment)
     if totalExperimentRuns == 0:
@@ -138,49 +158,50 @@ def run_batch(data):
 
         upload_experiment_results(experiment)
     except ExperimentAbort as err:
-        print(f'Experiment {expId} critical failure, not doing any result uploading or post processing')
-        logging.exception(err)
+        explogger.critical(f'Experiment {expId} critical failure, not doing any result uploading or post processing')
+        explogger.exception(err)
     except Exception as err:
-        print(f'Uncaught exception "{err}" while running an experiment the GLADOS code needs to be changed to handle this in a cleaner manner')
-        logging.exception(err)
+        explogger.error(f'Uncaught exception "{err}" while running an experiment the GLADOS code needs to be changed to handle this in a cleaner manner')
+        explogger.exception(err)
         raise err
     finally:
         expRef.update({'finished': True, 'finishedAtEpochMillis': int(time.time() * 1000)})
-        print(f'Exiting experiment {expId}')
+        explogger.info(f'Exiting experiment {expId}')
+        close_experiment_logger()  # TODO upload to firebase
         os.chdir('../..')
 
 
 def determine_experiment_file_type(filepath):
     rawfiletype = magic.from_file(filepath)
-    print(rawfiletype)
+    explogger.info("Raw filetype is %s", rawfiletype)
     filetype = 'unknown'
     if 'Python script' in rawfiletype or 'python3' in rawfiletype:
         filetype = ExperimentType.PYTHON
     elif 'Java archive data (JAR)' in rawfiletype:
         filetype = ExperimentType.JAVA
 
     if filetype == 'unknown':
-        print(f"{rawfiletype} could not be mapped to python or java, if it should consider updating the matching statements")
+        explogger.info(f"{rawfiletype} could not be mapped to python or java, if it should consider updating the matching statements")
         raise NotImplementedError("Unknown experiment file type")
     return rawfiletype, filetype
 
 
 def download_experiment_files(experiment: ExperimentData):
     if experiment.trialExtraFile != '' or experiment.postProcess != '' or experiment.keepLogs:
-        print('There will be experiment outputs')
+        explogger.info('There will be experiment outputs')
         os.makedirs('ResCsvs')
-    print(f'Downloading file for {experiment.expId}')
+    explogger.info(f'Downloading file for {experiment.expId}')
 
     filepath = f'experiment{experiment.expId}'
     experiment.file = filepath
-    print(f"Downloading {filepath} to ExperimentFiles/{experiment.expId}/{filepath}")
+    explogger.info(f"Downloading {filepath} to ExperimentFiles/{experiment.expId}/{filepath}")
     try:
         filedata = firebaseBucket.blob(filepath)
         filedata.download_to_filename(filepath)
     except Exception as err:
-        print(f"Error {err} occurred while trying to download experiment file")
+        explogger.error(f"Error {err} occurred while trying to download experiment file")
         raise GladosInternalError('Failed to download experiment files') from err
-    print(f"Downloaded {filepath} to ExperimentFiles/{experiment.expId}/{filepath}")
+    explogger.info(f"Downloaded {filepath} to ExperimentFiles/{experiment.expId}/{filepath}")
     return filepath
 
 
@@ -207,14 +228,14 @@ def parseParams(hyperparameters):
 
 
 def upload_experiment_results(experiment: ExperimentData):
-    print('Uploading Results to the frontend')
+    explogger.info('Uploading Results to the frontend')
     uploadBlob = firebaseBucket.blob(f"results/result{experiment.expId}.csv")
     uploadBlob.upload_from_filename('results.csv')
 
     _upload_to_mongodb(experiment)
 
     if experiment.trialExtraFile != '' or experiment.postProcess:
-        print('Uploading Result Csvs')
+        explogger.info('Uploading Result Csvs')
         try:
             shutil.make_archive('ResultCsvs', 'zip', 'ResCsvs')
             uploadBlob = firebaseBucket.blob(f"results/result{experiment.expId}.zip")
@@ -226,15 +247,15 @@ def upload_experiment_results(experiment: ExperimentData):
             experimentZipEntry = {"_id": experiment.expId, "fileContent": encoded}
             try:
                 resultZipId = mongoResultsZipCollections.insert_one(experimentZipEntry).inserted_id
-                print(f"inserted zip file into mongodb with id: {resultZipId}")
+                explogger.info(f"inserted zip file into mongodb with id: {resultZipId}")
             except Exception as err:
                 raise GladosInternalError("Encountered error while inserting results into MongoDB") from err
         except Exception as err:
             raise GladosInternalError("Error uploading to firebase") from err
 
 
 def _upload_to_mongodb(experiment: ExperimentData):
-    print('Uploading to MongoDB')
+    explogger.info('Uploading to MongoDB')
     try:
         mongoClient.admin.command('ping')
     except ConnectionFailure as err:
@@ -251,17 +272,17 @@ def _upload_to_mongodb(experiment: ExperimentData):
     experimentResultEntry = {"_id": experiment.expId, "resultContent": experimentData}
     try:
         resultId = mongoResultsCollection.insert_one(experimentResultEntry).inserted_id
-        print(f"inserted result csv into mongodb with id: {resultId}")
+        explogger.info(f"inserted result csv into mongodb with id: {resultId}")
     except Exception as err:
         raise GladosInternalError("Encountered error while inserting results into MongoDB") from err
 
 
 def post_process_experiment(experiment: ExperimentData):
     if experiment.postProcess:
-        print("Beginning post processing")
+        explogger.info("Beginning post processing")
         try:
             if experiment.scatter:
-                print("Creating Scatter Plot")
+                explogger.info("Creating Scatter Plot")
                 depVar = experiment.scatterDepVar
                 indVar = experiment.scatterIndVar
                 generateScatterPlot(indVar, depVar, 'results.csv', experiment.expId)

apps/backend/legacy-tests/logging_tryme.py

@@ -0,0 +1,26 @@
+import logging
+
+logging.info('Starting logging try me')
+
+logger = logging.getLogger('helloworld')
+
+logger.setLevel(logging.DEBUG)
+
+debug_file_log = logging.FileHandler(filename="TESTING.DEBUG.log", encoding="utf-8")
+debug_file_log.setLevel(logging.DEBUG)
+logger.addHandler(debug_file_log)
+
+logger.debug('This message should go to only the first log file')
+
+debug_file_log.close()
+logger.removeHandler(debug_file_log)
+
+debug_file_log_2 = logging.FileHandler(filename="TESTING2.DEBUG.log", encoding="utf-8")
+debug_file_log_2.setLevel(logging.DEBUG)
+logger.addHandler(debug_file_log_2)
+
+logger.debug('This message should go to only the second log file')
+
+debug_file_log_2.close()
+
+logging.info('Logging try me concluded')

apps/backend/linters/no_print.py

@@ -0,0 +1,35 @@
+# Based on https://stackoverflow.com/questions/71026245/how-to-add-custom-pylint-warning
+
+from typing import TYPE_CHECKING
+
+from astroid import nodes
+
+from pylint.checkers import BaseChecker
+from pylint.checkers.utils import check_messages
+
+if TYPE_CHECKING:
+    from pylint.lint import PyLinter
+
+# TODO the CI can't seem to see this file (or its parent directory? so it currently only runs locally in the editor)
+
+class PrintUsedChecker(BaseChecker):
+
+    name = "no_print_allowed"
+    msgs = {
+        "C9001": (
+            "GLADOS: Used `print` statement, use the correct logger instead",
+            "glados-print-used",
+            "Messages that are printed aren't available in the system"
+            "logs nor to system users. Use the logging system.",
+        )
+    }
+
+    @check_messages("glados-print-used")
+    def visit_call(self, node: nodes.Call) -> None:
+        if isinstance(node.func, nodes.Name):
+            if node.func.name == "print":
+                self.add_message("glados-print-used", node=node)
+
+
+def register(linter: "PyLinter") -> None:
+    linter.register_checker(PrintUsedChecker(linter))