From c81baf29a156d83fe3c3d8702bb93ddd796ff089 Mon Sep 17 00:00:00 2001 From: David Ormrod Morley Date: Thu, 12 Dec 2024 12:29:27 +0100 Subject: [PATCH] Add job status logging to job logger csv SCMSUITE-10132 SO107 --- core/basejob.py | 13 +++++- core/formatters.py | 1 + unit_tests/test_basejob.py | 54 ++++++++++++++++------- unit_tests/test_logging.py | 88 ++++++++++++++++++++++++-------------- 4 files changed, 108 insertions(+), 48 deletions(-) diff --git a/core/basejob.py b/core/basejob.py index fef4a864..7498d553 100644 --- a/core/basejob.py +++ b/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 diff --git a/core/formatters.py b/core/formatters.py index 0a7abef6..44d880be 100644 --- a/core/formatters.py +++ b/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": "", } diff --git a/unit_tests/test_basejob.py b/unit_tests/test_basejob.py index e9911e55..aeb72c4a 100644 --- a/unit_tests/test_basejob.py +++ b/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() diff --git a/unit_tests/test_logging.py b/unit_tests/test_logging.py index fe3b7fc1..066c1ac5 100644 --- a/unit_tests/test_logging.py +++ b/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}", "", 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,,,,, created,," + assert ( + read_row() == "test_job_csv_formatter,test_job_csv_formatter.002,created,,,,, created,," + ) + assert ( + read_row() + == f"test_job_csv_formatter,test_job_csv_formatter,successful,{path1},True,True,, created -> started -> registered -> running -> finished -> successful,," + ) + assert ( + read_row() + == f"test_job_csv_formatter,test_job_csv_formatter.002,crashed,{path2},False,False,some error, created -> started -> registered -> running -> crashed,," ) logger.close()