From 2c192c46f0fba510ec68b4f343040e66130b7c85 Mon Sep 17 00:00:00 2001 From: sarafael Date: Mon, 16 Nov 2020 07:55:22 +0100 Subject: [PATCH 01/11] log custom check variable --- config/cscs.py | 2 +- reframe/core/logging.py | 32 +++++++++++++++++++++++++------- 2 files changed, 26 insertions(+), 8 deletions(-) diff --git a/config/cscs.py b/config/cscs.py index 71d06304b5..28022e3f38 100644 --- a/config/cscs.py +++ b/config/cscs.py @@ -971,7 +971,7 @@ 'type': 'filelog', 'prefix': '%(check_system)s/%(check_partition)s', 'level': 'info', - 'format': '%(check_job_completion_time)s|reframe %(version)s|%(check_info)s|jobid=%(check_jobid)s|num_tasks=%(check_num_tasks)s|%(check_perf_var)s=%(check_perf_value)s|ref=%(check_perf_ref)s (l=%(check_perf_lower_thres)s, u=%(check_perf_upper_thres)s)|%(check_perf_unit)s', # noqa: E501 + 'format': '%(check_job_completion_time)s|reframe %(version)s|%(check_info)s|jobid=%(check_job_jobid)s|num_tasks=%(check_num_tasks)s|%(check_perf_var)s=%(check_perf_value)s|ref=%(check_perf_ref)s (l=%(check_perf_lower_thres)s, u=%(check_perf_upper_thres)s)|%(check_perf_unit)s', # noqa: E501 'datefmt': '%FT%T%:z', 'append': True }, diff --git a/reframe/core/logging.py b/reframe/core/logging.py index fd9154e7e8..addb02bf5c 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -212,7 +212,7 @@ def _create_file_handler(site_config, config_prefix): def _create_filelog_handler(site_config, config_prefix): basedir = os.path.abspath(site_config.get(f'{config_prefix}/basedir')) - prefix = site_config.get(f'{config_prefix}/prefix') + prefix = site_config.get(f'{config_prefix}/prefix') filename_patt = os.path.join(basedir, prefix) append = site_config.get(f'{config_prefix}/append') return MultiFileHandler(filename_patt, mode='a+' if append else 'w+') @@ -385,9 +385,7 @@ def debug2(self, message, *args, **kwargs): class LoggerAdapter(logging.LoggerAdapter): def __init__(self, logger=None, check=None): - super().__init__( - logger, - { + extra_vars = { 'check_name': 'reframe', 'check_jobid': '-1', 'check_job_completion_time': None, @@ -405,12 +403,25 @@ def __init__(self, logger=None, check=None): 'check_perf_lower_thres': None, 'check_perf_upper_thres': None, 'check_perf_unit': None, - 'osuser': osext.osuser() or '', + 'osuser': osext.osuser() or '', 'osgroup': osext.osgroup() or '', 'check_tags': None, 'version': osext.reframe_version(), } - ) + + self.user_log_vars = [] + if logger: + log_vars = [] + for h in logger.handlers: + fmt = re.findall(r'\%\((check_\S+?)\)s', h.formatter._fmt) + log_vars.extend(fmt) + + for v in set(log_vars): + if v not in extra_vars: + extra_vars[v] = None + self.user_log_vars.append(v) + + super().__init__(logger, extra_vars) self.check = check self.colorize = False @@ -428,6 +439,7 @@ 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 @@ -447,11 +459,17 @@ def _update_check_extras(self): self.extra['check_environ'] = self.check.current_environ.name if self.check.job: - 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_unix'] = ct + for v in self.user_log_vars: + _, *var_name = v.split('_') + if var_name[0] == 'job' and self.check.job: + self.extra[v] = getattr(self.check.job, '_'.join(var_name[1:])) + else: + self.extra[v] = getattr(self.check, '_'.join(var_name)) + def log_performance(self, level, tag, value, ref, low_thres, upper_thres, unit=None, *, msg=None): From 33df163607a7b135df176bc9b4f1f817f5e01729 Mon Sep 17 00:00:00 2001 From: sarafael Date: Mon, 16 Nov 2020 07:58:48 +0100 Subject: [PATCH 02/11] update ci config --- config/cscs-ci.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/config/cscs-ci.py b/config/cscs-ci.py index f611aa28c7..5ed06c6d36 100644 --- a/config/cscs-ci.py +++ b/config/cscs-ci.py @@ -235,7 +235,7 @@ 'type': 'filelog', 'prefix': '%(check_system)s/%(check_partition)s', 'level': 'info', - 'format': '%(check_job_completion_time)s|reframe %(version)s|%(check_info)s|jobid=%(check_jobid)s|num_tasks=%(check_num_tasks)s|%(check_perf_var)s=%(check_perf_value)s|ref=%(check_perf_ref)s (l=%(check_perf_lower_thres)s, u=%(check_perf_upper_thres)s)|%(check_perf_unit)s', # noqa: E501 + 'format': '%(check_job_completion_time)s|reframe %(version)s|%(check_info)s|jobid=%(check_job_jobid)s|num_tasks=%(check_num_tasks)s|%(check_perf_var)s=%(check_perf_value)s|ref=%(check_perf_ref)s (l=%(check_perf_lower_thres)s, u=%(check_perf_upper_thres)s)|%(check_perf_unit)s', # noqa: E501 'datefmt': '%FT%T%:z', 'append': True } From 2e8f47ad8faed8a78413792f29bb906787c252bd Mon Sep 17 00:00:00 2001 From: sarafael Date: Tue, 17 Nov 2020 11:03:05 +0100 Subject: [PATCH 03/11] variable for logging arbitrary info --- reframe/core/pipeline.py | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/reframe/core/pipeline.py b/reframe/core/pipeline.py index d873797ba8..3256e6e359 100644 --- a/reframe/core/pipeline.py +++ b/reframe/core/pipeline.py @@ -180,6 +180,11 @@ def disable_hook(cls, hook_name): #: :default: ``[]`` valid_systems = fields.TypedField('valid_systems', typ.List[str]) + #: Logging of arbitrary information in per test basis + #: :type: :class:`typ.Dict[str, object]` + #: :default: ``{}`` + log_extra = fields.TypedField('log_extra', typ.Dict[str, object]) + #: A detailed description of the test. #: #: :type: :class:`str` @@ -744,6 +749,7 @@ def _rfm_init(self, name=None, prefix=None): self.name = name self.descr = self.name + self.log_extra = {} self.valid_prog_environs = [] self.valid_systems = [] self.sourcepath = '' From 57c5a3362c545da722ef7181e8041e8a03b542c5 Mon Sep 17 00:00:00 2001 From: sarafael Date: Tue, 17 Nov 2020 11:14:33 +0100 Subject: [PATCH 04/11] add put back check_jobid --- reframe/core/logging.py | 1 + 1 file changed, 1 insertion(+) diff --git a/reframe/core/logging.py b/reframe/core/logging.py index addb02bf5c..d68e6b1471 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -459,6 +459,7 @@ def _update_check_extras(self): self.extra['check_environ'] = self.check.current_environ.name if self.check.job: + 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_unix'] = ct From 12fa08b14917e8f35d58062a55c2faa42b07faf1 Mon Sep 17 00:00:00 2001 From: sarafael Date: Wed, 18 Nov 2020 09:23:57 +0100 Subject: [PATCH 05/11] make log_exta a str --- reframe/core/pipeline.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/reframe/core/pipeline.py b/reframe/core/pipeline.py index 3256e6e359..b34373d20d 100644 --- a/reframe/core/pipeline.py +++ b/reframe/core/pipeline.py @@ -181,9 +181,9 @@ def disable_hook(cls, hook_name): valid_systems = fields.TypedField('valid_systems', typ.List[str]) #: Logging of arbitrary information in per test basis - #: :type: :class:`typ.Dict[str, object]` - #: :default: ``{}`` - log_extra = fields.TypedField('log_extra', typ.Dict[str, object]) + #: :type: :class:`str` + #: :default: ``''`` + log_extra = fields.TypedField('log_extra', str) #: A detailed description of the test. #: @@ -749,7 +749,7 @@ def _rfm_init(self, name=None, prefix=None): self.name = name self.descr = self.name - self.log_extra = {} + self.log_extra = '' self.valid_prog_environs = [] self.valid_systems = [] self.sourcepath = '' From a956034ecd2bf008120317bcd6cd039cee5dc424 Mon Sep 17 00:00:00 2001 From: sarafael Date: Fri, 20 Nov 2020 11:04:45 +0100 Subject: [PATCH 06/11] refactor dynamic logging --- reframe/core/logging.py | 62 ++++++++++++++++++++++++++--------------- 1 file changed, 39 insertions(+), 23 deletions(-) diff --git a/reframe/core/logging.py b/reframe/core/logging.py index d68e6b1471..1d01b1da21 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -165,7 +165,40 @@ def _format_time_rfc3339(timestamp, datefmt): return re.sub(r'(%)?\:z', tz_rfc3339, time.strftime(datefmt, timestamp)) -class RFC3339Formatter(logging.Formatter): +class DynamicFieldFormatter(logging.Formatter): + def __init__(self, fmt=None, datefmt=None, style='%'): + super().__init__(fmt, datefmt, style) + self.__extras = {} + fmt = re.findall(r'\%\((check_\S+?)\)s', fmt) + for v in set(fmt): + if v not in self.__extras: + self.__extras[v] = None + + def _fmt_check_attr(self, val): + if isinstance(val, list) or isinstance(val, tuple): + return ','.join(val) + else: + return val + + def format(self, record): + if record.check: + for spec in self.__extras.keys(): + _, *attr = spec.split('_') + if spec in record.__dict__.keys(): + continue + + record.__dict__[spec] = self.__extras[spec] + if attr[0] == 'job' and record.check.job: + self.__extras[spec] = self._fmt_check_attr( + getattr(record.check.job, '_'.join(attr[1:]))) + else: + self.__extras[spec] = self._fmt_check_attr( + getattr(record.check, '_'.join(attr))) + + return super().format(record) + + +class RFC3339Formatter(DynamicFieldFormatter): def formatTime(self, record, datefmt=None): datefmt = datefmt or self.default_time_format if '%:z' not in datefmt: @@ -385,7 +418,9 @@ def debug2(self, message, *args, **kwargs): class LoggerAdapter(logging.LoggerAdapter): def __init__(self, logger=None, check=None): - extra_vars = { + super().__init__( + logger, + { 'check_name': 'reframe', 'check_jobid': '-1', 'check_job_completion_time': None, @@ -408,20 +443,8 @@ def __init__(self, logger=None, check=None): 'check_tags': None, 'version': osext.reframe_version(), } - - self.user_log_vars = [] - if logger: - log_vars = [] - for h in logger.handlers: - fmt = re.findall(r'\%\((check_\S+?)\)s', h.formatter._fmt) - log_vars.extend(fmt) - - for v in set(log_vars): - if v not in extra_vars: - extra_vars[v] = None - self.user_log_vars.append(v) - - super().__init__(logger, extra_vars) + ) + self.extra['check'] = check self.check = check self.colorize = False @@ -464,13 +487,6 @@ def _update_check_extras(self): ct = self.check.job.completion_time self.extra['check_job_completion_time_unix'] = ct - for v in self.user_log_vars: - _, *var_name = v.split('_') - if var_name[0] == 'job' and self.check.job: - self.extra[v] = getattr(self.check.job, '_'.join(var_name[1:])) - else: - self.extra[v] = getattr(self.check, '_'.join(var_name)) - def log_performance(self, level, tag, value, ref, low_thres, upper_thres, unit=None, *, msg=None): From 07a6cc3fff4bf6f4dc9a6c312fd87f15f6e55b80 Mon Sep 17 00:00:00 2001 From: sarafael Date: Fri, 20 Nov 2020 11:14:42 +0100 Subject: [PATCH 07/11] small fix --- reframe/core/logging.py | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 1d01b1da21..44ebb36ac4 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -169,10 +169,9 @@ class DynamicFieldFormatter(logging.Formatter): def __init__(self, fmt=None, datefmt=None, style='%'): super().__init__(fmt, datefmt, style) self.__extras = {} - fmt = re.findall(r'\%\((check_\S+?)\)s', fmt) - for v in set(fmt): - if v not in self.__extras: - self.__extras[v] = None + log_vars = re.findall(r'\%\((check_\S+?)\)s', fmt) + for v in set(log_vars): + self.__extras.setdefault(v, None) def _fmt_check_attr(self, val): if isinstance(val, list) or isinstance(val, tuple): From b30b2509527dd06404c7aa17186d72ed5d1bb5a7 Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Sat, 21 Nov 2020 13:50:39 +0100 Subject: [PATCH 08/11] Fine tune implementation of check format specifiers - Remove the `log_extra` attribute. This is not needed, because if an attribute does not exist, it will be simply logged as `None`. So users can introduce any check attribute as a format specifier. - Add unit tests --- reframe/core/logging.py | 76 +++++++++++++++++++++------------------ reframe/core/pipeline.py | 6 ---- unittests/test_logging.py | 19 ++++++++-- 3 files changed, 58 insertions(+), 43 deletions(-) diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 44ebb36ac4..68432ab434 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,39 +164,54 @@ def _format_time_rfc3339(timestamp, datefmt): return re.sub(r'(%)?\:z', tz_rfc3339, time.strftime(datefmt, timestamp)) -class DynamicFieldFormatter(logging.Formatter): +def _xfmt(val): + 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) - self.__extras = {} - log_vars = re.findall(r'\%\((check_\S+?)\)s', fmt) - for v in set(log_vars): - self.__extras.setdefault(v, None) - - def _fmt_check_attr(self, val): - if isinstance(val, list) or isinstance(val, tuple): - return ','.join(val) - else: - return val + + # 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.keys(): - _, *attr = spec.split('_') - if spec in record.__dict__.keys(): + for spec in self.__extras: + if hasattr(record, spec): + # Attribute set elsewhere continue - record.__dict__[spec] = self.__extras[spec] - if attr[0] == 'job' and record.check.job: - self.__extras[spec] = self._fmt_check_attr( - getattr(record.check.job, '_'.join(attr[1:]))) - else: - self.__extras[spec] = self._fmt_check_attr( - getattr(record.check, '_'.join(attr))) + 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(DynamicFieldFormatter): +class RFC3339Formatter(CheckFieldFormatter): def formatTime(self, record, datefmt=None): datefmt = datefmt or self.default_time_format if '%:z' not in datefmt: @@ -420,7 +434,9 @@ def __init__(self, logger=None, check=None): super().__init__( logger, { - 'check_name': 'reframe', + # 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, @@ -428,9 +444,6 @@ def __init__(self, logger=None, check=None): '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, @@ -439,11 +452,9 @@ def __init__(self, logger=None, check=None): 'check_perf_unit': None, 'osuser': osext.osuser() or '', 'osgroup': osext.osgroup() or '', - 'check_tags': None, 'version': osext.reframe_version(), } ) - self.extra['check'] = check self.check = check self.colorize = False @@ -465,12 +476,7 @@ def _update_check_extras(self): 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/reframe/core/pipeline.py b/reframe/core/pipeline.py index b34373d20d..d873797ba8 100644 --- a/reframe/core/pipeline.py +++ b/reframe/core/pipeline.py @@ -180,11 +180,6 @@ def disable_hook(cls, hook_name): #: :default: ``[]`` valid_systems = fields.TypedField('valid_systems', typ.List[str]) - #: Logging of arbitrary information in per test basis - #: :type: :class:`str` - #: :default: ``''`` - log_extra = fields.TypedField('log_extra', str) - #: A detailed description of the test. #: #: :type: :class:`str` @@ -749,7 +744,6 @@ def _rfm_init(self, name=None, prefix=None): self.name = name self.descr = self.name - self.log_extra = '' self.valid_prog_environs = [] self.valid_systems = [] self.sourcepath = '' diff --git a/unittests/test_logging.py b/unittests/test_logging.py index ec960584ea..7e847a9f2e 100644 --- a/unittests/test_logging.py +++ b/unittests/test_logging.py @@ -35,6 +35,9 @@ class _FakeCheck(rfm.RegressionTest): 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} return test @@ -42,7 +45,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 +150,23 @@ 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\|None\|a=1,b=2', 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') From 4bcd9feabae2a46cb36d69d2071e4cf20f70d0a9 Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Sat, 21 Nov 2020 13:59:09 +0100 Subject: [PATCH 09/11] Revert style changes and changes in the configuration files. --- config/cscs-ci.py | 2 +- config/cscs.py | 2 +- reframe/core/logging.py | 4 ++-- 3 files changed, 4 insertions(+), 4 deletions(-) diff --git a/config/cscs-ci.py b/config/cscs-ci.py index 5ed06c6d36..f611aa28c7 100644 --- a/config/cscs-ci.py +++ b/config/cscs-ci.py @@ -235,7 +235,7 @@ 'type': 'filelog', 'prefix': '%(check_system)s/%(check_partition)s', 'level': 'info', - 'format': '%(check_job_completion_time)s|reframe %(version)s|%(check_info)s|jobid=%(check_job_jobid)s|num_tasks=%(check_num_tasks)s|%(check_perf_var)s=%(check_perf_value)s|ref=%(check_perf_ref)s (l=%(check_perf_lower_thres)s, u=%(check_perf_upper_thres)s)|%(check_perf_unit)s', # noqa: E501 + 'format': '%(check_job_completion_time)s|reframe %(version)s|%(check_info)s|jobid=%(check_jobid)s|num_tasks=%(check_num_tasks)s|%(check_perf_var)s=%(check_perf_value)s|ref=%(check_perf_ref)s (l=%(check_perf_lower_thres)s, u=%(check_perf_upper_thres)s)|%(check_perf_unit)s', # noqa: E501 'datefmt': '%FT%T%:z', 'append': True } diff --git a/config/cscs.py b/config/cscs.py index 28022e3f38..71d06304b5 100644 --- a/config/cscs.py +++ b/config/cscs.py @@ -971,7 +971,7 @@ 'type': 'filelog', 'prefix': '%(check_system)s/%(check_partition)s', 'level': 'info', - 'format': '%(check_job_completion_time)s|reframe %(version)s|%(check_info)s|jobid=%(check_job_jobid)s|num_tasks=%(check_num_tasks)s|%(check_perf_var)s=%(check_perf_value)s|ref=%(check_perf_ref)s (l=%(check_perf_lower_thres)s, u=%(check_perf_upper_thres)s)|%(check_perf_unit)s', # noqa: E501 + 'format': '%(check_job_completion_time)s|reframe %(version)s|%(check_info)s|jobid=%(check_jobid)s|num_tasks=%(check_num_tasks)s|%(check_perf_var)s=%(check_perf_value)s|ref=%(check_perf_ref)s (l=%(check_perf_lower_thres)s, u=%(check_perf_upper_thres)s)|%(check_perf_unit)s', # noqa: E501 'datefmt': '%FT%T%:z', 'append': True }, diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 68432ab434..d04e8d76c3 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -258,7 +258,7 @@ def _create_file_handler(site_config, config_prefix): def _create_filelog_handler(site_config, config_prefix): basedir = os.path.abspath(site_config.get(f'{config_prefix}/basedir')) - prefix = site_config.get(f'{config_prefix}/prefix') + prefix = site_config.get(f'{config_prefix}/prefix') filename_patt = os.path.join(basedir, prefix) append = site_config.get(f'{config_prefix}/append') return MultiFileHandler(filename_patt, mode='a+' if append else 'w+') @@ -450,7 +450,7 @@ def __init__(self, logger=None, check=None): 'check_perf_lower_thres': None, 'check_perf_upper_thres': None, 'check_perf_unit': None, - 'osuser': osext.osuser() or '', + 'osuser': osext.osuser() or '', 'osgroup': osext.osgroup() or '', 'version': osext.reframe_version(), } From 62998c89640820a9e424043d4b092e704d15cbd0 Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Sat, 21 Nov 2020 18:21:25 +0100 Subject: [PATCH 10/11] Treat properly deferrables - As well as format `None` and errors in a human-readable manner. --- reframe/core/logging.py | 41 +++++++++++++++++++++++++-------------- unittests/test_logging.py | 18 ++++++++++++++++- 2 files changed, 43 insertions(+), 16 deletions(-) diff --git a/reframe/core/logging.py b/reframe/core/logging.py index d04e8d76c3..eb8afb257b 100644 --- a/reframe/core/logging.py +++ b/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 '' + + if isinstance(val, _DeferredExpression): + try: + return val.evaluate() + except BaseException: + return '' + 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 '', - 'osgroup': osext.osgroup() or '', + '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(), } ) diff --git a/unittests/test_logging.py b/unittests/test_logging.py index 7e847a9f2e..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,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\|\|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( From 03d778e269198eba5caeac94e3d6e5f76fffe885 Mon Sep 17 00:00:00 2001 From: Vasileios Karakasis Date: Sat, 21 Nov 2020 18:23:06 +0100 Subject: [PATCH 11/11] Update documentation --- docs/config_reference.rst | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) 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