diff --git a/changelog.txt b/changelog.txt index 4cd40bdf9..7e3857add 100644 --- a/changelog.txt +++ b/changelog.txt @@ -27,6 +27,7 @@ Added - ``test-workflow`` CLI option for testing template environments/submission scripts (#747). - Frontier environment and template (#743). - Added ``-o`` / ``--operation`` flag to report project status information for specific operations (#725). +- Added builtin ``LogOperations`` execution hooks (#661). Changed +++++++ diff --git a/flow/hooks/__init__.py b/flow/hooks/__init__.py index bba7812f1..e7af75cd9 100644 --- a/flow/hooks/__init__.py +++ b/flow/hooks/__init__.py @@ -3,5 +3,6 @@ # This software is licensed under the BSD 3-Clause License. """Operation hooks.""" from .hooks import _Hooks +from .log_operations import LogOperations -__all__ = ["_Hooks"] +__all__ = ["_Hooks", "LogOperations"] diff --git a/flow/hooks/hooks.py b/flow/hooks/hooks.py index 9da269298..3765bc4c8 100644 --- a/flow/hooks/hooks.py +++ b/flow/hooks/hooks.py @@ -43,8 +43,8 @@ class _Hooks: def start_hook(operation_name, job): print(f"Starting operation {operation_name} on job {job.id}.") - @FlowProject.operation @FlowProject.operation_hooks.on_start(start_hook) + @FlowProject.operation def foo(job): pass diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py new file mode 100644 index 000000000..ffdfa2235 --- /dev/null +++ b/flow/hooks/log_operations.py @@ -0,0 +1,144 @@ +# Copyright (c) 2023 The Regents of the University of Michigan +# All rights reserved. +# This software is licensed under the BSD 3-Clause License. +"""Builtin execution hook for basic logging.""" +import logging + + +class LogOperations: + """:class:`~.LogOperations` logs information about the execution of operations to a log file. + + This hook can provide information on the start, successful completion, and/or + erroring of one or more operations in a `flow.FlowProject` instance. The logs are stored in a + file given by the parameter ``fn_logfile``. This file will be appended to if it already exists. + + The default formating for the log provides the time, job id, log level, and log message. + + .. note:: + + All logging is performed at the INFO level. To ensure outputs are captured in log files, + use the `--debug` flag when running or submitting jobs, or specify + `submit_options=--debug` in your directives (example shown below). + + + Examples + -------- + The following example will install :class:`~.LogOperations` at the operation level. + Where the log will be stored in a file name `foo.log` in the job directory. + + .. code-block:: python + from flow import FlowProject + from flow.hooks import LogOperations + + + class Project(FlowProject): + pass + + + def install_operation_log_hook(operation_name, project_cls): + log = LogOperation(f"{operation_name}.log") + return lambda op: log.install_operation_hooks(op, project_cls) + + + @install_operation_log_hook("foo", Project) + @Project.operation(directives={ + "submit_options": "--debug" # Always submit operation foo with the --debug flag + }) + def foo(job): + pass + + + The code block below provides an example of how install :class:`~.LogOperations` to an + instance of :class:`~.FlowProject` + + .. code-block:: python + from flow import FlowProject + from flow.hooks import LogOperations # Import build + + + class Project(FlowProject): + pass + + + # Project operation definitions + + + if __name__ == "__main__": + project = Project() + project = LogOperations().install_project_hooks(project) + project.main() + + Parameters + ---------- + fn_logfile : str + The name of the log file in the job directory. Default is "operations.log". + """ + + def __init__(self, fn_logfile="operations.log"): + self._fn_logfile = fn_logfile + # getLogger keep its own cache. This reduces the time spent setting up loggers + # by only doing it once. + self._loggers = {} + + def on_start(self, operation, job): + """Log the start of execution of an operation on a job.""" + self._get_logger(job).info(f"Operation '{operation}' started.") + + def on_success(self, operation, job): + """Log the successful completion of a given job(s) operation pair.""" + self._get_logger(job).info( + f"Operation '{operation}' finished without exception." + ) + + def on_exception(self, operation, error, job): + """Log the raising of an error in the execution of a given job(s) operation pair.""" + self._get_logger(job).info( + f"Operation '{operation}' failed with error '{error}'." + ) + + def _get_logger(self, job): + if job not in self._loggers: + self._loggers[job] = self._setup_logger(job) + return self._loggers[job] + + def _setup_logger(self, job): + logger = logging.getLogger(str(job)) + fh = logging.FileHandler(job.fn(self._fn_logfile)) + fh.setLevel(logging.DEBUG) + formatter = logging.Formatter( + "%(asctime)s - %(name)s - %(levelname)s - %(message)s" + ) + fh.setFormatter(formatter) + logger.addHandler(fh) + return logger + + def install_operation_hooks(self, op, project_cls=None): + """Decorate operation to log execution. + + Parameters + ---------- + op : function or type + An operation function to log or a subclass of `flow.FlowProject` if ``project_cls`` is + ``None``. + project_cls : type + A subclass of `flow.FlowProject`. + """ + if project_cls is None: + return lambda func: self.install_operation_hooks(func, op) + project_cls.operation_hooks.on_start(self.on_start)(op) + project_cls.operation_hooks.on_success(self.on_success)(op) + project_cls.operation_hooks.on_exception(self.on_exception)(op) + return op + + def install_project_hooks(self, project): + """Install log operation to all operations in a signac-flow project. + + Parameters + ---------- + project : flow.FlowProject + The project to install hooks on. + """ + project.project_hooks.on_start.append(self.on_start) + project.project_hooks.on_success.append(self.on_success) + project.project_hooks.on_exception.append(self.on_exception) + return project diff --git a/tests/define_hooks_logging_install.py b/tests/define_hooks_logging_install.py new file mode 100644 index 000000000..5b5197138 --- /dev/null +++ b/tests/define_hooks_logging_install.py @@ -0,0 +1,36 @@ +from define_hooks_logging_project import ( + HOOKS_ERROR_MESSAGE, + HOOKS_RUNTIME_MESSAGE, + set_logger, +) + +import flow +from flow.hooks import LogOperations + + +class _HooksLogOperationsProject(flow.FlowProject): + pass + + +@_HooksLogOperationsProject.operation +def base(job): + logger = set_logger(job) + + logger.info(HOOKS_RUNTIME_MESSAGE) + + if job.sp.raise_exception: + raise RuntimeError(HOOKS_ERROR_MESSAGE) + + +@_HooksLogOperationsProject.operation(cmd=True) +def base_cmd(job): + if job.sp.raise_exception: + return "exit 42" + else: + return "touch base_cmd.txt" + + +if __name__ == "__main__": + LogOperations("operations.log").install_project_hooks( + _HooksLogOperationsProject() + ).main() diff --git a/tests/define_hooks_logging_project.py b/tests/define_hooks_logging_project.py new file mode 100644 index 000000000..0ce4febe5 --- /dev/null +++ b/tests/define_hooks_logging_project.py @@ -0,0 +1,48 @@ +import logging + +from define_hooks_test_project import HOOKS_ERROR_MESSAGE + +from flow import FlowProject +from flow.hooks import LogOperations + +HOOKS_RUNTIME_MESSAGE = "Runtime message." + + +class _HooksLogOperationsProject(FlowProject): + pass + + +operation_log = LogOperations("operations.log") + + +def set_logger(job): + logger = logging.getLogger(str(job)) + sh = logging.StreamHandler() + logger.addHandler(sh) + return logger + + +@operation_log.install_operation_hooks(_HooksLogOperationsProject) +@_HooksLogOperationsProject.operation +def base(job): + logger = set_logger(job) + + logger.info(HOOKS_RUNTIME_MESSAGE) + + if job.sp.raise_exception: + raise RuntimeError(HOOKS_ERROR_MESSAGE) + + +@_HooksLogOperationsProject.operation_hooks.on_start(operation_log.on_start) +@_HooksLogOperationsProject.operation_hooks.on_success(operation_log.on_success) +@_HooksLogOperationsProject.operation_hooks.on_exception(operation_log.on_exception) +@_HooksLogOperationsProject.operation(cmd=True) +def base_cmd(job): + if job.sp.raise_exception: + return "exit 42" + else: + return "touch base_cmd.txt" + + +if __name__ == "__main__": + _HooksLogOperationsProject().main() diff --git a/tests/test_project.py b/tests/test_project.py index b5937cd0f..159fb4271 100644 --- a/tests/test_project.py +++ b/tests/test_project.py @@ -11,6 +11,7 @@ from io import StringIO from itertools import groupby +import define_hooks_logging_project import define_hooks_test_project import define_status_test_project import pytest @@ -2307,7 +2308,7 @@ def mock_project(self): project._entrypoint = self.entrypoint return project - def call_subcmd(self, subcmd, stderr=subprocess.DEVNULL): + def call_subcmd(self, subcmd, stderr=subprocess.PIPE): # Bypass raising the error/checking output since it interferes with hook.on_exception fn_script = self.entrypoint["path"] _cmd = f"python {fn_script} {subcmd} --debug" @@ -2316,8 +2317,8 @@ def call_subcmd(self, subcmd, stderr=subprocess.DEVNULL): with _switch_to_directory(self.project.path): return subprocess.check_output(_cmd.split(), stderr=stderr) except subprocess.CalledProcessError as error: - print(error, file=sys.stderr) - print(error.output, file=sys.stderr) + print("STDOUT:", error.stdout, sep="\n", file=sys.stderr) + print("STDERR:", error.stderr, sep="\n", file=sys.stderr) raise @pytest.fixture(scope="function") @@ -2462,8 +2463,13 @@ def test_no_decorator_keys(self, operation_name, job): class TestHooksInvalidOption(TestHooksSetUp): - def call_subcmd(self, subcmd, stderr=subprocess.STDOUT): - # Return error as output instead of raising error + def call_subcmd(self, subcmd, stderr=subprocess.PIPE): + """Call a flow command through the CLI. + + Return error as output instead of raising error. By default we also print out the stdout and + stderr of the `CalledProcessError` since pytest will capture it by default anyways. This + aids the debugging of tests by providing a traceback of the internal error. + """ fn_script = self.entrypoint["path"] _cmd = f"python {fn_script} {subcmd} --debug" with _add_path_to_environment_pythonpath(os.path.abspath(self.cwd)): @@ -2471,7 +2477,11 @@ def call_subcmd(self, subcmd, stderr=subprocess.STDOUT): with _switch_to_directory(self.project.path): return subprocess.check_output(_cmd.split(), stderr=stderr) except subprocess.CalledProcessError as error: - return str(error.output) + if error.stderr: + print("STDERR:", error.stderr, sep="\n") + if error.stdout: + print("STDOUT:", error.stderr, sep="\n") + return str(error.stdout) + str(error.stderr) def test_invalid_hook(self): class A(FlowProject): @@ -2511,6 +2521,64 @@ def test_raise_exception_in_hook_cmd(self): assert "RuntimeError" in error_output +class TestHooksLog(TestHooksSetUp): + project_class = define_hooks_logging_project._HooksLogOperationsProject + entrypoint = dict( + path=os.path.realpath( + os.path.join(os.path.dirname(__file__), "define_hooks_logging_project.py") + ) + ) + + ON_START_MSG = "Operation '{}' started." + SUCCESS_MSG = "Operation '{}' finished without exception." + EXCEPTION_MSG = "Operation '{}' failed with error" + + @staticmethod + def get_log_filename(): + return "operations.log" + + @staticmethod + def get_log_output(job, log_filename): + return "".join(line for line in open(job.fn(log_filename))) + + @pytest.fixture(params=["base", "base_cmd"]) + def operation_name(self, request): + return request.param + + @pytest.fixture + def error_message(operation_name): + if operation_name == "base": + return define_hooks_logging_project.HOOKS_ERROR_MESSAGE + return "42" + + def test_logging(self, project, job, operation_name, error_message): + log_fn = self.get_log_filename() + assert not job.isfile(log_fn) + + if job.sp.raise_exception: + with pytest.raises(subprocess.CalledProcessError): + self.call_subcmd(f"run -o {operation_name} -j {job.id}") + else: + self.call_subcmd(f"run -o {operation_name} -j {job.id}") + assert job.isfile(log_fn) + log_output = self.get_log_output(job, log_fn) + assert self.ON_START_MSG.format(operation_name) in log_output + if job.sp.raise_exception: + assert error_message in log_output + assert self.EXCEPTION_MSG.format(operation_name) in log_output + else: + assert error_message not in log_output + assert self.SUCCESS_MSG.format(operation_name) in log_output + + +class TestHooksLogInstall(TestHooksLog): + entrypoint = dict( + path=os.path.realpath( + os.path.join(os.path.dirname(__file__), "define_hooks_logging_install.py") + ) + ) + + class TestIgnoreConditions: def test_str(self): expected_results = {