Feature/hooks track operation

.github/workflows/ci-oldest-reqs.txt

@@ -8,3 +8,4 @@ pytest-cov==3.0.0
 pytest==7.0.1
 ruamel.yaml==0.17.21
 tqdm==4.60.0
+GitPython==3.1.37

flow/hooks/track_operations.py

@@ -8,38 +8,59 @@
 
 try:
     from .git_util import collect_git_metadata
 except ImportError:
     GIT = False
 else:
     GIT = True
 
 
+_DEFAULT_FILENAME = "signac-execution-history.log"
+
+
 class TrackOperations:
     """:class:`~.TrackOperations` tracks information about the execution of operations to a logfile.
 
-    This hooks can provides information on the start, successful completion, and/or erroring of
-    one or more operations in a `flow.FlowProject` instance. The logs are stored either in the
-    job document or the file given by ``log_filename``. If stored in the job document, it uses
-    the key ``execution_history``. The file or document list will be appended to if it already
+    This hook can provides information on the start, successful completion, and/or error of
+    one or more operations in a :class:`~.FlowProject` instance. The logs are stored in the file
+    given by ``log_filename`` within the job's path. The file  will be appended to if it already
     exists.
 
     The hooks stores metadata regarding the execution of the operation and the state of the
     project at the time of execution, error, and/or completion. The data will also include
     information about the git status if the project is detected as a git repo and
     ``GitPython`` is installed in the environment.
 
+    Each call to the hook adds a single JSON line to the log file. These can be
+    read using the `json` builtin package or :meth:`~.TrackOperations.read_log`.
+
+    The current schema has the following structure:
+
+    - ``time``: The time of querying the metadata.
+    - ``stage``: Whether the hook was executed either "prior" or "after" the associated
+      operation's execution.
+    - ``error``: The error message on executing the operation if any.
+    - ``project``
+       - ``path``: Filepath to the project
+       - ``schema_version``: The project's schema version
+    - ``operation``: The operation name
+    - ``job_id``: The job id
+    - ``git``
+       - ``commit_id``: The current commit of the project's git repo.
+       - ``dirty``: Whether the project's repo has uncommitted changes or not.
+    - ``_schema_version``: The metadata storage's schema version. Schema is currently in version 1.
+
+
     Warning
     -------
-    This class will error on construction if GitPython is not available and ``strict_git`` is set
-    to ``True``. If ``strict_git`` is ``True`` trying to execute an operation with uncommitted
-    changes.
+    This class will raise an exception when strict_git is set to ``True`` and either GitPython is
+    not available or the repository contains uncommitted changes (i.e. is "dirty").
 
     Examples
     --------
     The following example will install :class:`~.TrackOperations` at the operation level.
-    Where the log will be stored in the job document.
 
     .. code-block:: python
+
         from flow import FlowProject
         from flow.hooks import TrackOperations
 
@@ -61,6 +82,7 @@
     instance of :class:`~.FlowProject`
 
     .. code-block:: python
+
         from flow import FlowProject
         from flow.hooks import TrackOperations
 
@@ -77,19 +99,17 @@
 
     Parameters
     ----------
-    log_filename: str, optional
-        The name of the log file in the job workspace. If ``None`` store in a list in the job
-        document in a key labeled ``f"{operation_name}"`` under the ``"execution_history"`` key.
-        Defaults to ``None``.
-    strict_git: bool, optional
+    log_filename : str, optional
+        The name of the log file in the job workspace. Defaults to "signac-execution-history.log".
+    strict_git : bool, optional
         Whether to fail if ``GitPython`` cannot be imported or if there are uncommitted changes
         to the project's git repo. Defaults to ``True``.
     """
 
-    def __init__(self, log_filename=None, strict_git=True):
+    def __init__(self, log_filename=_DEFAULT_FILENAME, strict_git=True):
         self.log_filename = log_filename
         if strict_git and not GIT:
             raise RuntimeError(
                 "Unable to collect git metadata from the repository, "
                 "because the GitPython package is not installed.\n\n"
                 "You can use '{}(strict_git=False)' to ignore this "
@@ -98,13 +118,6 @@
         self.strict_git = strict_git
 
     def _write_metadata(self, job, metadata):
-        print(f"Writing... {metadata}.", flush=True)
-        if self.log_filename is None:
-            history = job.doc.setdefault("execution_history", {})
-            # No need to store job id or operation name.
-            operation_name = metadata.pop("job-operation")["name"]
-            history.setdefault(operation_name, []).append(metadata)
-            return
         with open(job.fn(self.log_filename), "a") as logfile:
             logfile.write(json.dumps(metadata) + "\n")
 
@@ -146,10 +159,10 @@
         Parameters
         ----------
         op : function or type
-            An operation function to log or a subclass of `flow.FlowProject` if ``project_cls`` is
-            ``None``.
+            An operation function to log or a subclass of :class:`~.FlowProject` if
+            ``project_cls`` is ``None``.
         project_cls : type
-            A subclass of `flow.FlowProject`.
+            A subclass of :class:`~.FlowProject`.
         """
         if project_cls is None:
             return lambda func: self.install_operation_hooks(func, op)
@@ -170,3 +183,23 @@
         project.project_hooks.on_success.append(self.on_success)
         project.project_hooks.on_exception.append(self.on_exception)
         return project
+
+    @classmethod
+    def read_log(cls, job, log_filename=_DEFAULT_FILENAME):
+        """Return the execution log data as a list of dictionaries.
+
+        Parameters
+        ----------
+        job : signac.job.Job
+            The job to read the execution history of.
+        log_filename : str, optional
+            The name of the log file in the job workspace. Defaults to
+            "signac-execution-history.log".
+
+        Returns
+        -------
+        log : list[dict[str, any]]
+            Returns the job's current execution history for logged operations.
+        """
+        with open(job.fn(log_filename)) as fh:
+            return [json.loads(line) for line in fh.readlines() if line != ""]

flow/hooks/util.py

@@ -10,12 +10,6 @@ def collect_metadata(operation, job):
 
     Returns a directory including schema version, time, project, and job-operation.
 
-    We can no longer track the following because we take in the operation name as a string rather
-    than as an object, but they provide useful information. We could try to perform introspection
-    of the project through the job later if desired to get these values.
-
-    - "cmd": operation.cmd,
-    - "directives": operation.directives,
     """
     return {
         # the metadata schema version:
@@ -26,8 +20,6 @@ def collect_metadata(operation, job):
             # the project schema version:
             "schema_version": job.project.config.get("schema_version"),
         },
-        "job-operation": {
-            "name": operation,
-            "job_id": job.id,
-        },
+        "operation": operation,
+        "job_id": job.id,
     }

tests/define_hooks_track_operations_project.py

@@ -8,22 +8,19 @@ class _HooksTrackOperations(FlowProject):
     pass
 
 
-LOG_FILENAME = "operations.log"
+LOG_FILENAME = "signac-execution-history.log"
 
 
 track_operations = TrackOperations(strict_git=False)
-track_operations_with_file = TrackOperations(LOG_FILENAME, strict_git=False)
 
 
-@track_operations_with_file.install_operation_hooks(_HooksTrackOperations)
 @track_operations.install_operation_hooks(_HooksTrackOperations)
 @_HooksTrackOperations.operation
 def base(job):
     if job.sp.raise_exception:
         raise RuntimeError(HOOKS_ERROR_MESSAGE)
 
 
-@track_operations_with_file.install_operation_hooks(_HooksTrackOperations)
 @track_operations.install_operation_hooks(_HooksTrackOperations)
 @_HooksTrackOperations.operation(cmd=True, with_job=True)
 def cmd(job):

tests/define_hooks_track_operations_strict_project.py

@@ -12,19 +12,16 @@ class _HooksTrackOperations(FlowProject):
 
 
 track_operations = TrackOperations()
-track_operations_with_file = TrackOperations(LOG_FILENAME)
 
 
 @track_operations.install_operation_hooks(_HooksTrackOperations)
-@track_operations_with_file.install_operation_hooks(_HooksTrackOperations)
 @_HooksTrackOperations.operation
 def base(job):
     if job.sp.raise_exception:
         raise RuntimeError(HOOKS_ERROR_MESSAGE)
 
 
 @track_operations.install_operation_hooks(_HooksTrackOperations)
-@track_operations_with_file.install_operation_hooks(_HooksTrackOperations)
 @_HooksTrackOperations.operation(cmd=True, with_job=True)
 def cmd(job):
     if job.sp.raise_exception:

tests/test_project.py

@@ -2,20 +2,21 @@
 # All rights reserved.
 # This software is licensed under the BSD 3-Clause License.
 import datetime
-import json
 import logging
 import os
+import platform
 import subprocess
 import sys
 from contextlib import contextmanager, redirect_stderr, redirect_stdout
 from functools import partial
 from io import StringIO
 from itertools import groupby
-from pathlib import Path
 
 import define_hooks_test_project
 import define_hooks_track_operations_project
+import define_hooks_track_operations_strict_project
 import define_status_test_project
+import git
 import pytest
 import signac
 from conftest import MockScheduler, TestProjectBase
@@ -42,17 +43,6 @@
     _switch_to_directory,
 )
 
-try:
-    import define_hooks_track_operations_strict_project
-    import git
-
-    skip_git = False
-except RuntimeError:
-    skip_git = True
-
-
-git_mark_skipif = pytest.mark.skipif(skip_git, reason="git could not be imported")
-
 
 @contextmanager
 def suspend_logging():
@@ -2600,10 +2590,7 @@ class TestHooksTrackOperationsNotStrict(TestHooksSetUp):
     def operation_info(self, request):
         return request.param
 
-    @pytest.fixture(
-        params=None if skip_git else (True, False),
-        ids=None if skip_git else ("git-dirty", "git-clean"),
-    )
+    @pytest.fixture(params=(True, False), ids=("git-dirty", "git-clean"))
     def git_repo(self, project, request):
         # params=None is equivalent to not passing a parameter which results in
         # result.param being unset.
@@ -2620,25 +2607,11 @@ def git_repo(self, project, request):
             repo.index.add(["dirty.txt"])
         return repo
 
-    def split_log(self, job, fn):
-        with open(job.fn(fn)) as f:
-            values = f.read().split("\n")
-        if values[-1] == "":
-            values = values[:-1]
-        return values
-
-    def get_log(self, job, fn=None):
-        if fn is None:
-            execution_history = job.doc["execution_history"]()
-            # Add back in redundent information to make check_metadata universal
-            for key, item in execution_history.items():
-                for entry in item:
-                    entry["job-operation"] = {"name": key, "job_id": job.id}
-            return execution_history
-        log_entries = [json.loads(entry) for entry in self.split_log(job, fn)]
+    def get_log(self, job):
+        log_entries = flow.hooks.TrackOperations.read_log(job)
         execution_history = {}
         for entry in log_entries:
-            operation_name = entry["job-operation"]["name"]
+            operation_name = entry["operation"]
             execution_history.setdefault(operation_name, []).append(entry)
         return execution_history
 
@@ -2653,40 +2626,35 @@ def check_metadata(
         repo,
     ):
         assert metadata["stage"] == expected_stage
-        # When running on MacOS CI a private/ is prepended to job.project.path
-        # seemingly indeterminetly. If metadata["project"]["path"] is checked
-        # then job.project.path will have "private" in it. If I check
-        # job.project.path then metadata["project"]["path"] will have "private"
-        # in it. If I check neither, one of them will have "private" in it.
-        test_path = os.path.join(
-            *filter(lambda x: x != "private", Path(metadata["project"]["path"]).parts)
-        )
-        current_path = os.path.join(
-            *filter(lambda x: x != "private", Path(job.project.path).parts)
-        )
-        assert current_path == test_path
+
+        test_path = metadata["project"]["path"]
+        current_path = job.project.path
+        # Still allow for local MacOS check but skip in CI MacOS runners. Rather
+        # than xfail or skip this ensures we test everything else.
+        if (
+            "private" in test_path
+            or "private" in current_path
+            and platform.system == "Darwin"
+        ):
+            pass
+        else:
+            assert current_path == test_path
         assert metadata["project"]["schema_version"] == job.project.config.get(
             "schema_version"
         )
         start_time = datetime.datetime.fromisoformat(metadata["time"])
         assert before_execution < start_time
-        job_op_metadata = metadata["job-operation"]
-        assert job_op_metadata["job_id"] == job.id
-        assert job_op_metadata["name"] == operation_name
+        assert metadata["job_id"] == job.id
+        assert metadata["operation"] == operation_name
 
         if expected_stage != "prior" and job.sp.raise_exception:
             assert error_message in metadata["error"]
 
         else:
             assert metadata["error"] is None
 
-        if repo is not None:
-            assert metadata["project"]["git"]["commit_id"] == str(repo.commit())
-            assert metadata["project"]["git"]["dirty"] == repo.is_dirty()
-        else:
-            if self.error_on_no_git:
-                # Should not happen in actual testing, here for developers.
-                assert False, "Expected gitpython for test."
+        assert metadata["project"]["git"]["commit_id"] == str(repo.commit())
+        assert metadata["project"]["git"]["dirty"] == repo.is_dirty()
 
     def test_metadata(self, project, job, operation_info, git_repo):
         operation_name, error_message = operation_info
@@ -2705,7 +2673,7 @@ def test_metadata(self, project, job, operation_info, git_repo):
 
         assert job.isfile(self.log_fname)
         for filename in (None, self.log_fname):
-            metadata = self.get_log(job, filename)
+            metadata = self.get_log(job)
             # For the single operation
             # Each metadata whether file or document is one since they both
             # write to different places.
@@ -2732,21 +2700,17 @@ def test_metadata(self, project, job, operation_info, git_repo):
                 )
 
 
-if not skip_git:
-
-    class TestHooksTrackOperationsStrict(TestHooksTrackOperationsNotStrict):
-        project_class = (
-            define_hooks_track_operations_strict_project._HooksTrackOperations
-        )
-        entrypoint = dict(
-            path=os.path.realpath(
-                os.path.join(
-                    os.path.dirname(__file__),
-                    "define_hooks_track_operations_strict_project.py",
-                )
+class TestHooksTrackOperationsStrict(TestHooksTrackOperationsNotStrict):
+    project_class = define_hooks_track_operations_strict_project._HooksTrackOperations
+    entrypoint = dict(
+        path=os.path.realpath(
+            os.path.join(
+                os.path.dirname(__file__),
+                "define_hooks_track_operations_strict_project.py",
             )
         )
-        error_on_no_git = True
+    )
+    error_on_no_git = True
 
 
 class TestIgnoreConditions: