diff --git a/apps/backend/.gitignore b/apps/backend/.gitignore index b9910e02..ffecfb9c 100644 --- a/apps/backend/.gitignore +++ b/apps/backend/.gitignore @@ -1,6 +1,9 @@ # Ignore docker container volume contents ExperimentFiles/ +# Ignore log files produced by the system +logs/ + # Python __pycache__ .venv diff --git a/apps/backend/.pylintrc b/apps/backend/.pylintrc index e64f7be5..60f6906f 100644 --- a/apps/backend/.pylintrc +++ b/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 diff --git a/apps/backend/app.py b/apps/backend/app.py index 7b1395e1..b7811d88 100644 --- a/apps/backend/app.py +++ b/apps/backend/app.py @@ -5,7 +5,8 @@ import sys import json import time -from flask import Flask, jsonify, request +import typing +from flask import Flask, Response, jsonify, request from flask_cors import CORS import firebase_admin from firebase_admin import credentials @@ -14,35 +15,39 @@ import pymongo from pymongo.errors import ConnectionFailure from bson.binary import Binary +from modules.data.types import DocumentId, IncomingStartRequest +from modules.logging.gladosLogging import EXPERIMENT_LOGGER, SYSTEM_LOGGER, close_experiment_logger, configure_root_logger, open_experiment_logger, upload_experiment_log from modules.runner import conduct_experiment from modules.exceptions import CustomFlaskError, GladosInternalError, ExperimentAbort from modules.output.plots import generateScatterPlot from modules.configs import generate_config_files from modules.data.experiment import ExperimentData, ExperimentType -from modules.data.parameters import ParamType, BoolParameter, FloatParam, IntegerParam, Parameter, StringParameter +from modules.data.parameters import Parameter, parseRawHyperparameterData try: import magic # Crashes on windows if you're missing the 'python-magic-bin' python package except ImportError: - print("Failed to import the 'magic' package, you're probably missing a system level dependency") + logging.error("Failed to import the 'magic' package, you're probably missing a system level dependency") sys.exit(1) # Must override so that vscode doesn't incorrectly parse another env file and have bad values 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() +syslogger = logging.getLogger(SYSTEM_LOGGER) +explogger = logging.getLogger(EXPERIMENT_LOGGER) FIREBASE_CREDENTIALS = os.environ.get(ENV_FIREBASE_CREDENTIALS) if FIREBASE_CREDENTIALS is None: if HAS_DOTENV_FILE: raise AssertionError(f"Missing environment variable {ENV_FIREBASE_CREDENTIALS} in your `.env` file") - 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") + raise AssertionError(f"Missing environment variable {ENV_FIREBASE_CREDENTIALS} - you need a `.env` file in this folder with it defined") firebaseCredentials = credentials.Certificate(json.loads(FIREBASE_CREDENTIALS)) firebaseApp = firebase_admin.initialize_app(firebaseCredentials) @@ -60,15 +65,21 @@ 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) +syslogger.info("GLADOS Backend Started") + @flaskApp.post("/experiment") def recv_experiment(): - runner.submit(handle_exceptions_from_run, request.get_json()) - return 'OK' + data = request.get_json() + if _check_request_integrity(data): + runner.submit(run_batch_and_catch_exceptions, data) + return Response(status=200) + syslogger.error("Received malformed experiment request: %s", data) + return Response(status=400) @flaskApp.get("/queue") @@ -82,55 +93,83 @@ def glados_custom_flask_error(error): return jsonify(error.to_dict()), error.status_code -def handle_exceptions_from_run(data): +def _check_request_integrity(data: typing.Any): + try: + return data['experiment']['id'] is not None + except KeyError: + return False + + +def run_batch_and_catch_exceptions(data: IncomingStartRequest): 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) + syslogger.error("Unexpected exception while trying to run the experiment, this was not caught by our own code and needs to be handled better.") + syslogger.exception(err) + close_experiment_logger() + # Unsafe to upload experiment logs files here raise err -def run_batch(data): - print(f'Run_Batch starting with data {data}') - experiments = firebaseDb.collection(DB_COLLECTION_EXPERIMENTS) +def run_batch(data: IncomingStartRequest): + syslogger.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) + syslogger.debug('received %s', expId) - # Parsing the argument data - experimentData = expRef.get().to_dict() + open_experiment_logger(expId) + # Retrieve experiment details from firebase try: - hyperparameters: "dict[str,Parameter]" = parseParams(json.loads(experimentData['hyperparameters'])['hyperparameters']) + experiments = firebaseDb.collection(DB_COLLECTION_EXPERIMENTS) + expRef = experiments.document(expId) + experimentData = expRef.get().to_dict() + except Exception as err: # pylint: disable=broad-exception-caught + explogger.error("Error retrieving experiment data from firebase, aborting") + close_experiment_run(expId, None, err) + return + + # Parse hyperaparameters into their datatype. Required to parse the rest of the experiment data + try: + hyperparameters: "dict[str,Parameter]" = parseRawHyperparameterData(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)) + explogger.error("Error generating configs - hyperparameters not found in experiment object, aborting") + close_experiment_run(expId, expRef, err) + return experimentData['hyperparameters'] = hyperparameters - #Parsing into Datatype - experiment = ExperimentData(**experimentData) - experiment.postProcess = experiment.scatter + # Parsing into Datatype + try: + experiment = ExperimentData(**experimentData) + experiment.postProcess = experiment.scatter + except ValueError as err: + explogger.error("Experiment data was not formatted correctly, aborting") + close_experiment_run(expId, expRef, err) + 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: - raise GladosInternalError("Error generating configs - somehow no config files were produced?") + os.chdir('../..') + close_experiment_run(expId, expRef, GladosInternalError("Error generating configs - somehow no config files were produced?")) + experiment.totalExperimentRuns = totalExperimentRuns expRef.update({"totalExperimentRuns": experiment.totalExperimentRuns}) + possibleException = None try: conduct_experiment(experiment, expRef) @@ -138,21 +177,31 @@ 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) - 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) - raise err + explogger.error(f'Experiment {expId} critical failure, not doing any result uploading or post processing') + possibleException = err + except Exception as err: # pylint: disable=broad-exception-caught + explogger.error(f'Uncaught exception "{err}" while running an experiment. The GLADOS code needs to be changed to handle this in a cleaner manner') + possibleException = err finally: - expRef.update({'finished': True, 'finishedAtEpochMillis': int(time.time() * 1000)}) - print(f'Exiting experiment {expId}') + close_experiment_run(expId, expRef, possibleException) os.chdir('../..') +def close_experiment_run(expId: DocumentId, expRef: "typing.Any | None", error: "Exception | None"): + if error: + explogger.exception(error) + explogger.info(f'Exiting experiment {expId}') + if expRef: + expRef.update({'finished': True, 'finishedAtEpochMillis': int(time.time() * 1000)}) + else: + syslogger.warning(f'No experiment ref supplied when closing {expId} , could not update it to finished') + close_experiment_logger() + upload_experiment_log(expId) + + 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 @@ -160,63 +209,46 @@ def determine_experiment_file_type(filepath): 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 -def parseParams(hyperparameters): - result = {} - for param in hyperparameters: - name = param['name'] - del param['name'] - if param['type'] == 'integer': - param['type'] = ParamType.INTEGER - result[name] = IntegerParam(**param) - elif param['type'] == 'float': - param['type'] = ParamType.FLOAT - result[name] = FloatParam(**param) - elif param['type'] == 'bool': - param['type'] = ParamType.BOOL - result[name] = BoolParameter(**param) - elif param['type'] == 'string': - param['type'] = ParamType.STRING - result[name] = StringParameter(**param) - else: - raise GladosInternalError(f"{param['type']} is not a supported type") - return result - - def upload_experiment_results(experiment: ExperimentData): - print('Uploading Results to the frontend') + """ + Call this function when inside the experiment folder! + """ + 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') + if experiment.trialExtraFile != '' or experiment.postProcess or experiment.keepLogs: + explogger.info('Uploading Result Csvs') try: shutil.make_archive('ResultCsvs', 'zip', 'ResCsvs') + + # TODO remove firebase usage once transition to mongo file storage is complete uploadBlob = firebaseBucket.blob(f"results/result{experiment.expId}.zip") uploadBlob.upload_from_filename('ResultCsvs.zip') @@ -226,15 +258,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 + raise GladosInternalError("Error uploading experiment results") 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 +283,20 @@ 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): + """ + Call this function when inside the experiment folder! + """ 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) diff --git a/apps/backend/legacy-tests/logging_tryme.py b/apps/backend/legacy-tests/logging_tryme.py new file mode 100644 index 00000000..3210cd1a --- /dev/null +++ b/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') diff --git a/apps/backend/linters/no_print.py b/apps/backend/linters/no_print.py new file mode 100644 index 00000000..c378191d --- /dev/null +++ b/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)) diff --git a/apps/backend/modules/configs.py b/apps/backend/modules/configs.py index 43d71347..9dcbdc7e 100644 --- a/apps/backend/modules/configs.py +++ b/apps/backend/modules/configs.py @@ -6,9 +6,11 @@ from modules.data.parameters import ParamType, BoolParameter, FloatParam, IntegerParam, Parameter, StringParameter from modules.exceptions import GladosInternalError +from modules.logging.gladosLogging import get_experiment_logger FilePath = str +explogger = get_experiment_logger() def float_range(start: float, stop: float, step=1.0): count = 0 @@ -38,19 +40,18 @@ def generate_config_files(experiment: ExperimentData): configDict = {} configIdNumber = 0 - for defaultKey, defaultVar in parameters.items(): - print(f'Keeping {defaultVar} constant') + for varyingKey, varyingVar in parameters.items(): + explogger.info(f'Keeping {varyingVar} constant') possibleParamVals = [] #Required to do the cross product, since each config is made by #doing a cross product of lists of name value pairs the default variable needs to be #a single item list so that there is only one possible value for the default variable - default = [(defaultKey, get_default(defaultVar))] - possibleParamVals.append(default) + generate_list(varyingVar, varyingKey, possibleParamVals) for otherKey, otherVar in parameters.items(): - if otherKey != defaultKey: - generate_list(otherVar, otherKey, possibleParamVals) + if otherKey != varyingKey: + possibleParamVals.append([(otherKey, get_default(otherVar))]) try: permutations = list(itertools.product(*possibleParamVals)) except Exception as err: @@ -64,23 +65,22 @@ def generate_config_files(experiment: ExperimentData): configItems[name] = value configItems.update(constants) configDict[f'config{configIdNumber}'] = ConfigData(data=configItems) - print(f'Generated config {configIdNumber}') + explogger.info(f'Generated config {configIdNumber}') configIdNumber += 1 - print("Finished generating configs") + explogger.info("Finished generating configs") experiment.configs = configDict return configIdNumber def create_config_from_data(experiment: ExperimentData, configNum: int): if experiment.configs == {}: - msg = f"Configs for experiment{experiment.expId} is Empty at create_config_from_data, Config File will be empty" - print(msg) + explogger.info(f"Configs for experiment{experiment.expId} is Empty at create_config_from_data, Config File will be empty") try: configData = experiment.configs[f'config{configNum}'].data except KeyError as err: #TODO: Discuss how we handle this error msg = f"There is no config {configNum} cannot generate this config, there are only {len(experiment.configs)} configs" - print(msg) + explogger.exception(err) raise GladosInternalError(msg) from err os.chdir('configFiles') @@ -91,7 +91,7 @@ def create_config_from_data(experiment: ExperimentData, configNum: int): outputConfig.write(configFile) configFile.write(experiment.dumbTextArea) configFile.close() - print(f"Wrote config{configNum} to a file") + explogger.info(f"Wrote config{configNum} to a file") os.chdir('..') return f'{configNum}.ini' @@ -120,21 +120,20 @@ def gather_parameters(hyperparams, constants, parameters): param = FloatParam(**hyperparameter.dict()) #Since we already know if param will be an integer or a float we can access min and max without messing anything up if param.min == param.max: - print(f'param {parameterKey} has the same min and max value; converting to constant') + explogger.warning(f'param {parameterKey} has the same min and max value; converting to constant') constants[parameterKey] = param.min else: #Varies adding to batch - print(f'param {parameterKey} varies, adding to batch') + explogger.info(f'param {parameterKey} varies, adding to batch') parameters[parameterKey] = param elif parameterType == ParamType.STRING: #Strings never vary technically should be in the constants section now stringParam = StringParameter(**hyperparameter.dict()) - print(f'param {parameterKey} is a string, adding to constants') + explogger.warning(f'param {parameterKey} is a string, adding to constants') constants[parameterKey] = stringParam.default elif parameterType == ParamType.BOOL: - print(f'param {parameterKey} varies, adding to batch') + explogger.info(f'param {parameterKey} varies, adding to batch') parameters[parameterKey] = hyperparameter else: msg = f'ERROR DURING CONFIG GEN: param {parameterKey} {hyperparameter} Does not have a supported type' - print(msg) raise GladosInternalError(msg) except KeyError as err: raise GladosInternalError('Error during finding constants') from err diff --git a/apps/backend/modules/data/parameters.py b/apps/backend/modules/data/parameters.py index 11e33a76..650cb0d5 100644 --- a/apps/backend/modules/data/parameters.py +++ b/apps/backend/modules/data/parameters.py @@ -1,6 +1,8 @@ from enum import Enum from pydantic import BaseModel, validator, root_validator +from modules.exceptions import GladosInternalError + class ParamType(Enum): BOOL = "bool" @@ -68,3 +70,27 @@ def check_step(cls, step: float): if step <= 0: raise ValueError("Step value cannot be less than or equal to 0") return step + + +def parseRawHyperparameterData(hyperparameters): + result = {} + for entry in hyperparameters: + entryType = entry['type'] + entryName = entry['name'] + del entry['name'] + + if entryType == 'integer': + entry['type'] = ParamType.INTEGER + result[entryName] = IntegerParam(**entry) + elif entryType == 'float': + entry['type'] = ParamType.FLOAT + result[entryName] = FloatParam(**entry) + elif entryType == 'bool': + entry['type'] = ParamType.BOOL + result[entryName] = BoolParameter(**entry) + elif entryType == 'string': + entry['type'] = ParamType.STRING + result[entryName] = StringParameter(**entry) + else: + raise GladosInternalError(f"{entryType} (used by '{entryName}') is not a supported hyperparameter type") + return result diff --git a/apps/backend/modules/data/types.py b/apps/backend/modules/data/types.py index 2d206711..f3f7b7ca 100644 --- a/apps/backend/modules/data/types.py +++ b/apps/backend/modules/data/types.py @@ -1,10 +1,15 @@ from enum import Enum +from typing import Any, Dict, TypedDict DocumentId = str UserId = str EpochMilliseconds = int +class IncomingStartRequest(TypedDict): + experiment: "Dict[str, Any]" + + class ResultStatus(Enum): UNKNOWN = "unknown" SUCCESS = "success" diff --git a/apps/backend/modules/logging/gladosLogging.py b/apps/backend/modules/logging/gladosLogging.py new file mode 100644 index 00000000..f0a0c1f6 --- /dev/null +++ b/apps/backend/modules/logging/gladosLogging.py @@ -0,0 +1,109 @@ +import datetime +import logging +from logging.handlers import RotatingFileHandler +import os + +from modules.data.types import DocumentId + +# Important information about loggers: +# + Calls of child loggers will be propgated to parent loggers. +# So, logging to `glados.experiment` will also log to `glados` +# + They can be written to from multiple THREADS without issue, but not multiple PROCESSES +# https://docs.python.org/3/library/logging.html#thread-safety +# + It's not a good idea to create a ton of loggers, because they are never GC'd. +# That's why we use new handlers to separate log files, instead of creating a new logger for each experiment. +# https://docs.python.org/3/howto/logging-cookbook.html#patterns-to-avoid +# + If a child logger's parent has handlers set up, the parent's handlers will be considered when calling hasHandlers, but not in logger.handlers + +SYSTEM_LOGGER = 'glados' +EXPERIMENT_LOGGER = 'glados.experiment' + +LOGGING_DIRECTORY = 'logs' + + +def _create_directories(): + # https://stackoverflow.com/questions/32133856/logger-cannot-find-file + if not os.path.exists(LOGGING_DIRECTORY): + os.makedirs(LOGGING_DIRECTORY) + if not os.path.exists(f"{LOGGING_DIRECTORY}/experiment"): + os.makedirs(f"{LOGGING_DIRECTORY}/experiment") + + +def get_system_logger(): + return logging.getLogger(SYSTEM_LOGGER) + + +def get_experiment_logger(): + return logging.getLogger(EXPERIMENT_LOGGER) + + +root_logger = get_system_logger() + + +def configure_root_logger(): + _create_directories() + + root_logger.setLevel(logging.DEBUG) + + bytes_to_megabytes = 1000000 + max_file_size = 10 * bytes_to_megabytes + system_log_file = RotatingFileHandler(filename=f"{LOGGING_DIRECTORY}/system.DEBUG.log", encoding="utf-8", backupCount=10, maxBytes=max_file_size) + system_log_file.setLevel(logging.DEBUG) + system_log_file.setFormatter(_standard_file_formatter()) + root_logger.addHandler(system_log_file) + + console = logging.StreamHandler() + console.setLevel(logging.DEBUG) + console.setFormatter(_standard_stream_formatter()) + root_logger.addHandler(console) + + +def get_filepath_for_experiment_log(experimentId: DocumentId): + return f"{LOGGING_DIRECTORY}/experiment/experiment_{experimentId}.log" + + +def open_experiment_logger(experimentId: DocumentId): + root_logger.info('Opening experiment logger for experiment %s', experimentId) + explogger = logging.getLogger(EXPERIMENT_LOGGER) + + if len(explogger.handlers) > 0: + root_logger.error("Experiment logger already has a handler! This means the last one wasn't closed properly. Closing it now to avoid file pollution.") + while len(explogger.handlers) > 0: + item = explogger.handlers[0] + root_logger.error("Closed a handler: %s", item) + explogger.removeHandler(item) + + experiment_log_file = logging.FileHandler(filename=get_filepath_for_experiment_log(experimentId), encoding="utf-8") + experiment_log_file.setLevel(logging.DEBUG) + experiment_log_file.setFormatter(_standard_file_formatter()) + explogger.addHandler(experiment_log_file) + + +def close_experiment_logger(): + root_logger.info('Closing experiment logger file') + + explogger = logging.getLogger(EXPERIMENT_LOGGER) + if len(explogger.handlers) == 0: + root_logger.warning("Experiment logger has no handler! This means it was closed twice. Ignoring.") + return + handler = explogger.handlers[0] + explogger.removeHandler(handler) + handler.close() + + +def upload_experiment_log(experimentId: DocumentId): + filePath = get_filepath_for_experiment_log(experimentId) + get_system_logger().warning('TODO upload the file to the database: %s', filePath) + + +def _standard_file_formatter(): + formatter = logging.Formatter("%(asctime)s | %(levelname)s | %(name)s | %(message)s") + formatter.usesTime() + formatter.formatTime = ( # https://stackoverflow.com/a/58777937 + lambda record, datefmt=None: datetime.datetime.fromtimestamp(record.created, datetime.timezone.utc).astimezone().isoformat(sep="T", timespec="milliseconds")) + return formatter + + +def _standard_stream_formatter(): + formatter = logging.Formatter("%(levelname)s | %(name)s | %(message)s") + return formatter diff --git a/apps/backend/modules/output/plots.py b/apps/backend/modules/output/plots.py index 394d4c81..609e691a 100644 --- a/apps/backend/modules/output/plots.py +++ b/apps/backend/modules/output/plots.py @@ -4,6 +4,9 @@ import matplotlib.pyplot as plt from modules.exceptions import FileHandlingError +from modules.logging.gladosLogging import get_experiment_logger + +explogger = get_experiment_logger() def generateScatterPlot(independentVar, dependantVar, resultFile, expId): @@ -18,8 +21,8 @@ def generateScatterPlot(independentVar, dependantVar, resultFile, expId): y.append(float(row[depIndex])) figure, axes = plt.subplots() - print(np.array(x)) - print(np.array(y)) + explogger.info('Array of x is %s', np.array(x)) + explogger.info('Array of y is %s', np.array(y)) m, b = np.polyfit(np.array(x), np.array(y), 1) sc = axes.scatter(x,y) plt.plot(x, m*np.array(x) + b) diff --git a/apps/backend/modules/runner.py b/apps/backend/modules/runner.py index 2f8b75d8..fb6bbe35 100644 --- a/apps/backend/modules/runner.py +++ b/apps/backend/modules/runner.py @@ -10,10 +10,12 @@ from modules.exceptions import ExperimentAbort, FileHandlingError, GladosInternalError, GladosUserError, TrialTimeoutError from modules.exceptions import InternalTrialFailedError from modules.configs import get_config_paramNames +from modules.logging.gladosLogging import get_experiment_logger PROCESS_OUT_STREAM = 0 PROCESS_ERROR_STREAM = 1 +explogger = get_experiment_logger() def get_data(process: 'Popen[str]', trialRun: int, keepLogs: bool, trialTimeout: int): try: @@ -28,13 +30,13 @@ def get_data(process: 'Popen[str]', trialRun: int, keepLogs: bool, trialTimeout: os.chdir('..') if data[PROCESS_ERROR_STREAM]: errorMessage = f'errors returned from pipe is {data[PROCESS_ERROR_STREAM]}' - print(errorMessage) + explogger.error(errorMessage) raise InternalTrialFailedError(errorMessage) except TimeoutExpired as timeErr: - print(f"{timeErr} Trial timed out") + explogger.error(f"{timeErr} Trial timed out") raise TrialTimeoutError("Trial took too long to complete") from timeErr except Exception as err: - print("Encountered another exception while reading pipe: {err}") + explogger.error("Encountered another exception while reading pipe: {err}") raise InternalTrialFailedError("Encountered another exception while reading pipe") from err @@ -63,7 +65,7 @@ def get_line_n_of_trial_results_csv(targetLineNumber: int, filename: str): msg = f"{filename} only has one line, Potentially only has a Header or Value row" else: msg = "Error in get nth line that should not occur" - print(msg) + explogger.error(msg) raise GladosUserError(msg) except Exception as err: raise GladosUserError("Failed to read trial results csv, does the file exist? Typo in the user-specified output filename(s)?") from err @@ -77,8 +79,11 @@ def add_to_output_batch(fileOutput, ExpRun): def conduct_experiment(experiment: ExperimentData, expRef): + """ + Call this function when inside the experiment folder! + """ os.mkdir('configFiles') - print(f"Running Experiment {experiment.expId}") + explogger.info(f"Running Experiment {experiment.expId}") experiment.passes = 0 experiment.fails = 0 @@ -86,10 +91,11 @@ def conduct_experiment(experiment: ExperimentData, expRef): with open('results.csv', 'w', encoding="utf8") as expResults: paramNames = [] writer = csv.writer(expResults) - print(f"Now Running {experiment.totalExperimentRuns} trials") + explogger.info(f"Now Running {experiment.totalExperimentRuns} trials") for trialNum in range(0, experiment.totalExperimentRuns): startSeconds = time.time() - expRef.update({"startedAtEpochMillis": int(startSeconds * 1000)}) + if trialNum == 0: + expRef.update({"startedAtEpochMillis": int(startSeconds * 1000)}) try: configFileName = create_config_from_data(experiment, trialNum) @@ -101,25 +107,25 @@ def conduct_experiment(experiment: ExperimentData, expRef): try: run_trial(experiment, f'configFiles/{configFileName}', trialNum) except InternalTrialFailedError as err: - print(f'Trial#{trialNum} Encountered an Error') + explogger.error(f'Trial#{trialNum} Encountered an Error') experiment.fails += 1 expRef.update({'fails': experiment.fails}) if numOutputs is not None: #After the first trial this should be defined not sure how else to do this writer.writerow([trialNum] + ["ERROR" for i in range(numOutputs)] + get_configs_ordered(f'configFiles/{trialNum}.ini', paramNames)) if trialNum == 0: #First Trial Failure Abort message = f"First trial of {experiment.expId} ran into an error while running, aborting the whole experiment. Read the traceback to find out what the actual cause of this problem is (it will not necessarily be at the top of the stack trace)." - print(message) + explogger.error(message) raise ExperimentAbort(message) from err continue except TrialTimeoutError as timeoutErr: #First Trial timeout Abort - print(f"Trial#{trialNum} timed out") + explogger.error(f"Trial#{trialNum} timed out") experiment.fails += 1 expRef.update({'fails': experiment.fails}) if numOutputs is not None: #After the first trial this should be defined not sure how else to do this writer.writerow([trialNum] + ["TIMEOUT" for i in range(numOutputs)] + get_configs_ordered(f'configFiles/{trialNum}.ini', paramNames)) if trialNum == 0: - message = f"First trial of {experiment.expId} timed out into an error while running, aborting the whole experiment." - print(message) + message = f"First trial of {experiment.expId} timed out while running, aborting the whole experiment." + explogger.error(message) raise ExperimentAbort(message) from timeoutErr continue @@ -129,7 +135,7 @@ def conduct_experiment(experiment: ExperimentData, expRef): if trialNum == 0: #Setting up the Headers of the CSV estimatedTotalTimeMinutes = timeTakenMinutes * experiment.totalExperimentRuns - print(f"Estimated minutes to run: {estimatedTotalTimeMinutes}") + explogger.info(f"Estimated minutes to run: {estimatedTotalTimeMinutes}") expRef.update({'estimatedTotalTimeMinutes': estimatedTotalTimeMinutes}) #Setting up the header for the Result try: @@ -147,7 +153,7 @@ def conduct_experiment(experiment: ExperimentData, expRef): raise err writer.writerow([trialNum] + output + get_configs_ordered(f'configFiles/{trialNum}.ini', paramNames)) - print(f'Trial#{trialNum} completed') + explogger.info(f'Trial#{trialNum} completed') experiment.passes += 1 expRef.update({'passes': experiment.passes}) - print("Finished running Trials") + explogger.info("Finished running Trials") diff --git a/apps/backend/tests/typeTesting.py b/apps/backend/tests/typeTesting.py index 850fe37b..5ffd7203 100644 --- a/apps/backend/tests/typeTesting.py +++ b/apps/backend/tests/typeTesting.py @@ -1,8 +1,7 @@ import json -from app import parseParams -from modules.data.experiment import ExperimentData +from app import parseRawHyperparameterData from modules.configs import generate_config_files -from modules.data.experiment import ExperimentType +from modules.data.experiment import ExperimentType, ExperimentData # This file shows how to construct an ExperimentData object from a JSON string # This approach can help in writing tests for that functionality, after that, this file can be deleted @@ -34,7 +33,7 @@ 'expId': 'V3dpcllHWPrK1Kgbyzqb' } # cspell:enable - hyperparameters = parseParams(json.loads(expInfo['hyperparameters'])['hyperparameters']) + hyperparameters = parseRawHyperparameterData(json.loads(expInfo['hyperparameters'])['hyperparameters']) expInfo['hyperparameters'] = hyperparameters experiment = ExperimentData(**expInfo) generate_config_files(experiment) diff --git a/apps/frontend/components/flows/AddExperiment/stepComponents/InformationStep.tsx b/apps/frontend/components/flows/AddExperiment/stepComponents/InformationStep.tsx index 3d8e929e..a5c1e022 100644 --- a/apps/frontend/components/flows/AddExperiment/stepComponents/InformationStep.tsx +++ b/apps/frontend/components/flows/AddExperiment/stepComponents/InformationStep.tsx @@ -45,7 +45,7 @@ export const InformationStep = ({ form, ...props }) => { /> - +
= async (req, res) => { console.error('Error contacting server: ', error); res.status(500).json({ response: message } as any); } - console.log('found results: ', results); if (results.length !== 1) { console.warn(`Experiment ${expIdToCsvDownload} CSV not found`); res.status(404).json({ response: 'Experiment CSV not found' } as any); diff --git a/apps/frontend/pages/api/download/zip/[expIdToZipDownload].tsx b/apps/frontend/pages/api/download/zip/[expIdToZipDownload].tsx index a9cd803b..9b9557b6 100644 --- a/apps/frontend/pages/api/download/zip/[expIdToZipDownload].tsx +++ b/apps/frontend/pages/api/download/zip/[expIdToZipDownload].tsx @@ -25,7 +25,6 @@ const mongoZipHandler: NextApiHandler = async (req, res) => { console.error('Error contacting server: ', error); res.status(500).json({ response: message } as any); } - console.log('found results: ', results); if (results.length !== 1) { console.warn(`Experiment ${expIdToZipDownload} ZIP not found`); res.status(404).json({ response: 'Experiment ZIP not found' } as any);