From f4f5cb7a4f7be8727b4430c13d0b1d841a63fb14 Mon Sep 17 00:00:00 2001 From: Kelly Wang Date: Tue, 2 Aug 2022 12:03:33 -0400 Subject: [PATCH 01/35] Added log operations. --- flow/hooks/log_operations.py | 57 ++++++++++++++++++++++++++++++++++++ 1 file changed, 57 insertions(+) create mode 100644 flow/hooks/log_operations.py diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py new file mode 100644 index 000000000..d8690f0d8 --- /dev/null +++ b/flow/hooks/log_operations.py @@ -0,0 +1,57 @@ +# Copyright (c) 2018 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 basic information about the execution of operations to a log file. + + #TODO: Add detail + + Parameters + ---------- + fn_logfile: log filename + #TODO. + Default is ".operations.logs" + """ + + def __init__(self, fn_logfile=".operations.log"): + self._fn_logfile = fn_logfile + self._loggers = dict() + + def log_operation(self, operation, error=None): + """Add user-defined job operation to logger.""" + if str(operation.job) in self._loggers: + logger = self._loggers[str(operation.job)] + else: + logger = self._loggers[str(operation.job)] = logging.getLogger( + str(operation.job) + ) + logger.setLevel(logging.DEBUG) + + fh = logging.FileHandler(operation.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) + + if error is None: + logger.info(f"Executed operation '{operation}'.") + else: + logger.info( + "Execution of operation '{}' failed with " + "error '{}'.".format(operation, error) + ) + + def install_hooks(self, project): + """Install log operation to all operations in a signac project.""" + project.hooks.on_success.append(self.log_operation) + project.hooks.on_exception.append(self.log_operation) + return project + + __call__ = install_hooks From 3999fe3629981bd8c816792bfdeed445413aef62 Mon Sep 17 00:00:00 2001 From: Kelly Wang Date: Tue, 2 Aug 2022 12:17:09 -0400 Subject: [PATCH 02/35] Added LogOperations to __init__ --- flow/hooks/__init__.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) 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"] From 8e4d9897ee56c53d191a495d1c9c221ed8fb0b36 Mon Sep 17 00:00:00 2001 From: Kelly Wang Date: Tue, 2 Aug 2022 18:30:36 -0400 Subject: [PATCH 03/35] Added tests for LogOperations. --- flow/hooks/log_operations.py | 34 ++++++--- tests/test_project.py | 135 +++++++++++++++++++++++++++++++++++ 2 files changed, 160 insertions(+), 9 deletions(-) diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index d8690f0d8..5832628f0 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -21,17 +21,33 @@ def __init__(self, fn_logfile=".operations.log"): self._fn_logfile = fn_logfile self._loggers = dict() - def log_operation(self, operation, error=None): - """Add user-defined job operation to logger.""" - if str(operation.job) in self._loggers: - logger = self._loggers[str(operation.job)] + def log_operation(self, operation, job): + """TODO: Add user-defined job operation to logger.""" + if str(job) in self._loggers: + logger = self._loggers[str(job)] else: - logger = self._loggers[str(operation.job)] = logging.getLogger( - str(operation.job) + logger = self._loggers[str(job)] = logging.getLogger(str(job)) + logger.setLevel(logging.DEBUG) + + 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) + logger.info(f"Executed operation '{operation}'.") + + def log_operation_on_exception(self, operation, error, job): + """TODO: Add user-defined job operation to logger.""" + if str(job) in self._loggers: + logger = self._loggers[str(job)] + else: + logger = self._loggers[str(job)] = logging.getLogger(str(job)) logger.setLevel(logging.DEBUG) - fh = logging.FileHandler(operation.job.fn(self._fn_logfile)) + fh = logging.FileHandler(job.fn(self._fn_logfile)) fh.setLevel(logging.DEBUG) formatter = logging.Formatter( "%(asctime)s - %(name)s - %(levelname)s - %(message)s" @@ -50,8 +66,8 @@ def log_operation(self, operation, error=None): def install_hooks(self, project): """Install log operation to all operations in a signac project.""" - project.hooks.on_success.append(self.log_operation) - project.hooks.on_exception.append(self.log_operation) + project.project_hooks.on_success.append(self.log_operation) + project.project_hooks.on_exception.append(self.log_operation_on_exception) return project __call__ = install_hooks diff --git a/tests/test_project.py b/tests/test_project.py index 3c4e0bccf..c70a9bec3 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 pytest import signac @@ -2560,6 +2561,140 @@ def test_raise_exception_in_hook_cmd(self): assert "RuntimeError" in error_output +class TestHooksLogOperationSetUp(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") + ) + ) + + @staticmethod + def get_log_filename(operation_name, key): + return f"{operation_name}_{key}.log" + + @staticmethod + def get_log_output(job, log_filename): + return "".join(line for line in open(job.fn(log_filename))) + + +class TestHooksLogCmd(TestHooksLogOperationSetUp): + error_message = "42" + runtime_message = "" + + @pytest.fixture(params=["base_cmd"]) + def operation_name(self, request): + return request.param + + def test_success(self, project, job, operation_name): + log_fn = self.get_log_filename(operation_name, self.keys[2]) + + 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}") + + if job.sp.raise_exception: + assert not job.isfile(log_fn) + else: + assert job.isfile(log_fn) + log_output = self.get_log_output(job, log_fn) + assert self.runtime_message in log_output + assert f"Executed operation '{operation_name}'" in log_output + + def test_exception(self, project, job, operation_name): + log_fn = self.get_log_filename(operation_name, self.keys[3]) + + 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}") + + if job.sp.raise_exception: + assert job.isfile(log_fn) + log_output = self.get_log_output(job, log_fn) + assert self.error_message in log_output + assert ( + f"Execution of operation '{operation_name}' failed with" in log_output + ) + else: + assert not job.isfile(log_fn) + + +class TestHooksLogBase(TestHooksLogCmd): + error_message = define_hooks_logging_project.HOOKS_ERROR_MESSAGE + + @pytest.fixture(params=["base"]) + def operation_name(self, request): + return request.param + + def test_start(self, project, job, operation_name): + log_fn = self.get_log_filename(operation_name, self.keys[0]) + + 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.runtime_message in log_output + + if job.sp.raise_exception: + assert self.error_message in log_output + assert ( + f"Execution of operation '{operation_name}' failed with" in log_output + ) + else: + assert self.error_message not in log_output + assert f"Executed operation '{operation_name}'" in log_output + + +class TestHooksLogInstall(TestHooksLogOperationSetUp): + entrypoint = dict( + path=os.path.realpath( + os.path.join(os.path.dirname(__file__), "define_hooks_logging_install.py") + ) + ) + + def test_install(self, project, job): + log_fn = job.fn("operations.log") + + assert not job.isfile(log_fn) + + if job.sp.raise_exception: + with pytest.raises(subprocess.CalledProcessError): + self.call_subcmd(f"run -j {job.id} -o base") + with pytest.raises(subprocess.CalledProcessError): + self.call_subcmd(f"run -j {job.id} -o base_cmd") + else: + self.call_subcmd(f"run -j {job.id} -o base") + self.call_subcmd(f"run -j {job.id} -o base_cmd") + + assert job.isfile(log_fn) + log_output = self.get_log_output(job, log_fn) + + if job.sp.raise_exception: + assert "42" in log_output + assert define_hooks_logging_project.HOOKS_ERROR_MESSAGE in log_output + assert "Execution of operation 'base' failed with" in log_output + assert "Execution of operation 'base_cmd' failed with" in log_output + else: + assert "Executed operation 'base'" in log_output + assert "Executed operation 'base_cmd'" in log_output + + class TestIgnoreConditions: def test_str(self): expected_results = { From dfcf5ab6a8aea02fd300c747724f6563cc89cffa Mon Sep 17 00:00:00 2001 From: Kelly Wang Date: Tue, 2 Aug 2022 18:35:35 -0400 Subject: [PATCH 04/35] Added project definitions for log hook tests. --- tests/define_hooks_logging_install.py | 35 +++++++++++++++ tests/define_hooks_logging_project.py | 65 +++++++++++++++++++++++++++ 2 files changed, 100 insertions(+) create mode 100644 tests/define_hooks_logging_install.py create mode 100644 tests/define_hooks_logging_project.py diff --git a/tests/define_hooks_logging_install.py b/tests/define_hooks_logging_install.py new file mode 100644 index 000000000..c91e11eff --- /dev/null +++ b/tests/define_hooks_logging_install.py @@ -0,0 +1,35 @@ +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 +@flow.cmd +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_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..5859ca37d --- /dev/null +++ b/tests/define_hooks_logging_project.py @@ -0,0 +1,65 @@ +import logging + +from define_hooks_test_project import HOOKS_ERROR_MESSAGE + +import flow +from flow import FlowProject +from flow.hooks import LogOperations + +HOOKS_RUNTIME_MESSAGE = "Runtime message." + + +class _HooksLogOperationsProject(FlowProject): + pass + + +def log_operation(fn_log_file, trigger): + lo = LogOperations(fn_log_file).log_operation + return trigger(lambda operation, job: lo(operation, job)) + + +def log_operation_on_exception(fn_log_file): + lo = LogOperations(fn_log_file).log_operation_on_exception + return _HooksLogOperationsProject.operation_hooks.on_exception( + lambda operation, error, job: lo(operation, error, job) + ) + + +def set_logger(job): + logger = logging.getLogger(str(job)) + sh = logging.StreamHandler() + logger.addHandler(sh) + return logger + + +on_start = _HooksLogOperationsProject.operation_hooks.on_start +on_exit = _HooksLogOperationsProject.operation_hooks.on_exit +on_success = _HooksLogOperationsProject.operation_hooks.on_success + + +@_HooksLogOperationsProject.operation +@log_operation("base_start.log", on_start) +@log_operation("base_success.log", on_success) +@log_operation_on_exception("base_exception.log") +def base(job): + logger = set_logger(job) + + logger.info(HOOKS_RUNTIME_MESSAGE) + + if job.sp.raise_exception: + raise RuntimeError(HOOKS_ERROR_MESSAGE) + + +@_HooksLogOperationsProject.operation +@log_operation("base_cmd_success.log", on_success) +@log_operation_on_exception("base_cmd_exception.log") +@flow.cmd +def base_cmd(job): + if job.sp.raise_exception: + return "exit 42" + else: + return "touch base_cmd.txt" + + +if __name__ == "__main__": + _HooksLogOperationsProject().main() From 5f12826c453dc6f828dd5910708112e9da07eab2 Mon Sep 17 00:00:00 2001 From: Brandon Butler Date: Fri, 7 Oct 2022 12:16:38 -0400 Subject: [PATCH 05/35] refactor: LogHook rework the getting/setting up of loggers --- flow/hooks/log_operations.py | 50 +++++++++++++++--------------------- 1 file changed, 20 insertions(+), 30 deletions(-) diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index 5832628f0..fcb86cded 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -19,43 +19,33 @@ class LogOperations: def __init__(self, fn_logfile=".operations.log"): self._fn_logfile = fn_logfile + # getLogger keep its own cache. This just serves to reduce the time spent setting up loggers + # by only doing it once. self._loggers = dict() def log_operation(self, operation, job): """TODO: Add user-defined job operation to logger.""" - if str(job) in self._loggers: - logger = self._loggers[str(job)] - else: - logger = self._loggers[str(job)] = logging.getLogger(str(job)) - logger.setLevel(logging.DEBUG) - - 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) - logger.info(f"Executed operation '{operation}'.") + self._get_logger(job).info(f"Executed operation '{operation}'.") + + 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(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 log_operation_on_exception(self, operation, error, job): """TODO: Add user-defined job operation to logger.""" - if str(job) in self._loggers: - logger = self._loggers[str(job)] - else: - logger = self._loggers[str(job)] = logging.getLogger(str(job)) - logger.setLevel(logging.DEBUG) - - 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) - + logger = self._get_logger(job) if error is None: logger.info(f"Executed operation '{operation}'.") else: From 3951e74b2461e0f9980a887c44460c085ca6658b Mon Sep 17 00:00:00 2001 From: Brandon Butler Date: Fri, 7 Oct 2022 15:29:12 -0400 Subject: [PATCH 06/35] doc: Fix pre-commit failure. --- flow/hooks/log_operations.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index fcb86cded..169b60b41 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -6,7 +6,7 @@ class LogOperations: - """:class:`~.LogOperations` logs basic information about the execution of operations to a log file. + """:class:`~.LogOperations` logs information about the execution of operations to a log file. #TODO: Add detail From b360a2f32a559d85dddf5e6dd60d140951e8f6c1 Mon Sep 17 00:00:00 2001 From: Brandon Butler Date: Mon, 10 Oct 2022 10:00:03 -0400 Subject: [PATCH 07/35] test: TestHooksInvalidOption.call_subcmd outputs error every time. --- tests/test_project.py | 15 ++++++++++++--- 1 file changed, 12 insertions(+), 3 deletions(-) diff --git a/tests/test_project.py b/tests/test_project.py index a40972228..02cee5105 100644 --- a/tests/test_project.py +++ b/tests/test_project.py @@ -2559,8 +2559,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)): @@ -2568,7 +2573,11 @@ def call_subcmd(self, subcmd, stderr=subprocess.STDOUT): with _switch_to_directory(self.project.root_directory()): 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): From ee84251ba396b668278f9a328252bffc61cf5cdd Mon Sep 17 00:00:00 2001 From: Brandon Butler Date: Mon, 10 Oct 2022 10:00:48 -0400 Subject: [PATCH 08/35] fix: stringify job before passing to logging.getLogger() --- flow/hooks/log_operations.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index 169b60b41..fbf92ca1a 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -33,7 +33,7 @@ def _get_logger(self, job): return self._loggers[job] def _setup_logger(self, job): - logger = logging.getLogger(job) + logger = logging.getLogger(str(job)) fh = logging.FileHandler(job.fn(self._fn_logfile)) fh.setLevel(logging.DEBUG) formatter = logging.Formatter( From f990244dad0de77c5460c2d2d8a5a995995752d4 Mon Sep 17 00:00:00 2001 From: Brandon Butler Date: Mon, 10 Oct 2022 11:19:17 -0400 Subject: [PATCH 09/35] refactor: Modify names of log functions for Log hook Names now match the names of the hook triggers. We also rename the install_hooks to specify that it installs hooks project wide. --- flow/hooks/log_operations.py | 40 +++++++++++++++++++----------------- 1 file changed, 21 insertions(+), 19 deletions(-) diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index fbf92ca1a..13167f17b 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -23,9 +23,21 @@ def __init__(self, fn_logfile=".operations.log"): # by only doing it once. self._loggers = dict() - def log_operation(self, operation, job): - """TODO: Add user-defined job operation to logger.""" - self._get_logger(job).info(f"Executed operation '{operation}'.") + def on_start(self, operation, job): + """Log the start of execution of a given job(s) operation pair.""" + self._get_logger(job).info(f"Starting execution of operation '{operation}'.") + + def on_success(self, operation, job): + """Log the successful completion of a given job(s) operation pair.""" + self._get_logger(job).info( + f"Successfully finished execution of operation '{operation}'." + ) + + 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"Execution of operation '{operation}' failed with error '{error}'." + ) def _get_logger(self, job): if job not in self._loggers: @@ -43,21 +55,11 @@ def _setup_logger(self, job): logger.addHandler(fh) return logger - def log_operation_on_exception(self, operation, error, job): - """TODO: Add user-defined job operation to logger.""" - logger = self._get_logger(job) - if error is None: - logger.info(f"Executed operation '{operation}'.") - else: - logger.info( - "Execution of operation '{}' failed with " - "error '{}'.".format(operation, error) - ) - - def install_hooks(self, project): - """Install log operation to all operations in a signac project.""" - project.project_hooks.on_success.append(self.log_operation) - project.project_hooks.on_exception.append(self.log_operation_on_exception) + def install_project_hooks(self, project): + """Install log operation to all operations in a signac-flow project.""" + 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 - __call__ = install_hooks + __call__ = install_project_hooks From d52d350cf54dfa79b800019df53043192fa75126 Mon Sep 17 00:00:00 2001 From: Brandon Butler Date: Mon, 10 Oct 2022 11:26:02 -0400 Subject: [PATCH 10/35] doc: Improve documentation of LogOperations hook --- flow/hooks/log_operations.py | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index 13167f17b..06f5d335d 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -8,13 +8,16 @@ class LogOperations: """:class:`~.LogOperations` logs information about the execution of operations to a log file. - #TODO: Add detail + This hooks provides information, optionally, 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. Parameters ---------- fn_logfile: log filename - #TODO. - Default is ".operations.logs" + The name of the log file in the job workspace. Default is ".operations.logs". """ def __init__(self, fn_logfile=".operations.log"): From 78264664f67b4440a233a191dbd11fae220f78d9 Mon Sep 17 00:00:00 2001 From: Brandon Butler Date: Mon, 10 Oct 2022 11:39:11 -0400 Subject: [PATCH 11/35] feat: Add helper method for operation level hooks --- flow/hooks/log_operations.py | 22 +++++++++++++++++++++- 1 file changed, 21 insertions(+), 1 deletion(-) diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index 06f5d335d..ee7d80fe1 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -58,8 +58,28 @@ def _setup_logger(self, job): logger.addHandler(fh) return logger + def install_operation_hooks(self, op, project_cls): + """Install log operation to one operation in a signac-flow project. + + Parameters + ---------- + op : function + An operation function to log. + project_cls : type + A subclass of `flow.FlowProject`. + """ + project_cls.operation.on_start(op, self.on_start) + project_cls.operation.on_success(op, self.on_success) + project_cls.operation.on_exception(op, self.on_exception) + def install_project_hooks(self, project): - """Install log operation to all operations in a signac-flow project.""" + """Install log operation to all operations in a signac-flow project. + + Parameters + ---------- + project : flow.FlowProject + The project to install project wide 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) From 5fca1ac535e3ee1cea2399d62fdc870ca6e84e33 Mon Sep 17 00:00:00 2001 From: Brandon Butler Date: Mon, 10 Oct 2022 11:40:26 -0400 Subject: [PATCH 12/35] refactor: Modify LogOperations base log filename --- flow/hooks/log_operations.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index ee7d80fe1..9e4a2f1e3 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -17,10 +17,10 @@ class LogOperations: Parameters ---------- fn_logfile: log filename - The name of the log file in the job workspace. Default is ".operations.logs". + The name of the log file in the job workspace. Default is "execution-record.log". """ - def __init__(self, fn_logfile=".operations.log"): + def __init__(self, fn_logfile="execution-record.log"): self._fn_logfile = fn_logfile # getLogger keep its own cache. This just serves to reduce the time spent setting up loggers # by only doing it once. From 1e97e2ba20c1ba7ea02e7a17927f4dbda10527a4 Mon Sep 17 00:00:00 2001 From: Brandon Butler Date: Mon, 10 Oct 2022 11:41:34 -0400 Subject: [PATCH 13/35] refactor: Remove __call__ method of LogOperation The call method is confusing as it only applies to projects but hooks can be project or operation wide. --- flow/hooks/log_operations.py | 2 -- 1 file changed, 2 deletions(-) diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index 9e4a2f1e3..8163b21ae 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -84,5 +84,3 @@ def install_project_hooks(self, project): project.project_hooks.on_success.append(self.on_success) project.project_hooks.on_exception.append(self.on_exception) return project - - __call__ = install_project_hooks From 8b619de4f33470b037085d6dfc62afc7fda3c986 Mon Sep 17 00:00:00 2001 From: Brandon Butler Date: Mon, 10 Oct 2022 13:36:20 -0400 Subject: [PATCH 14/35] fix: LogOperation.install_operation_hooks Allow for the correct passing of the project to install the hooks for. --- flow/hooks/log_operations.py | 18 +++++++++++------- 1 file changed, 11 insertions(+), 7 deletions(-) diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index 8163b21ae..de3c2f48d 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -58,19 +58,23 @@ def _setup_logger(self, job): logger.addHandler(fh) return logger - def install_operation_hooks(self, op, project_cls): - """Install log operation to one operation in a signac-flow project. + def install_operation_hooks(self, op, project_cls=None): + """Decorate operation to install log operation to one operation in a signac-flow project. Parameters ---------- - op : function - An operation function to log. + 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`. """ - project_cls.operation.on_start(op, self.on_start) - project_cls.operation.on_success(op, self.on_success) - project_cls.operation.on_exception(op, self.on_exception) + 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. From 66d2e6cea6fe9383f0e767686a523ea92678be53 Mon Sep 17 00:00:00 2001 From: Brandon Butler Date: Mon, 10 Oct 2022 13:37:25 -0400 Subject: [PATCH 15/35] test: Update tests to recent LogOperation updates --- tests/define_hooks_logging_install.py | 4 ++- tests/define_hooks_logging_project.py | 25 ++++------------ tests/test_project.py | 43 ++++++++++++++------------- 3 files changed, 30 insertions(+), 42 deletions(-) diff --git a/tests/define_hooks_logging_install.py b/tests/define_hooks_logging_install.py index c91e11eff..e6ec49847 100644 --- a/tests/define_hooks_logging_install.py +++ b/tests/define_hooks_logging_install.py @@ -32,4 +32,6 @@ def base_cmd(job): if __name__ == "__main__": - LogOperations("operations.log").install_hooks(_HooksLogOperationsProject()).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 index 5859ca37d..7aebca975 100644 --- a/tests/define_hooks_logging_project.py +++ b/tests/define_hooks_logging_project.py @@ -13,16 +13,7 @@ class _HooksLogOperationsProject(FlowProject): pass -def log_operation(fn_log_file, trigger): - lo = LogOperations(fn_log_file).log_operation - return trigger(lambda operation, job: lo(operation, job)) - - -def log_operation_on_exception(fn_log_file): - lo = LogOperations(fn_log_file).log_operation_on_exception - return _HooksLogOperationsProject.operation_hooks.on_exception( - lambda operation, error, job: lo(operation, error, job) - ) +operation_log = LogOperations("operations.log") def set_logger(job): @@ -32,15 +23,8 @@ def set_logger(job): return logger -on_start = _HooksLogOperationsProject.operation_hooks.on_start -on_exit = _HooksLogOperationsProject.operation_hooks.on_exit -on_success = _HooksLogOperationsProject.operation_hooks.on_success - - +@operation_log.install_operation_hooks(_HooksLogOperationsProject) @_HooksLogOperationsProject.operation -@log_operation("base_start.log", on_start) -@log_operation("base_success.log", on_success) -@log_operation_on_exception("base_exception.log") def base(job): logger = set_logger(job) @@ -50,9 +34,10 @@ def base(job): 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 -@log_operation("base_cmd_success.log", on_success) -@log_operation_on_exception("base_cmd_exception.log") @flow.cmd def base_cmd(job): if job.sp.raise_exception: diff --git a/tests/test_project.py b/tests/test_project.py index 02cee5105..23e777ddd 100644 --- a/tests/test_project.py +++ b/tests/test_project.py @@ -2404,7 +2404,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" @@ -2413,8 +2413,8 @@ def call_subcmd(self, subcmd, stderr=subprocess.DEVNULL): with _switch_to_directory(self.project.root_directory()): 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") @@ -2625,9 +2625,13 @@ class TestHooksLogOperationSetUp(TestHooksSetUp): ) ) + ON_START_MSG = "Starting execution of operation '{}'." + SUCCESS_MSG = "Successfully finished execution of operation '{}'." + EXCEPTION_MSG = "Execution of operation '{}' failed with error" + @staticmethod - def get_log_filename(operation_name, key): - return f"{operation_name}_{key}.log" + def get_log_filename(): + return "operations.log" @staticmethod def get_log_output(job, log_filename): @@ -2643,8 +2647,7 @@ def operation_name(self, request): return request.param def test_success(self, project, job, operation_name): - log_fn = self.get_log_filename(operation_name, self.keys[2]) - + log_fn = self.get_log_filename() assert not job.isfile(log_fn) if job.sp.raise_exception: @@ -2659,10 +2662,11 @@ def test_success(self, project, job, operation_name): assert job.isfile(log_fn) log_output = self.get_log_output(job, log_fn) assert self.runtime_message in log_output - assert f"Executed operation '{operation_name}'" in log_output + assert self.ON_START_MSG.format(operation_name) in log_output + assert self.SUCCESS_MSG.format(operation_name) in log_output def test_exception(self, project, job, operation_name): - log_fn = self.get_log_filename(operation_name, self.keys[3]) + log_fn = self.get_log_filename() assert not job.isfile(log_fn) @@ -2676,9 +2680,7 @@ def test_exception(self, project, job, operation_name): assert job.isfile(log_fn) log_output = self.get_log_output(job, log_fn) assert self.error_message in log_output - assert ( - f"Execution of operation '{operation_name}' failed with" in log_output - ) + assert self.EXCEPTION_MSG.format(operation_name) else: assert not job.isfile(log_fn) @@ -2691,7 +2693,7 @@ def operation_name(self, request): return request.param def test_start(self, project, job, operation_name): - log_fn = self.get_log_filename(operation_name, self.keys[0]) + log_fn = self.get_log_filename() assert not job.isfile(log_fn) @@ -2707,14 +2709,13 @@ def test_start(self, project, job, operation_name): assert self.runtime_message in log_output + assert self.ON_START_MSG.format(operation_name) in log_output if job.sp.raise_exception: assert self.error_message in log_output - assert ( - f"Execution of operation '{operation_name}' failed with" in log_output - ) + assert self.EXCEPTION_MSG.format(operation_name) else: assert self.error_message not in log_output - assert f"Executed operation '{operation_name}'" in log_output + assert self.SUCCESS_MSG.format(operation_name) in log_output class TestHooksLogInstall(TestHooksLogOperationSetUp): @@ -2744,11 +2745,11 @@ def test_install(self, project, job): if job.sp.raise_exception: assert "42" in log_output assert define_hooks_logging_project.HOOKS_ERROR_MESSAGE in log_output - assert "Execution of operation 'base' failed with" in log_output - assert "Execution of operation 'base_cmd' failed with" in log_output + assert self.EXCEPTION_MSG.format("base") in log_output + assert self.EXCEPTION_MSG.format("base_cmd") in log_output else: - assert "Executed operation 'base'" in log_output - assert "Executed operation 'base_cmd'" in log_output + assert self.SUCCESS_MSG.format("base") in log_output + assert self.SUCCESS_MSG.format("base_cmd") in log_output class TestIgnoreConditions: From 79b34e01689e26d50738721cb63e8d28c010b19e Mon Sep 17 00:00:00 2001 From: Brandon Butler Date: Tue, 11 Oct 2022 11:00:59 -0400 Subject: [PATCH 16/35] test: Fix faulty test's assumption on underlying project Assumes that we are using different log files in LogOperation tests. --- tests/test_project.py | 30 ++++++------------------------ 1 file changed, 6 insertions(+), 24 deletions(-) diff --git a/tests/test_project.py b/tests/test_project.py index 23e777ddd..0b52099d3 100644 --- a/tests/test_project.py +++ b/tests/test_project.py @@ -2646,7 +2646,7 @@ class TestHooksLogCmd(TestHooksLogOperationSetUp): def operation_name(self, request): return request.param - def test_success(self, project, job, operation_name): + def test_logging(self, project, job, operation_name): log_fn = self.get_log_filename() assert not job.isfile(log_fn) @@ -2656,33 +2656,15 @@ def test_success(self, project, job, operation_name): 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 not job.isfile(log_fn) - else: - assert job.isfile(log_fn) - log_output = self.get_log_output(job, log_fn) - assert self.runtime_message in log_output - assert self.ON_START_MSG.format(operation_name) in log_output - assert self.SUCCESS_MSG.format(operation_name) in log_output - - def test_exception(self, project, job, operation_name): - 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}") - - if job.sp.raise_exception: - assert job.isfile(log_fn) - log_output = self.get_log_output(job, log_fn) assert self.error_message in log_output assert self.EXCEPTION_MSG.format(operation_name) else: - assert not job.isfile(log_fn) + assert self.runtime_message in log_output + assert self.SUCCESS_MSG.format(operation_name) in log_output class TestHooksLogBase(TestHooksLogCmd): From 26a63e2b218411d19c74060b2735650873cc9466 Mon Sep 17 00:00:00 2001 From: Brandon Butler Date: Tue, 11 Oct 2022 12:39:04 -0400 Subject: [PATCH 17/35] ci: Update CircleCI --- .circleci/config.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.circleci/config.yml b/.circleci/config.yml index bae10eaa9..17f0b9fbf 100644 --- a/.circleci/config.yml +++ b/.circleci/config.yml @@ -5,7 +5,7 @@ version: 2.1 orbs: - codecov: codecov/codecov@3.2.2 + codecov: codecov/codecov@3.2.3 references: restore_keys: &restore_keys From 40f6dadea52c5307452b2d7d992e06ac4d109059 Mon Sep 17 00:00:00 2001 From: Kelly Wang Date: Tue, 24 Jan 2023 08:51:35 -0500 Subject: [PATCH 18/35] Added more detailed docstring. --- flow/hooks/hooks.py | 2 +- flow/hooks/log_operations.py | 10 ++++++++++ 2 files changed, 11 insertions(+), 1 deletion(-) diff --git a/flow/hooks/hooks.py b/flow/hooks/hooks.py index 9da269298..b3da8e7c8 100644 --- a/flow/hooks/hooks.py +++ b/flow/hooks/hooks.py @@ -29,7 +29,7 @@ class _Hooks: starts, succeeds, fails, or finishes (regardless of whether the operation executed successfully or failed). - Hooks can be installed at the operation level as decorators, or on an + Hooks can be installed at the operation level as decorators, or on instance of :class:`~.FlowProject` through :meth:`~.FlowProject.project_hooks`. diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index de3c2f48d..bfb73d688 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -14,6 +14,16 @@ class LogOperations: The default formating for the log provides the time, job id, log level, and log message. + Examples + -------- + The code block below provides an example of how install :class:`~.LogOperations` to a + instance of :class:`~.FlowProject` + + .. code-block:: python + from flow import FLowProject + from flow.hooks import LogOperations # Import build + + Parameters ---------- fn_logfile: log filename From 12916179234d3ecf6dc32c6195d0831cb2748d6d Mon Sep 17 00:00:00 2001 From: Kelly Wang Date: Tue, 24 Jan 2023 09:12:17 -0500 Subject: [PATCH 19/35] Updated hooks test setup with new signac-flow API --- tests/define_hooks_logging_install.py | 3 +-- tests/define_hooks_logging_project.py | 4 +--- 2 files changed, 2 insertions(+), 5 deletions(-) diff --git a/tests/define_hooks_logging_install.py b/tests/define_hooks_logging_install.py index e6ec49847..5b5197138 100644 --- a/tests/define_hooks_logging_install.py +++ b/tests/define_hooks_logging_install.py @@ -22,8 +22,7 @@ def base(job): raise RuntimeError(HOOKS_ERROR_MESSAGE) -@_HooksLogOperationsProject.operation -@flow.cmd +@_HooksLogOperationsProject.operation(cmd=True) def base_cmd(job): if job.sp.raise_exception: return "exit 42" diff --git a/tests/define_hooks_logging_project.py b/tests/define_hooks_logging_project.py index 7aebca975..0ce4febe5 100644 --- a/tests/define_hooks_logging_project.py +++ b/tests/define_hooks_logging_project.py @@ -2,7 +2,6 @@ from define_hooks_test_project import HOOKS_ERROR_MESSAGE -import flow from flow import FlowProject from flow.hooks import LogOperations @@ -37,8 +36,7 @@ def base(job): @_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 -@flow.cmd +@_HooksLogOperationsProject.operation(cmd=True) def base_cmd(job): if job.sp.raise_exception: return "exit 42" From 7e306cc0f8b6e3318ce81ba29415214de20fb9e1 Mon Sep 17 00:00:00 2001 From: Kelly Wang <47036428+klywang@users.noreply.github.com> Date: Fri, 27 Jan 2023 11:53:48 -0500 Subject: [PATCH 20/35] Update flow/hooks/log_operations.py Co-authored-by: Hardik Ojha <44747868+kidrahahjo@users.noreply.github.com> --- flow/hooks/log_operations.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index bfb73d688..92ac41027 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -34,7 +34,7 @@ def __init__(self, fn_logfile="execution-record.log"): self._fn_logfile = fn_logfile # getLogger keep its own cache. This just serves to reduce the time spent setting up loggers # by only doing it once. - self._loggers = dict() + self._loggers = {} def on_start(self, operation, job): """Log the start of execution of a given job(s) operation pair.""" From 3633ffa79ecc3cd5491ba277ad0a1223220d4936 Mon Sep 17 00:00:00 2001 From: Kelly Wang Date: Tue, 14 Feb 2023 15:46:06 -0500 Subject: [PATCH 21/35] Changed scamples to be consistent with new decorator evalutaion order. --- flow/hooks/hooks.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/flow/hooks/hooks.py b/flow/hooks/hooks.py index b3da8e7c8..95ad7dd7f 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 From 1646cdc9b562265ecb52c4d7a489441496f7df07 Mon Sep 17 00:00:00 2001 From: Kelly Wang Date: Tue, 14 Feb 2023 15:46:34 -0500 Subject: [PATCH 22/35] Finished docstring in example. --- flow/hooks/log_operations.py | 13 ++++++++++++- 1 file changed, 12 insertions(+), 1 deletion(-) diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index 92ac41027..9d5a718e3 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -20,10 +20,21 @@ class LogOperations: instance of :class:`~.FlowProject` .. code-block:: python - from flow import FLowProject + from flow import FlowProject from flow.hooks import LogOperations # Import build + class Project(FlowProject): + pass + + + # Do something + + + if __name__ == "__main__": + LogOperations.install_project_hooks(Project).main() + + Parameters ---------- fn_logfile: log filename From 467668ed7c479affa0710b4b5f48a677eab0eb0a Mon Sep 17 00:00:00 2001 From: Kelly Wang Date: Tue, 14 Feb 2023 15:49:17 -0500 Subject: [PATCH 23/35] Fixed example in LogOperations. --- flow/hooks/log_operations.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index 9d5a718e3..4db7582d6 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -32,7 +32,9 @@ class Project(FlowProject): if __name__ == "__main__": - LogOperations.install_project_hooks(Project).main() + project = Project() + project = LogOperations().install_hooks(project) + project.main() Parameters From 1f27e50b079faa04033e7e630dbae7b1c9b86249 Mon Sep 17 00:00:00 2001 From: Kelly Wang Date: Sun, 26 Feb 2023 14:37:50 -0500 Subject: [PATCH 24/35] Updated examples. --- flow/hooks/log_operations.py | 36 +++++++++++++++++++++++++++++++++++- 1 file changed, 35 insertions(+), 1 deletion(-) diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index 4db7582d6..4ffcd1d4b 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -14,8 +14,41 @@ class LogOperations: 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 `run_options=--debug` + and `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 workspace. + + .. 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={ + "run_options": "--debug", # Always run operation foo with the --debug flag + "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 a instance of :class:`~.FlowProject` @@ -33,10 +66,11 @@ class Project(FlowProject): if __name__ == "__main__": project = Project() - project = LogOperations().install_hooks(project) + project = LogOperations().install_project_hooks(project) project.main() + Parameters ---------- fn_logfile: log filename From 7f0ddad0bf856729ee6d0feaeadee3169d10d198 Mon Sep 17 00:00:00 2001 From: Kelly Wang Date: Sun, 26 Feb 2023 14:41:10 -0500 Subject: [PATCH 25/35] Updated example so tha trun opertions was not included. Did not work when I tested the example. --- flow/hooks/log_operations.py | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index 4ffcd1d4b..a711ac767 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -17,8 +17,8 @@ class LogOperations: .. 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 `run_options=--debug` - and `submit_options=--debug` in your directives (example shown below). + use the `--debug` flag when running or submitting jobs, or specify + `submit_options=--debug` in your directives (example shown below). Examples @@ -42,7 +42,6 @@ def install_operation_log_hook(operation_name, project_cls): @install_operation_log_hook("foo", Project) @Project.operation(directives={ - "run_options": "--debug", # Always run operation foo with the --debug flag "submit_options": "--debug" # Always submit operation foo with the --debug flag }) def foo(job): From 0452d88a9788c5f1f6c059fc31b663617e99648d Mon Sep 17 00:00:00 2001 From: Kelly Wang <47036428+klywang@users.noreply.github.com> Date: Fri, 7 Jul 2023 12:14:33 -0400 Subject: [PATCH 26/35] Apply suggestions from code review Co-authored-by: Bradley Dice --- flow/hooks/hooks.py | 2 +- flow/hooks/log_operations.py | 18 ++++++++---------- 2 files changed, 9 insertions(+), 11 deletions(-) diff --git a/flow/hooks/hooks.py b/flow/hooks/hooks.py index 95ad7dd7f..3765bc4c8 100644 --- a/flow/hooks/hooks.py +++ b/flow/hooks/hooks.py @@ -29,7 +29,7 @@ class _Hooks: starts, succeeds, fails, or finishes (regardless of whether the operation executed successfully or failed). - Hooks can be installed at the operation level as decorators, or on + Hooks can be installed at the operation level as decorators, or on an instance of :class:`~.FlowProject` through :meth:`~.FlowProject.project_hooks`. diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index a711ac767..d56712e16 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -1,4 +1,4 @@ -# Copyright (c) 2018 The Regents of the University of Michigan +# 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.""" @@ -8,7 +8,7 @@ class LogOperations: """:class:`~.LogOperations` logs information about the execution of operations to a log file. - This hooks provides information, optionally, on the start, successful completion, and/or + 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. @@ -48,7 +48,7 @@ def foo(job): pass - The code block below provides an example of how install :class:`~.LogOperations` to a + The code block below provides an example of how install :class:`~.LogOperations` to an instance of :class:`~.FlowProject` .. code-block:: python @@ -68,22 +68,20 @@ class Project(FlowProject): project = LogOperations().install_project_hooks(project) project.main() - - Parameters ---------- - fn_logfile: log filename + fn_logfile : str The name of the log file in the job workspace. Default is "execution-record.log". """ def __init__(self, fn_logfile="execution-record.log"): self._fn_logfile = fn_logfile - # getLogger keep its own cache. This just serves to reduce the time spent setting up loggers + # 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 a given job(s) operation pair.""" + """Log the start of execution of an operation on a job.""" self._get_logger(job).info(f"Starting execution of operation '{operation}'.") def on_success(self, operation, job): @@ -115,7 +113,7 @@ def _setup_logger(self, job): return logger def install_operation_hooks(self, op, project_cls=None): - """Decorate operation to install log operation to one operation in a signac-flow project. + """Decorate operation to log execution. Parameters ---------- @@ -138,7 +136,7 @@ def install_project_hooks(self, project): Parameters ---------- project : flow.FlowProject - The project to install project wide hooks on. + The project to install hooks on. """ project.project_hooks.on_start.append(self.on_start) project.project_hooks.on_success.append(self.on_success) From fb3bb26a5f81d90147de66bde4bba9247b6c6eff Mon Sep 17 00:00:00 2001 From: "dependabot[bot]" <49699333+dependabot[bot]@users.noreply.github.com> Date: Sat, 1 Jul 2023 17:07:28 -0400 Subject: [PATCH 27/35] Build(deps-dev): Bump pre-commit from 3.3.2 to 3.3.3 (#756) Bumps [pre-commit](https://github.com/pre-commit/pre-commit) from 3.3.2 to 3.3.3. - [Release notes](https://github.com/pre-commit/pre-commit/releases) - [Changelog](https://github.com/pre-commit/pre-commit/blob/main/CHANGELOG.md) - [Commits](https://github.com/pre-commit/pre-commit/compare/v3.3.2...v3.3.3) --- updated-dependencies: - dependency-name: pre-commit dependency-type: direct:development update-type: version-update:semver-patch ... Signed-off-by: dependabot[bot] Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> --- requirements/requirements-dev.txt | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/requirements/requirements-dev.txt b/requirements/requirements-dev.txt index 57291c19d..7ed570488 100644 --- a/requirements/requirements-dev.txt +++ b/requirements/requirements-dev.txt @@ -1,3 +1,3 @@ click>=7.0 ruamel.yaml>=0.16.12 -pre-commit==3.3.2 +pre-commit==3.3.3 From ea627fee6fb9f027e65bb545a5594a7aed1c693a Mon Sep 17 00:00:00 2001 From: "dependabot[bot]" <49699333+dependabot[bot]@users.noreply.github.com> Date: Mon, 3 Jul 2023 10:29:12 -0400 Subject: [PATCH 28/35] Build(deps): Bump ruamel-yaml from 0.17.31 to 0.17.32 (#755) Bumps [ruamel-yaml](https://sourceforge.net/p/ruamel-yaml/code/ci/default/tree) from 0.17.31 to 0.17.32. --- updated-dependencies: - dependency-name: ruamel-yaml dependency-type: direct:production update-type: version-update:semver-patch ... Signed-off-by: dependabot[bot] Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> --- requirements/requirements-test.txt | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/requirements/requirements-test.txt b/requirements/requirements-test.txt index 4b279be1c..7153da753 100644 --- a/requirements/requirements-test.txt +++ b/requirements/requirements-test.txt @@ -2,4 +2,4 @@ click==8.1.3 coverage==7.2.7 pytest-cov==4.1.0 pytest==7.3.1 -ruamel.yaml==0.17.31 +ruamel.yaml==0.17.32 From 670dd2590c9d4b07322dfc6e8dac0f81b75292fd Mon Sep 17 00:00:00 2001 From: "dependabot[bot]" <49699333+dependabot[bot]@users.noreply.github.com> Date: Mon, 3 Jul 2023 11:23:20 -0400 Subject: [PATCH 29/35] Build(deps): Bump pytest from 7.3.1 to 7.4.0 (#754) Bumps [pytest](https://github.com/pytest-dev/pytest) from 7.3.1 to 7.4.0. - [Release notes](https://github.com/pytest-dev/pytest/releases) - [Changelog](https://github.com/pytest-dev/pytest/blob/main/CHANGELOG.rst) - [Commits](https://github.com/pytest-dev/pytest/compare/7.3.1...7.4.0) --- updated-dependencies: - dependency-name: pytest dependency-type: direct:production update-type: version-update:semver-minor ... Signed-off-by: dependabot[bot] Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com> --- requirements/requirements-test.txt | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/requirements/requirements-test.txt b/requirements/requirements-test.txt index 7153da753..c41b9b990 100644 --- a/requirements/requirements-test.txt +++ b/requirements/requirements-test.txt @@ -1,5 +1,5 @@ click==8.1.3 coverage==7.2.7 pytest-cov==4.1.0 -pytest==7.3.1 +pytest==7.4.0 ruamel.yaml==0.17.32 From e19256bcc98294eb7e3b812b8b3a06fd81241eaf Mon Sep 17 00:00:00 2001 From: "pre-commit-ci[bot]" <66853113+pre-commit-ci[bot]@users.noreply.github.com> Date: Mon, 3 Jul 2023 23:17:22 -0800 Subject: [PATCH 30/35] [pre-commit.ci] pre-commit autoupdate (#757) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit updates: - [github.com/asottile/pyupgrade: v3.3.1 → v3.8.0](https://github.com/asottile/pyupgrade/compare/v3.3.1...v3.8.0) Co-authored-by: pre-commit-ci[bot] <66853113+pre-commit-ci[bot]@users.noreply.github.com> --- .pre-commit-config.yaml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index b574d4e44..2ace0946a 100644 --- a/.pre-commit-config.yaml +++ b/.pre-commit-config.yaml @@ -11,7 +11,7 @@ repos: - id: trailing-whitespace - id: debug-statements - repo: https://github.com/asottile/pyupgrade - rev: 'v3.3.1' + rev: 'v3.8.0' hooks: - id: pyupgrade args: From 1debcb9e797e7c7865b3582748be38b019d09e55 Mon Sep 17 00:00:00 2001 From: Kelly Wang Date: Fri, 7 Jul 2023 12:45:04 -0400 Subject: [PATCH 31/35] Modified log strings for consistency. --- flow/hooks/log_operations.py | 6 +++--- tests/test_project.py | 8 ++++---- 2 files changed, 7 insertions(+), 7 deletions(-) diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index d56712e16..9d04381e4 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -82,18 +82,18 @@ def __init__(self, fn_logfile="execution-record.log"): def on_start(self, operation, job): """Log the start of execution of an operation on a job.""" - self._get_logger(job).info(f"Starting execution of operation '{operation}'.") + 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"Successfully finished execution of operation '{operation}'." + 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"Execution of operation '{operation}' failed with error '{error}'." + f"Operation '{operation}' failed with error '{error}'." ) def _get_logger(self, job): diff --git a/tests/test_project.py b/tests/test_project.py index 64d879d1a..49c78e86f 100644 --- a/tests/test_project.py +++ b/tests/test_project.py @@ -2529,9 +2529,9 @@ class TestHooksLogOperationSetUp(TestHooksSetUp): ) ) - ON_START_MSG = "Starting execution of operation '{}'." - SUCCESS_MSG = "Successfully finished execution of operation '{}'." - EXCEPTION_MSG = "Execution of operation '{}' failed with error" + ON_START_MSG = "Operation '{}' started." + SUCCESS_MSG = "Operation '{}' finished without exception." + EXCEPTION_MSG = "Operation '{}' failed with error" @staticmethod def get_log_filename(): @@ -2565,7 +2565,7 @@ def test_logging(self, project, job, operation_name): assert self.ON_START_MSG.format(operation_name) in log_output if job.sp.raise_exception: assert self.error_message in log_output - assert self.EXCEPTION_MSG.format(operation_name) + assert self.EXCEPTION_MSG.format(operation_name) in log_output else: assert self.runtime_message in log_output assert self.SUCCESS_MSG.format(operation_name) in log_output From 7b9182732acce29654dc6ef92c1c1ca9de5308f4 Mon Sep 17 00:00:00 2001 From: Kelly Wang Date: Fri, 7 Jul 2023 12:47:14 -0400 Subject: [PATCH 32/35] Comment clarity and shorter default log name. --- flow/hooks/log_operations.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index 9d04381e4..ec472ae7e 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -60,7 +60,7 @@ class Project(FlowProject): pass - # Do something + # Project operation definitions if __name__ == "__main__": @@ -71,10 +71,10 @@ class Project(FlowProject): Parameters ---------- fn_logfile : str - The name of the log file in the job workspace. Default is "execution-record.log". + The name of the log file in the job workspace. Default is "operations.log". """ - def __init__(self, fn_logfile="execution-record.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. From 8b448fc8210582426f74588f8b378ea9d89c4256 Mon Sep 17 00:00:00 2001 From: Kelly Wang Date: Fri, 7 Jul 2023 12:52:19 -0400 Subject: [PATCH 33/35] Update job workspace to job directory. --- flow/hooks/log_operations.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/flow/hooks/log_operations.py b/flow/hooks/log_operations.py index ec472ae7e..ffdfa2235 100644 --- a/flow/hooks/log_operations.py +++ b/flow/hooks/log_operations.py @@ -24,7 +24,7 @@ class LogOperations: 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 workspace. + Where the log will be stored in a file name `foo.log` in the job directory. .. code-block:: python from flow import FlowProject @@ -71,7 +71,7 @@ class Project(FlowProject): Parameters ---------- fn_logfile : str - The name of the log file in the job workspace. Default is "operations.log". + The name of the log file in the job directory. Default is "operations.log". """ def __init__(self, fn_logfile="operations.log"): From 1f3229fd54f20a549cfc712747e74e2ab37b1baa Mon Sep 17 00:00:00 2001 From: Kelly Wang Date: Fri, 7 Jul 2023 12:55:28 -0400 Subject: [PATCH 34/35] Updated changelog. --- changelog.txt | 1 + 1 file changed, 1 insertion(+) diff --git a/changelog.txt b/changelog.txt index d11f2857f..dc08249db 100644 --- a/changelog.txt +++ b/changelog.txt @@ -17,6 +17,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 +++++++ From 672726bb930ad1cd851d363a238c3fe9f51df5b5 Mon Sep 17 00:00:00 2001 From: Brandon Butler Date: Fri, 13 Oct 2023 10:48:40 -0400 Subject: [PATCH 35/35] test: Refactor hook test into single template --- tests/test_project.py | 83 +++++++------------------------------------ 1 file changed, 12 insertions(+), 71 deletions(-) diff --git a/tests/test_project.py b/tests/test_project.py index 49c78e86f..159fb4271 100644 --- a/tests/test_project.py +++ b/tests/test_project.py @@ -2521,7 +2521,7 @@ def test_raise_exception_in_hook_cmd(self): assert "RuntimeError" in error_output -class TestHooksLogOperationSetUp(TestHooksSetUp): +class TestHooksLog(TestHooksSetUp): project_class = define_hooks_logging_project._HooksLogOperationsProject entrypoint = dict( path=os.path.realpath( @@ -2541,46 +2541,18 @@ def get_log_filename(): def get_log_output(job, log_filename): return "".join(line for line in open(job.fn(log_filename))) - -class TestHooksLogCmd(TestHooksLogOperationSetUp): - error_message = "42" - runtime_message = "" - - @pytest.fixture(params=["base_cmd"]) + @pytest.fixture(params=["base", "base_cmd"]) def operation_name(self, request): return request.param - def test_logging(self, project, job, operation_name): - 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}") + @pytest.fixture + def error_message(operation_name): + if operation_name == "base": + return define_hooks_logging_project.HOOKS_ERROR_MESSAGE + return "42" - 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 self.error_message in log_output - assert self.EXCEPTION_MSG.format(operation_name) in log_output - else: - assert self.runtime_message in log_output - assert self.SUCCESS_MSG.format(operation_name) in log_output - - -class TestHooksLogBase(TestHooksLogCmd): - error_message = define_hooks_logging_project.HOOKS_ERROR_MESSAGE - - @pytest.fixture(params=["base"]) - def operation_name(self, request): - return request.param - - def test_start(self, project, job, operation_name): + 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: @@ -2588,55 +2560,24 @@ def test_start(self, project, job, operation_name): 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.runtime_message in log_output - assert self.ON_START_MSG.format(operation_name) in log_output if job.sp.raise_exception: - assert self.error_message in log_output - assert self.EXCEPTION_MSG.format(operation_name) + assert error_message in log_output + assert self.EXCEPTION_MSG.format(operation_name) in log_output else: - assert self.error_message not in log_output + assert error_message not in log_output assert self.SUCCESS_MSG.format(operation_name) in log_output -class TestHooksLogInstall(TestHooksLogOperationSetUp): +class TestHooksLogInstall(TestHooksLog): entrypoint = dict( path=os.path.realpath( os.path.join(os.path.dirname(__file__), "define_hooks_logging_install.py") ) ) - def test_install(self, project, job): - log_fn = job.fn("operations.log") - - assert not job.isfile(log_fn) - - if job.sp.raise_exception: - with pytest.raises(subprocess.CalledProcessError): - self.call_subcmd(f"run -j {job.id} -o base") - with pytest.raises(subprocess.CalledProcessError): - self.call_subcmd(f"run -j {job.id} -o base_cmd") - else: - self.call_subcmd(f"run -j {job.id} -o base") - self.call_subcmd(f"run -j {job.id} -o base_cmd") - - assert job.isfile(log_fn) - log_output = self.get_log_output(job, log_fn) - - if job.sp.raise_exception: - assert "42" in log_output - assert define_hooks_logging_project.HOOKS_ERROR_MESSAGE in log_output - assert self.EXCEPTION_MSG.format("base") in log_output - assert self.EXCEPTION_MSG.format("base_cmd") in log_output - else: - assert self.SUCCESS_MSG.format("base") in log_output - assert self.SUCCESS_MSG.format("base_cmd") in log_output - class TestIgnoreConditions: def test_str(self):