Feature: Add LogOperations to execution hooks

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"]

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`.
 

flow/hooks/log_operations.py

@@ -0,0 +1,100 @@
+# 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 information about the execution of operations to a log file.
+
+    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.
+
+    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
+        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
+        # by only doing it once.
+        self._loggers = dict()
+
+    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:
+            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 install log operation to one operation in a signac-flow project.
+
+        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 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)
+        return project

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()

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()

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
@@ -2233,7 +2234,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"
@@ -2242,8 +2243,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")
@@ -2388,16 +2389,25 @@ 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)):
             try:
                 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):
@@ -2437,6 +2447,123 @@ 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")
+        )
+    )
+
+    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():
+        return "operations.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_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}")
+
+        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)
+        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):
+        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.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)
+        else:
+            assert self.error_message not in log_output
+            assert self.SUCCESS_MSG.format(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 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):
         expected_results = {