Merge pull request #1600 from rsarm/feat/logging

[feat] Allow any test attribute to be logged

Author: Vasileios Karakasis

docs/config_reference.rst

@@ -695,12 +695,8 @@ All logging handlers share the following set of common attributes:
      If specific formatting is desired, the ``check_job_completion_time`` should be used instead.
    - ``%(check_name)s``: The name of the regression test on behalf of which ReFrame is currently executing.
      If ReFrame is not executing in the context of a regression test, ``reframe`` will be printed instead.
-   - ``%(check_num_tasks)s``: The number of tasks assigned to the regression test.
-   - ``%(check_outputdir)s``: The output directory associated with the currently executing test.
    - ``%(check_partition)s``: The system partition where this test is currently executing.
-   - ``%(check_stagedir)s``: The stage directory associated with the currently executing test.
    - ``%(check_system)s``: The system where this test is currently executing.
-   - ``%(check_tags)s``: The tags associated with this test.
    - ``%(check_perf_lower_thres)s``: The lower threshold of the performance difference from the reference value expressed as a fractional value.
      See the :attr:`reframe.core.pipeline.RegressionTest.reference` attribute of regression tests for more details.
    - ``%(check_perf_ref)s``: The reference performance value of a certain performance variable.
@@ -709,11 +705,20 @@ All logging handlers share the following set of common attributes:
      See the :attr:`reframe.core.pipeline.RegressionTest.reference` attribute of regression tests for more details.
    - ``%(check_perf_value)s``: The performance value obtained for a certain performance variable.
    - ``%(check_perf_var)s``: The name of the `performance variable <tutorial_basic.html#writing-a-performance-test>`__ being logged.
+   - ``%(check_ATTR)s``: This will log the value of the attribute ``ATTR`` of the currently executing regression test.
+     Mappings will be logged as ``k1=v1,k2=v2,..`` and all other iterables, except strings, will be logged as comma-separated lists.
+     If ``ATTR`` is not an attribute of the test, ``%(check_ATTR)s`` will be logged as ``<undefined>``.
+     This allows users to log arbitrary attributes of their tests.
+     For the complete list of test attributes, please refer to :doc:`regression_test_api`.
    - ``%(osuser)s``: The name of the OS user running ReFrame.
    - ``%(osgroup)s``: The name of the OS group running ReFrame.
    - ``%(version)s``: The ReFrame version.
 
 
+.. versionadded:: 3.3
+   The ability to log arbitrary test attributes was added.
+
+
 .. js:attribute:: .logging[].handlers[].datefmt
 
 .. object:: .logging[].handlers_perflog[].datefmt

reframe/core/logging.py

@@ -9,7 +9,6 @@
 import logging.handlers
 import numbers
 import os
-import pprint
 import re
 import shutil
 import sys
@@ -145,7 +144,7 @@ def emit(self, record):
         except OSError as e:
             raise LoggingError('logging failed') from e
 
-        self.baseFilename = os.path.join(dirname, record.check_name + '.log')
+        self.baseFilename = os.path.join(dirname, record.check.name + '.log')
         self.stream = self._streams.get(self.baseFilename, None)
         super().emit(record)
         self._streams[self.baseFilename] = self.stream
@@ -165,7 +164,65 @@ def _format_time_rfc3339(timestamp, datefmt):
     return re.sub(r'(%)?\:z', tz_rfc3339, time.strftime(datefmt, timestamp))
 
 
-class RFC3339Formatter(logging.Formatter):
+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
+
+    if isinstance(val, collections.abc.Mapping):
+        return ','.join(f'{k}={v}' for k, v in val.items())
+
+    if isinstance(val, collections.abc.Iterable):
+        return ','.join(val)
+
+    return val
+
+
+class CheckFieldFormatter(logging.Formatter):
+    '''Log formatter that dynamically looks up format specifiers inside a
+    regression test.'''
+
+    def __init__(self, fmt=None, datefmt=None, style='%'):
+        super().__init__(fmt, datefmt, style)
+
+        # NOTE: This will work only when style='%'
+        self.__extras = {
+            spec: None for spec in re.findall(r'\%\((check_\S+?)\)s', fmt)
+        }
+
+        # Set the default value for 'check_name'
+        if 'check_name' in self.__extras:
+            self.__extras['check_name'] = 'reframe'
+
+    def format(self, record):
+        # Fill in the check-specific record attributes
+        if record.check:
+            for spec in self.__extras:
+                if hasattr(record, spec):
+                    # Attribute set elsewhere
+                    continue
+
+                attr = spec.split('_', maxsplit=1)[1]
+                val = getattr(record.check, attr, None)
+                record.__dict__[spec] = _xfmt(val)
+        else:
+            # Update record with the dynamic extras even if check is not set
+            record.__dict__.update(self.__extras)
+
+        return super().format(record)
+
+
+class RFC3339Formatter(CheckFieldFormatter):
     def formatTime(self, record, datefmt=None):
         datefmt = datefmt or self.default_time_format
         if '%:z' not in datefmt:
@@ -176,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
@@ -388,26 +445,24 @@ def __init__(self, logger=None, check=None):
         super().__init__(
             logger,
             {
-                'check_name': 'reframe',
-                'check_jobid': '-1',
-                'check_job_completion_time': None,
-                'check_job_completion_time_unix': None,
+                # Here we only set the format specifiers that do not
+                # correspond directly to check attributes
+                'check': check,
+                '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_outputdir': None,
-                'check_stagedir': None,
-                'check_num_tasks': 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_tags': None,
+                '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(),
             }
         )
@@ -428,15 +483,11 @@ def std_stream_handlers(self):
 
     def _update_check_extras(self):
         '''Return a dictionary with all the check-specific information.'''
+
         if self.check is None:
             return
 
-        self.extra['check_name'] = self.check.name
         self.extra['check_info'] = self.check.info()
-        self.extra['check_outputdir'] = self.check.outputdir
-        self.extra['check_stagedir'] = self.check.stagedir
-        self.extra['check_num_tasks'] = self.check.num_tasks
-        self.extra['check_tags'] = ','.join(self.check.tags)
         if self.check.current_system:
             self.extra['check_system'] = self.check.current_system.name
 

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,20 +30,30 @@ 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')(),
                            getlauncher('local')(),
                            'fakejob')
     test.job._completion_time = time.time()
+    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
 
 
 @pytest.fixture
 def rfc3339formatter():
     return rlog.RFC3339Formatter(
         fmt='[%(asctime)s] %(levelname)s: %(check_name)s: %(message)s',
-        datefmt='%FT%T')
+        datefmt='%FT%T'
+    )
 
 
 @pytest.fixture
@@ -146,12 +157,32 @@ def test_logger_levels(logfile, logger_with_check):
     assert _pattern_in_logfile('foo', logfile)
 
 
+def test_logger_dynamic_attributes(logfile, logger_with_check):
+    formatter = rlog.RFC3339Formatter('%(check_custom)s|%(check_custom_list)s|'
+                                      '%(check_foo)s|%(check_custom_dict)s')
+    logger_with_check.logger.handlers[0].setFormatter(formatter)
+    logger_with_check.info('xxx')
+    assert _pattern_in_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(
         fmt=('[%(asctime)s] %(levelname)s: %(check_name)s: '
              'ct:%(check_job_completion_time)s: %(message)s'),
-        datefmt='%FT%T%:z')
+        datefmt='%FT%T%:z'
+    )
     logger_with_check.logger.handlers[0].setFormatter(formatter)
     logger_with_check.info('foo')
     logger_without_check.info('foo')