Merge pull request #184 from SCM-NV/DavidOrmrodMorley/log_job_status_…

…changes

Add job status logging to job logger csv SCMSUITE-10132 SO107

core/basejob.py

@@ -2,9 +2,10 @@
 import os
 import stat
 import threading
+import datetime
 import time
 from os.path import join as opj
-from typing import TYPE_CHECKING, Dict, Generator, Iterable, List, Optional, Union
+from typing import TYPE_CHECKING, Dict, Generator, Iterable, List, Optional, Union, Tuple
 from abc import ABC, abstractmethod
 import traceback
 
@@ -94,6 +95,7 @@ def __init__(
     ):
         if os.path.sep in name:
             raise PlamsError("Job name cannot contain {}".format(os.path.sep))
+        self._status_log: List[Tuple[datetime.datetime, str]] = []
         self.status = JobStatus.CREATED
         self.results = self.__class__._result_type(self)
         self.name = name
@@ -135,6 +137,15 @@ def status(self, value: JobStatusType) -> None:
         # This setter should really be private i.e. internally should use self._status
         # But for backwards compatibility it is exposed and set by e.g. the JobManager
         self._status = value
+        self._status_log.append((datetime.datetime.now(), str(value)))
+
+    @property
+    def status_log(self) -> List[Tuple[datetime.datetime, str]]:
+        """
+        Log of the status changes of the job, in chronological order.
+        Each entry in the list consists of a timestamp and the set status.
+        """
+        return self._status_log
 
     def run(
         self, jobrunner: Optional["JobRunner"] = None, jobmanager: Optional["JobManager"] = None, **kwargs

core/formatters.py

@@ -29,6 +29,7 @@ def _format_job(job: Job) -> Dict[str, Any]:
             "job_ok": "",
             "job_check": "",
             "job_get_errormsg": "",
+            "job_timeline": str.join(" -> ", [f"{dt.strftime('%Y-%m-%d %H:%M:%S')} {s}" for dt, s in job.status_log]),
             "job_parent_name": "",
             "job_parent_path": "",
         }

unit_tests/test_basejob.py

@@ -6,6 +6,7 @@
 import shutil
 import re
 from io import StringIO
+import csv
 
 from scm.plams.core.settings import Settings
 from scm.plams.core.basejob import SingleJob, MultiJob
@@ -357,23 +358,46 @@ def test_job_summaries_logged(self, config):
         job2.run(jobmanager=job_manager)
         job3.run(jobmanager=job_manager)
 
+        dt_fmt = "\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}"
+
+        def assert_csv_entry(entry, statuses, postfix="", ok="True", check="True", error_msg=""):
+            assert re.match(dt_fmt, entry[0])
+            assert entry[1] == "plamsjob"
+            assert entry[2] == f"plamsjob{postfix}"
+            assert entry[3] == statuses[-1]
+            assert entry[4].endswith(f"plamsjob{postfix}")
+            assert entry[5] == ok
+            assert entry[6] == check
+            assert error_msg in entry[7]
+            status_pattern = str.join(" -> ", [rf"{dt_fmt} {s}" for s in statuses])
+            assert re.match(status_pattern, entry[8])
+
         with open(job_manager.job_logger.logfile) as f:
-            assert (
-                f.readline()
-                == """logged_at,job_base_name,job_name,job_status,job_path,job_ok,job_check,job_get_errormsg,job_parent_name,job_parent_path
-"""
-            )
+            reader = csv.reader(f)
+
+            assert next(reader) == [
+                "logged_at",
+                "job_base_name",
+                "job_name",
+                "job_status",
+                "job_path",
+                "job_ok",
+                "job_check",
+                "job_get_errormsg",
+                "job_timeline",
+                "job_parent_name",
+                "job_parent_path",
+            ]
 
-            assert (
-                re.match(r"^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},plamsjob,plamsjob,successful", f.readline()) is not None
-            )
-            assert (
-                re.match(r"^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},plamsjob,plamsjob\.002,copied", f.readline())
-                is not None
-            )
-            assert (
-                re.match(r"^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},plamsjob,plamsjob\.003,crashed", f.readline())
-                is not None
+            assert_csv_entry(next(reader), ["created", "started", "registered", "running", "finished", "successful"])
+            assert_csv_entry(next(reader), ["created", "started", "registered", "copied"], postfix=".002")
+            assert_csv_entry(
+                next(reader),
+                ["created", "started", "registered", "running", "crashed"],
+                postfix=".003",
+                error_msg="not_a_cmd",
+                ok="False",
+                check="False",
             )
 
         job_manager.job_logger.close()

unit_tests/test_logging.py

@@ -1,3 +1,4 @@
+import csv
 import os.path
 import re
 import uuid
@@ -562,54 +563,62 @@ def test_log_cannot_change_field_names_or_add_fields(self):
             logger.close()
 
     def test_log_correctly_escapes_commas_and_multiline_strings(self):
-        with patch("sys.stdout", new_callable=StringIO) as mock_stdout:
-            name = str(uuid.uuid4())
-            logger = get_logger(name, "csv")
-            logger.configure(3)
+        with temp_file_path(suffix=".csv") as temp_log_file:
+            with patch("sys.stdout", new_callable=StringIO) as mock_stdout:
+                name = str(uuid.uuid4())
+                logger = get_logger(name, "csv")
+                logger.configure(3, 3, temp_log_file)
 
-            logger.log(
-                {
-                    "commas": "a,b,c,'(d,e,f)'",
-                    "multi-line": """See the following:
+                logger.log(
+                    {
+                        "commas": "a,b,c,'(d,e,f)'",
+                        "multi-line": """See the following:
     a,b,c
     d,e,f
 """,
-                },
-                3,
-            )
-            logger.log(
-                {
-                    "commas": 'm,"n,",,,o\'',
-                    "multi-line": """See the following:
+                    },
+                    3,
+                )
+                logger.log(
+                    {
+                        "commas": 'm,"n,",,,o\'',
+                        "multi-line": """See the following:
     m,n,o
 
     p,q,r
 """,
-                },
-                3,
-            )
+                    },
+                    3,
+                )
 
-        assert mock_stdout.getvalue() == (
-            """commas,multi-line
-"a,b,c,\'(d,e,f)\'","See the following:
+            assert mock_stdout.getvalue() == (
+                """commas,multi-line
+"a,b,c,'(d,e,f)'","See the following:
     a,b,c
     d,e,f
 "
-"m,""n,"",,,o\'","See the following:
+"m,""n,"",,,o'","See the following:
     m,n,o
 
     p,q,r
 "
 """
-        )
+            )
 
-        logger.close()
+            with open(temp_log_file) as tf:
+                reader = csv.reader(tf)
+
+                assert next(reader) == ["commas", "multi-line"]
+                assert next(reader) == ["a,b,c,'(d,e,f)'", "See the following:\n    a,b,c\n    d,e,f\n"]
+                assert next(reader) == ['m,"n,",,,o\'', "See the following:\n    m,n,o\n\n    p,q,r\n"]
+
+            logger.close()
 
 
 class TestJobCSVFormatter:
 
     def test_formatter_populates_job_fields(self):
-        with temp_file_path(suffix=".log") as temp_log_file:
+        with temp_file_path(suffix=".csv") as temp_log_file:
 
             job1 = DummySingleJob(name="test_job_csv_formatter")
             job2 = DummySingleJob(name="test_job_csv_formatter.002", cmd="err")
@@ -636,14 +645,29 @@ def get_errormsg():
             path2 = os.path.join(dir, "plams_workdir", "test_job_csv_formatter.002")
 
             with open(temp_log_file) as tf:
+                reader = csv.reader(tf)
+
+                # Read csv and regularise timestamps for easier comparison
+                def read_row():
+                    row = next(reader)
+                    row[7] = re.sub(r"\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}", "<timestamp>", row[7])
+                    return str.join(",", row)
+
                 assert (
-                    tf.read()
-                    == f"""job_base_name,job_name,job_status,job_path,job_ok,job_check,job_get_errormsg,job_parent_name,job_parent_path
-test_job_csv_formatter,test_job_csv_formatter,created,,,,,,
-test_job_csv_formatter,test_job_csv_formatter.002,created,,,,,,
-test_job_csv_formatter,test_job_csv_formatter,successful,{path1},True,True,,,
-test_job_csv_formatter,test_job_csv_formatter.002,crashed,{path2},False,False,some error,,
-"""
+                    read_row()
+                    == "job_base_name,job_name,job_status,job_path,job_ok,job_check,job_get_errormsg,job_timeline,job_parent_name,job_parent_path"
+                )
+                assert read_row() == "test_job_csv_formatter,test_job_csv_formatter,created,,,,,<timestamp> created,,"
+                assert (
+                    read_row() == "test_job_csv_formatter,test_job_csv_formatter.002,created,,,,,<timestamp> created,,"
+                )
+                assert (
+                    read_row()
+                    == f"test_job_csv_formatter,test_job_csv_formatter,successful,{path1},True,True,,<timestamp> created -> <timestamp> started -> <timestamp> registered -> <timestamp> running -> <timestamp> finished -> <timestamp> successful,,"
+                )
+                assert (
+                    read_row()
+                    == f"test_job_csv_formatter,test_job_csv_formatter.002,crashed,{path2},False,False,some error,<timestamp> created -> <timestamp> started -> <timestamp> registered -> <timestamp> running -> <timestamp> crashed,,"
                 )
 
             logger.close()