diff --git a/reframe/core/logging.py b/reframe/core/logging.py index f2429ee1be..0bce2bbd5b 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -178,15 +178,17 @@ def __generate_header(self, record): # Expand the special check_#ALL specifier if '%(check_#ALL)s' in self.__fmt: delim = _guess_delim(self.__fmt) - self.__fmt = self.__fmt.replace( + fmt = self.__fmt.replace( '%(check_#ALL)s', delim.join(f'%({x})s' for x in sorted(record.__rfm_loggable_attrs__) if x not in self.__ignore_keys) ) + else: + fmt = self.__fmt header = '' - for m in self.__attr_patt.finditer(self.__fmt): + for m in self.__attr_patt.finditer(fmt): attr = m.group(1) delim = m.group(2) if attr == 'check_perfvalues': @@ -306,19 +308,25 @@ def __init__(self, fmt=None, datefmt=None, perffmt=None, self.__specs = re.findall(r'\%\((\S+?)\)s', fmt) self.__delim = perffmt[-1] if perffmt else '' self.__expand_vars = '%(check_#ALL)s' in self.__fmt - self.__expanded = False + self.__expanded_fmt = {} self.__ignore_keys = set(ignore_keys) if ignore_keys else set() - def _expand_fmt(self, attrs): - if not self.__expand_vars or self.__expanded: + def _expand_fmt(self, record): + if not self.__expand_vars: return self.__fmt - delim = _guess_delim(self.__fmt) - self.__fmt = self.__fmt.replace( - '%(check_#ALL)s', delim.join(f'%({x})s' for x in attrs - if x not in self.__ignore_keys) - ) - self.__expanded = True + key = id(record.__rfm_check__) + attrs = sorted(record.__rfm_loggable_attrs__) + try: + return self.__expanded_fmt[key] + except KeyError: + delim = _guess_delim(self.__fmt) + fmt = self.__fmt.replace( + '%(check_#ALL)s', delim.join(f'%({x})s' for x in attrs + if x not in self.__ignore_keys) + ) + self.__expanded_fmt[key] = fmt + return fmt def _format_perf(self, perfvars): chunks = [] @@ -341,9 +349,9 @@ def _format_perf(self, perfvars): return self.__delim.join(chunks) def formatMessage(self, record): - self._expand_fmt(sorted(record.__rfm_loggable_attrs__)) + fmt = self._expand_fmt(record) for s in self.__specs: - if not hasattr(record, s): + if s != 'check_#ALL' and not hasattr(record, s): setattr(record, s, None) record_proxy = dict(record.__dict__) @@ -362,7 +370,7 @@ def formatMessage(self, record): ) try: - return self.__fmt % record_proxy + return fmt % record_proxy except ValueError: return ("") diff --git a/unittests/test_policies.py b/unittests/test_policies.py index fec13d0101..885973ca8d 100644 --- a/unittests/test_policies.py +++ b/unittests/test_policies.py @@ -4,6 +4,7 @@ # SPDX-License-Identifier: BSD-3-Clause import contextlib +import io import json import jsonschema import os @@ -999,89 +1000,79 @@ def assert_git_timeout(self): assert not runner.stats.failed() -@pytest.fixture -def perf_test(): - class _MyTest(rfm.RunOnlyRegressionTest): - valid_systems = ['*'] - valid_prog_environs = ['*'] - executable = 'echo perf0=100 && echo perf1=50' +class _MyPerfTest(rfm.RunOnlyRegressionTest): + valid_systems = ['*'] + valid_prog_environs = ['*'] + executable = 'echo perf0=100 && echo perf1=50' - @sanity_function - def validate(self): - return sn.assert_found(r'perf0', self.stdout) + @sanity_function + def validate(self): + return sn.assert_found(r'perf0', self.stdout) - @performance_function('unit0') - def perf0(self): - return sn.extractsingle(r'perf0=(\S+)', self.stdout, 1, float) + @performance_function('unit0') + def perf0(self): + return sn.extractsingle(r'perf0=(\S+)', self.stdout, 1, float) - @performance_function('unit1') - def perf1(self): - return sn.extractsingle(r'perf1=(\S+)', self.stdout, 1, float) + @performance_function('unit1') + def perf1(self): + return sn.extractsingle(r'perf1=(\S+)', self.stdout, 1, float) - return _MyTest() +class _MyPerfParamTest(_MyPerfTest): + p = parameter([1, 2]) -@pytest.fixture -def perf_param_tests(): - class _MyTest(rfm.RunOnlyRegressionTest): - valid_systems = ['*'] - valid_prog_environs = ['*'] - executable = 'echo perf0=100 && echo perf1=50' - p = parameter([1, 2]) - @sanity_function - def validate(self): - return sn.assert_found(r'perf0', self.stdout) +class _MyFailingTest(rfm.RunOnlyRegressionTest): + valid_systems = ['*'] + valid_prog_environs = ['*'] + executable = 'echo perf0=100' - @performance_function('unit0') - def perf0(self): - return sn.extractsingle(r'perf0=(\S+)', self.stdout, 1, float) + @sanity_function + def validate(self): + return False - @performance_function('unit1') - def perf1(self): - return sn.extractsingle(r'perf1=(\S+)', self.stdout, 1, float) + @performance_function('unit0') + def perf0(self): + return sn.extractsingle(r'perf0=(\S+)', self.stdout, 1, float) - return [_MyTest(variant_num=v) for v in range(_MyTest.num_variants)] +class _LazyPerfTest(rfm.RunOnlyRegressionTest): + valid_systems = ['*'] + valid_prog_environs = ['*'] + executable = 'echo perf0=100' -@pytest.fixture -def failing_perf_test(): - class _MyFailingTest(rfm.RunOnlyRegressionTest): - valid_systems = ['*'] - valid_prog_environs = ['*'] - executable = 'echo perf0=100' + @sanity_function + def validate(self): + return True - @sanity_function - def validate(self): - return False + @run_before('performance') + def set_perf_vars(self): + self.perf_variables = { + 'perf0': sn.make_performance_function( + sn.extractsingle(r'perf0=(\S+)', self.stdout, 1, float), + 'unit0' + ) + } - @performance_function('unit0') - def perf0(self): - return sn.extractsingle(r'perf0=(\S+)', self.stdout, 1, float) - return _MyFailingTest() +@pytest.fixture +def perf_test(): + return _MyPerfTest() @pytest.fixture -def lazy_perf_test(): - class _LazyPerfTest(rfm.RunOnlyRegressionTest): - valid_systems = ['*'] - valid_prog_environs = ['*'] - executable = 'echo perf0=100' +def perf_param_tests(): + return [_MyPerfParamTest(variant_num=v) + for v in range(_MyPerfParamTest.num_variants)] - @sanity_function - def validate(self): - return True - @run_before('performance') - def set_perf_vars(self): - self.perf_variables = { - 'perf0': sn.make_performance_function( - sn.extractsingle(r'perf0=(\S+)', self.stdout, 1, float), - 'unit0' - ) - } +@pytest.fixture +def failing_perf_test(): + return _MyFailingTest() + +@pytest.fixture +def lazy_perf_test(): return _LazyPerfTest() @@ -1142,6 +1133,14 @@ def _assert_header(filepath, header): assert fp.readline().strip() == header +def _assert_no_logging_error(fn, *args, **kwargs): + captured_stderr = io.StringIO() + with contextlib.redirect_stderr(captured_stderr): + fn(*args, **kwargs) + + assert 'Logging error' not in captured_stderr.getvalue() + + def test_perf_logging(make_runner, make_exec_ctx, perf_test, config_perflog, tmp_path): make_exec_ctx( @@ -1164,14 +1163,14 @@ def test_perf_logging(make_runner, make_exec_ctx, perf_test, testcases = executors.generate_testcases([perf_test]) runner.runall(testcases) - logfile = tmp_path / 'perflogs' / 'generic' / 'default' / '_MyTest.log' + logfile = tmp_path / 'perflogs' / 'generic' / 'default' / '_MyPerfTest.log' assert os.path.exists(logfile) assert _count_lines(logfile) == 2 # Rerun with the same configuration and check that new entry is appended testcases = executors.generate_testcases([perf_test]) runner = make_runner() - runner.runall(testcases) + _assert_no_logging_error(runner.runall, testcases) assert _count_lines(logfile) == 3 # Change the configuration and rerun @@ -1189,7 +1188,7 @@ def test_perf_logging(make_runner, make_exec_ctx, perf_test, logging.configure_logging(rt.runtime().site_config) testcases = executors.generate_testcases([perf_test]) runner = make_runner() - runner.runall(testcases) + _assert_no_logging_error(runner.runall, testcases) assert _count_lines(logfile) == 2 _assert_header(logfile, 'job_completion_time,version,display_name,system,partition,' @@ -1209,7 +1208,7 @@ def test_perf_logging(make_runner, make_exec_ctx, perf_test, logging.configure_logging(rt.runtime().site_config) testcases = executors.generate_testcases([perf_test]) runner = make_runner() - runner.runall(testcases) + _assert_no_logging_error(runner.runall, testcases) assert _count_lines(logfile) == 2 _assert_header(logfile, 'job_completion_time,version,display_name,system,partition,' @@ -1238,9 +1237,9 @@ def test_perf_logging_no_end_delim(make_runner, make_exec_ctx, perf_test, logging.configure_logging(rt.runtime().site_config) runner = make_runner() testcases = executors.generate_testcases([perf_test]) - runner.runall(testcases) + _assert_no_logging_error(runner.runall, testcases) - logfile = tmp_path / 'perflogs' / 'generic' / 'default' / '_MyTest.log' + logfile = tmp_path / 'perflogs' / 'generic' / 'default' / '_MyPerfTest.log' assert os.path.exists(logfile) assert _count_lines(logfile) == 2 @@ -1270,9 +1269,9 @@ def test_perf_logging_no_perfvars(make_runner, make_exec_ctx, perf_test, logging.configure_logging(rt.runtime().site_config) runner = make_runner() testcases = executors.generate_testcases([perf_test]) - runner.runall(testcases) + _assert_no_logging_error(runner.runall, testcases) - logfile = tmp_path / 'perflogs' / 'generic' / 'default' / '_MyTest.log' + logfile = tmp_path / 'perflogs' / 'generic' / 'default' / '_MyPerfTest.log' assert os.path.exists(logfile) assert _count_lines(logfile) == 2 @@ -1307,9 +1306,9 @@ def test_perf_logging_multiline(make_runner, make_exec_ctx, perf_test, testcases = executors.generate_testcases( [perf_test, simple_test, failing_perf_test] ) - runner.runall(testcases) + _assert_no_logging_error(runner.runall, testcases) - logfile = tmp_path / 'perflogs' / 'generic' / 'default' / '_MyTest.log' + logfile = tmp_path / 'perflogs' / 'generic' / 'default' / '_MyPerfTest.log' assert os.path.exists(logfile) assert _count_lines(logfile) == 3 @@ -1340,7 +1339,7 @@ def test_perf_logging_lazy(make_runner, make_exec_ctx, lazy_perf_test, logging.configure_logging(rt.runtime().site_config) runner = make_runner() testcases = executors.generate_testcases([lazy_perf_test]) - runner.runall(testcases) + _assert_no_logging_error(runner.runall, testcases) logfile = tmp_path / 'perflogs' / 'generic' / 'default' / '_LazyPerfTest.log' assert os.path.exists(logfile) @@ -1352,9 +1351,9 @@ def test_perf_logging_all_attrs(make_runner, make_exec_ctx, perf_test, logging.configure_logging(rt.runtime().site_config) runner = make_runner() testcases = executors.generate_testcases([perf_test]) - runner.runall(testcases) + _assert_no_logging_error(runner.runall, testcases) - logfile = tmp_path / 'perflogs' / 'generic' / 'default' / '_MyTest.log' + logfile = tmp_path / 'perflogs' / 'generic' / 'default' / '_MyPerfTest.log' assert os.path.exists(logfile) with open(logfile) as fp: header = fp.readline() @@ -1363,14 +1362,41 @@ def test_perf_logging_all_attrs(make_runner, make_exec_ctx, perf_test, assert len(header.split('|')) == len(loggable_attrs) + 1 +def test_perf_logging_custom_vars(make_runner, make_exec_ctx, + config_perflog, tmp_path): + # Create two tests with different loggable variables + class _X(_MyPerfTest): + x = variable(int, value=1, loggable=True) + + class _Y(_MyPerfTest): + y = variable(int, value=2, loggable=True) + + make_exec_ctx(config_perflog(fmt='%(check_result)s|%(check_#ALL)s')) + logging.configure_logging(rt.runtime().site_config) + runner = make_runner() + testcases = executors.generate_testcases([_X(), _Y()]) + _assert_no_logging_error(runner.runall, testcases) + + logfiles = [tmp_path / 'perflogs' / 'generic' / 'default' / '_X.log', + tmp_path / 'perflogs' / 'generic' / 'default' / '_Y.log'] + for f in logfiles: + with open(f) as fp: + header = fp.readline().strip() + if os.path.basename(f).startswith('_X'): + assert 'x' in header.split('|') + else: + assert 'y' in header.split('|') + + def test_perf_logging_param_test(make_runner, make_exec_ctx, perf_param_tests, config_perflog, tmp_path): make_exec_ctx(config_perflog(fmt='%(check_result)s|%(check_#ALL)s')) logging.configure_logging(rt.runtime().site_config) runner = make_runner() testcases = executors.generate_testcases(perf_param_tests) - runner.runall(testcases) + _assert_no_logging_error(runner.runall, testcases) - logfile = tmp_path / 'perflogs' / 'generic' / 'default' / '_MyTest.log' + logfile = (tmp_path / 'perflogs' / 'generic' / + 'default' / '_MyPerfParamTest.log') assert os.path.exists(logfile) assert _count_lines(logfile) == 3