Merge pull request #1275 from victorusu/bug/RFC3339Formatter

[bugfix] Fix logging crash when increasing verbosity level

Author: Vasileios Karakasis

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.

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_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,6 +419,7 @@ def __init__(self, logger=None, check=None):
                 'check_name': 'reframe',
                 'check_jobid': '-1',
                 'check_job_completion_time': None,
+                'check_job_completion_time_unix': 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_completion_time_unix'] = ct
 
     def log_performance(self, level, tag, value, ref,
                         low_thres, upper_thres, unit=None, *, msg=None):

unittests/test_cli.py

@@ -473,6 +473,16 @@ 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 '--- Logging error ---' not in 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