From b848006c824d27ff4c3899b50fea481c95e5f88b Mon Sep 17 00:00:00 2001 From: Victor Holanda Rusu Date: Thu, 23 Apr 2020 11:31:22 +0200 Subject: [PATCH 1/4] Fix string conversion in the RFC3339Formatter Fixes #1261 Fixes #1265 --- reframe/core/logging.py | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 102549b52e..2c4b29f022 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -175,8 +175,8 @@ def formatTime(self, record, datefmt=None): def format(self, record): datefmt = self.datefmt or self.default_time_format - if record.check_job_completion_time is not None: - ct = self.converter(record.check_job_completion_time) + if record.check_job_unix_completion_time is not None: + ct = self.converter(record.check_job_unix_completion_time) record.check_job_completion_time = _format_time_rfc3339( ct, datefmt ) @@ -419,6 +419,7 @@ def __init__(self, logger=None, check=None): 'check_name': 'reframe', 'check_jobid': '-1', 'check_job_completion_time': None, + 'check_job_unix_completion_time': None, 'check_info': 'reframe', 'check_system': None, 'check_partition': None, @@ -480,7 +481,7 @@ def _update_check_extras(self): self.extra['check_jobid'] = self.check.job.jobid if self.check.job.completion_time: ct = self.check.job.completion_time - self.extra['check_job_completion_time'] = ct + self.extra['check_job_unix_completion_time'] = ct def log_performance(self, level, tag, value, ref, low_thres, upper_thres, unit=None, *, msg=None): From 143c48ac6bda19833227761ec8059efe26fb8ee8 Mon Sep 17 00:00:00 2001 From: Victor Holanda Rusu Date: Tue, 28 Apr 2020 13:06:28 +0200 Subject: [PATCH 2/4] Address PR remarks --- reframe/core/logging.py | 8 ++++---- unittests/test_cli.py | 9 +++++++++ 2 files changed, 13 insertions(+), 4 deletions(-) diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 2c4b29f022..b8b1aa9fb1 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -175,8 +175,8 @@ def formatTime(self, record, datefmt=None): def format(self, record): datefmt = self.datefmt or self.default_time_format - if record.check_job_unix_completion_time is not None: - ct = self.converter(record.check_job_unix_completion_time) + if record.check_job_completion_time_unix is not None: + ct = self.converter(record.check_job_completion_time_unix) record.check_job_completion_time = _format_time_rfc3339( ct, datefmt ) @@ -419,7 +419,7 @@ def __init__(self, logger=None, check=None): 'check_name': 'reframe', 'check_jobid': '-1', 'check_job_completion_time': None, - 'check_job_unix_completion_time': None, + 'check_job_completion_time_unix': None, 'check_info': 'reframe', 'check_system': None, 'check_partition': None, @@ -481,7 +481,7 @@ def _update_check_extras(self): self.extra['check_jobid'] = self.check.job.jobid if self.check.job.completion_time: ct = self.check.job.completion_time - self.extra['check_job_unix_completion_time'] = ct + self.extra['check_job_completion_time_unix'] = ct def log_performance(self, level, tag, value, ref, low_thres, upper_thres, unit=None, *, msg=None): diff --git a/unittests/test_cli.py b/unittests/test_cli.py index 96285b4dbb..b220afdf41 100644 --- a/unittests/test_cli.py +++ b/unittests/test_cli.py @@ -473,6 +473,15 @@ def test_verbosity(self): assert 'Traceback' not in stderr assert 0 == returncode + def test_verbosity_with_check(self): + self.more_options = ['-vvvvv'] + self.checkpath = ['unittests/resources/checks/hellocheck.py'] + returncode, stdout, stderr = self._run_reframe() + assert '' != stdout + assert 'Traceback' not in stdout + assert 'Traceback' not in stderr + assert 0 == returncode + @fixtures.switch_to_user_runtime def test_unload_module(self): # This test is mostly for ensuring coverage. `_run_reframe()` restores From 6eb8b07e7e69305e4ee8cf0f4c573b724b941066 Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Tue, 28 Apr 2020 14:17:10 +0200 Subject: [PATCH 3/4] Additional assertion in verbosity unit tests --- unittests/test_cli.py | 1 + 1 file changed, 1 insertion(+) diff --git a/unittests/test_cli.py b/unittests/test_cli.py index b220afdf41..e700e252e4 100644 --- a/unittests/test_cli.py +++ b/unittests/test_cli.py @@ -478,6 +478,7 @@ def test_verbosity_with_check(self): self.checkpath = ['unittests/resources/checks/hellocheck.py'] returncode, stdout, stderr = self._run_reframe() assert '' != stdout + assert '--- Logging error ---' not in stdout assert 'Traceback' not in stdout assert 'Traceback' not in stderr assert 0 == returncode From c3e8ad1e3b96af9f705766fa73f4c70ef30c8ed1 Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Tue, 28 Apr 2020 14:51:06 +0200 Subject: [PATCH 4/4] Document the `check_job_completion_time_unix` log record attribute --- docs/running.rst | 3 +++ 1 file changed, 3 insertions(+) diff --git a/docs/running.rst b/docs/running.rst index 03fe08b650..0fe0e3e27c 100644 --- a/docs/running.rst +++ b/docs/running.rst @@ -862,6 +862,9 @@ All handlers accept the following set of attributes (keys) in their configuratio In this case, the accuracy depends on the execution policy used. If tests are executed with the serial execution policy, this is close to the real completion time, but if the asynchronous execution policy is used, it can differ significantly. If the job completion time cannot be retrieved, ``None`` will be printed. + - ``check_job_completion_time_unix``: *[new in 3.0]* The completion time of the job spawned by this regression test expressed as UNIX time. + This is a raw time field and will not be formatted according to ``datefmt``. + If specific formatting is desired, the ``check_job_completion_time`` should be used instead. - ``check_name``: Prints the name of the regression test on behalf of which ReFrame is currently executing. If ReFrame is not in the context of regression test, ``reframe`` will be printed. - ``check_num_tasks``: The number of tasks assigned to the regression test.