diff --git a/gusto/io.py b/gusto/io.py index f8bd37bf4..f436607e4 100644 --- a/gusto/io.py +++ b/gusto/io.py @@ -10,7 +10,7 @@ from firedrake import (Function, functionspaceimpl, File, DumbCheckpoint, FILE_CREATE, FILE_READ, CheckpointFile) import numpy as np -from gusto.logging import logger +from gusto.logging import logger, update_logfile_location __all__ = ["pick_up_mesh", "IO"] @@ -36,6 +36,7 @@ def pick_up_mesh(output, mesh_name): chkfile = output.checkpoint_pickup_filename else: dumpdir = path.join("results", output.dirname) + update_logfile_location(dumpdir) chkfile = path.join(dumpdir, "chkpt.h5") with CheckpointFile(chkfile, 'r') as chk: mesh = chk.load_mesh(mesh_name) @@ -293,6 +294,7 @@ def setup_dump(self, state_fields, t, pick_up=False): self.output.point_data, self.output.checkpoint and not pick_up]): # setup output directory and check that it does not already exist self.dumpdir = path.join("results", self.output.dirname) + update_logfile_location(self.dumpdir) running_tests = '--running-tests' in sys.argv or "pytest" in self.output.dirname if self.mesh.comm.Get_rank() == 0: @@ -429,6 +431,7 @@ def pick_up_from_checkpoint(self, state_fields): # Set dumpdir if has not been done already if self.dumpdir is None: self.dumpdir = path.join("results", self.output.dirname) + update_logfile_location(self.dumpdir) # Need to pick up reference profiles, but don't know which are stored possible_ref_profiles = [] diff --git a/gusto/logging.py b/gusto/logging.py index bfc760843..9db5d9211 100644 --- a/gusto/logging.py +++ b/gusto/logging.py @@ -31,14 +31,36 @@ from datetime import datetime from logging import NOTSET, DEBUG, INFO, WARNING, ERROR, CRITICAL # noqa: F401 +from pathlib import Path from pyop2.mpi import COMM_WORLD -__all__ = ["logger", "set_log_handler"] +__all__ = [ + "logger", "set_log_handler", "LoggingError", "NOTSET", "DEBUG", + "INFO", "WARNING", "ERROR", "CRITICAL" +] + + +class LoggingError(Exception): + pass + logging.captureWarnings(True) logger = logging.getLogger("gusto") + +def capture_exceptions(exception_type, exception_value, traceback, logger=logger): + """ This function allows all unhandled exceptions to be logged to + Gusto's logs + """ + logger.error( + "Gusto is logging this unhandled exception:", + exc_info=(exception_type, exception_value, traceback) + ) + + +sys.excepthook = capture_exceptions + # Set the log level based on environment variables log_level = os.environ.get("GUSTO_LOG_LEVEL", WARNING) logfile_level = os.environ.get("GUSTO_FILE_LOG_LEVEL", DEBUG) @@ -60,14 +82,14 @@ parallel_log = None -def create_logfile_handler(path): - ''' Handler for logfiles +def create_logfile_handler(path, mode="w"): + """ Handler for logfiles. Args: path: path to log file - ''' - logfile = logging.FileHandler(filename=path, mode="w") + """ + logfile = logging.FileHandler(filename=path, mode=mode) logfile.setLevel(logfile_level) logfile_formatter = logging.Formatter( '%(asctime)s %(levelname)-8s %(message)s' @@ -77,11 +99,11 @@ def create_logfile_handler(path): def create_console_handler(fmt): - ''' Handler for console logging + """ Handler for console logging. Args: fmt: format string for log output - ''' + """ console = logging.StreamHandler() console.setLevel(logconsole_level) console_formatter = logging.Formatter(fmt) @@ -90,15 +112,14 @@ def create_console_handler(fmt): def set_log_handler(comm=COMM_WORLD): - """ - Set all handlers for logging. + """ Set all handlers for logging. Args: comm (:class:`MPI.Comm`): MPI communicator. """ # Set up logging timestamp = datetime.now() - logfile_name = f"gusto-{timestamp.strftime('%Y-%m-%dT%H%M%S')}" + logfile_name = f"temp-gusto-{timestamp.strftime('%Y-%m-%dT%H%M%S')}" if parallel_log in ["FILE", "BOTH"]: logfile_name += f"_{comm.rank}" logfile_name += ".log" @@ -113,15 +134,55 @@ def set_log_handler(comm=COMM_WORLD): if comm.rank == 0: # Always log on rank 0 - logger.addHandler(create_logfile_handler(logfile_path)) - logger.addHandler(create_console_handler(console_format_str)) + lfh = create_logfile_handler(logfile_path) + lfh.name = "gusto-temp-file-log" + logger.addHandler(lfh) + ch = create_console_handler(console_format_str) + ch.name = "gusto-console-log" + logger.addHandler(ch) else: # Only log on other ranks if enabled if parallel_log in ["FILE", "BOTH"]: - logger.addHandler(create_logfile_handler(logfile_path)) + lfh = create_logfile_handler(logfile_path) + lfh.name = "gusto-temp-file-log" + logger.addHandler(lfh) if parallel_log in ["CONSOLE", "BOTH"]: - logger.addHandler(create_console_handler(console_format_str)) + ch = create_console_handler(console_format_str) + ch.name = "gusto-console-log" + logger.addHandler(ch) if not logger.handlers: logger.addHandler(logging.NullHandler()) logger.info("Running %s" % " ".join(sys.argv)) + + +def update_logfile_location(new_path): + """ Update the location of the logfile. + + This is used to move the temporary log file created in the results + directory to the appropriate model directory. + + """ + new_path = Path(new_path) + fh = [*filter(lambda x: x.name == "gusto-temp-file-log", logger.handlers)] + + if len(fh) == 1: + fh = fh[0] + logger.debug("Closing temporary logger and moving logfile") + old_path = Path(fh.baseFilename) + filename = Path(old_path.name.removeprefix("temp-")) + fh.flush() + fh.close() + + os.makedirs(new_path, exist_ok=True) + os.rename(old_path, new_path/filename) + + new_fh = create_logfile_handler(new_path/filename, mode="a") + new_fh.name = "gusto-file-log" + logger.addHandler(new_fh) + logger.debug("Re-opening logger") + elif len(fh) > 1: + raise LoggingError( + "More than one log handler with name `gusto-temp-file-log`\n" + "Logging has been set up incorrectly" + )