Treat properly deferrables

- As well as format `None` and errors in a human-readable manner.

Author: Vasileios Karakasis

reframe/core/logging.py

@@ -165,6 +165,17 @@ def _format_time_rfc3339(timestamp, datefmt):
 
 
 def _xfmt(val):
+    from reframe.core.deferrable import _DeferredExpression
+
+    if val is None:
+        return '<undefined>'
+
+    if isinstance(val, _DeferredExpression):
+        try:
+            return val.evaluate()
+        except BaseException:
+            return '<error>'
+
     if isinstance(val, str):
         return val
 
@@ -222,7 +233,7 @@ def formatTime(self, record, datefmt=None):
 
     def format(self, record):
         datefmt = self.datefmt or self.default_time_format
-        if record.check_job_completion_time_unix is not None:
+        if record.check_job_completion_time_unix != _xfmt(None):
             ct = self.converter(record.check_job_completion_time_unix)
             record.check_job_completion_time = _format_time_rfc3339(
                 ct, datefmt
@@ -437,21 +448,21 @@ def __init__(self, logger=None, check=None):
                 # Here we only set the format specifiers that do not
                 # correspond directly to check attributes
                 'check': check,
-                'check_jobid': '-1',
-                'check_job_completion_time': None,
-                'check_job_completion_time_unix': None,
+                'check_jobid': _xfmt(None),
+                'check_job_completion_time': _xfmt(None),
+                'check_job_completion_time_unix': _xfmt(None),
                 'check_info': 'reframe',
-                'check_system': None,
-                'check_partition': None,
-                'check_environ': None,
-                'check_perf_var': None,
-                'check_perf_value': None,
-                'check_perf_ref': None,
-                'check_perf_lower_thres': None,
-                'check_perf_upper_thres': None,
-                'check_perf_unit': None,
-                'osuser':  osext.osuser()  or '<unknown>',
-                'osgroup': osext.osgroup() or '<unknown>',
+                'check_system': _xfmt(None),
+                'check_partition': _xfmt(None),
+                'check_environ': _xfmt(None),
+                'check_perf_var': _xfmt(None),
+                'check_perf_value': _xfmt(None),
+                'check_perf_ref': _xfmt(None),
+                'check_perf_lower_thres': _xfmt(None),
+                'check_perf_upper_thres': _xfmt(None),
+                'check_perf_unit': _xfmt(None),
+                'osuser':  _xfmt(osext.osuser()),
+                'osgroup': _xfmt(osext.osgroup()),
                 'version': osext.reframe_version(),
             }
         )

unittests/test_logging.py

@@ -19,6 +19,7 @@
 import reframe.core.runtime as rt
 import reframe.core.settings as settings
 import reframe.utility as util
+import reframe.utility.sanity as sn
 from reframe.core.exceptions import ConfigError, ReframeError
 from reframe.core.backends import (getlauncher, getscheduler)
 from reframe.core.schedulers import Job
@@ -29,6 +30,10 @@ def fake_check():
     class _FakeCheck(rfm.RegressionTest):
         pass
 
+    @sn.sanity_function
+    def error():
+        raise BaseException
+
     # A bit hacky, but we don't want to run a full test every time
     test = _FakeCheck()
     test._job = Job.create(getscheduler('local')(),
@@ -38,6 +43,8 @@ class _FakeCheck(rfm.RegressionTest):
     test.custom = 'hello extras'
     test.custom_list = ['custom', 'attr']
     test.custom_dict = {'a': 1, 'b': 2}
+    test.deferred = sn.defer('hello')
+    test.deferred_error = error()
     return test
 
 
@@ -156,10 +163,19 @@ def test_logger_dynamic_attributes(logfile, logger_with_check):
     logger_with_check.logger.handlers[0].setFormatter(formatter)
     logger_with_check.info('xxx')
     assert _pattern_in_logfile(
-        r'hello extras\|custom,attr\|None\|a=1,b=2', logfile
+        r'hello extras\|custom,attr\|<undefined>\|a=1,b=2', logfile
     )
 
 
+def test_logger_dynamic_attributes_deferrables(logfile, logger_with_check):
+    formatter = rlog.RFC3339Formatter(
+        '%(check_deferred)s|%(check_deferred_error)s'
+    )
+    logger_with_check.logger.handlers[0].setFormatter(formatter)
+    logger_with_check.info('xxx')
+    assert _pattern_in_logfile(r'hello\|<error>', logfile)
+
+
 def test_rfc3339_timezone_extension(logfile, logger_with_check,
                                     logger_without_check):
     formatter = rlog.RFC3339Formatter(