diff --git a/docs/config_reference.rst b/docs/config_reference.rst index b63b93e089..bda0ded856 100644 --- a/docs/config_reference.rst +++ b/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 `__ 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 ````. + 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 diff --git a/reframe/core/logging.py b/reframe/core/logging.py index fd9154e7e8..eb8afb257b 100644 --- a/reframe/core/logging.py +++ b/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 '' + + if isinstance(val, _DeferredExpression): + try: + return val.evaluate() + except BaseException: + return '' + + 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 '', - 'osgroup': osext.osgroup() or '', - '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 diff --git a/unittests/test_logging.py b/unittests/test_logging.py index ec960584ea..38136f843c 100644 --- a/unittests/test_logging.py +++ b/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,12 +30,21 @@ 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 @@ -42,7 +52,8 @@ class _FakeCheck(rfm.RegressionTest): 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\|\|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\|', 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')