diff --git a/docs/config_reference.rst b/docs/config_reference.rst index 90bb95277..590ecef8d 100644 --- a/docs/config_reference.rst +++ b/docs/config_reference.rst @@ -1308,6 +1308,7 @@ All logging handlers share the following set of common attributes: .. csv-table:: + ``%(check_basename)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.name` attribute without any parameter suffixes; essentially the test's class name. ``%(check_build_locally)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.build_locally` attribute. ``%(check_build_time_limit)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.build_time_limit` attribute. ``%(check_descr)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.descr` attribute. @@ -1320,14 +1321,18 @@ All logging handlers share the following set of common attributes: ``%(check_extra_resources)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.extra_resources` attribute. ``%(check_fail_phase)s``, The phase where the test has failed. ``%(check_fail_reason)s``, The failure reason if the test has failed. + ``%(check_filename)s``, The file where this test is defined. + ``%(check_fixture)s``, Whether this test is a fixture. ``%(check_hashcode)s``, The unique hash associated with this test. ``%(check_info)s``, Various information about this test; essentially the return value of the test's :func:`~reframe.core.pipeline.RegressionTest.info` function. - ``%(check_job_completion_time)s``, Same as the ``(check_job_completion_time_unix)s`` but formatted according to ``datefmt``. + ``%(check_job_completion_time)s``, Same as the ``%(check_job_completion_time_unix)s`` but formatted according to ``datefmt``. ``%(check_job_completion_time_unix)s``, The completion time of the associated run job (see :attr:`~reframe.core.schedulers.Job.completion_time`). ``%(check_job_exitcode)s``, The exit code of the associated run job. + ``%(check_job_id)s``, The ID of the associated run job. ``%(check_job_nodelist)s``, The list of nodes that the associated run job has run on. - ``%(check_job_submit_time)s``, The submission time of the associated run job (see :attr:`~reframe.core.schedulers.Job.submit_time`). - ``%(check_jobid)s``, The ID of the associated run job. + ``%(check_job_stderr)s``, The name of the file containing the standard error of the associated run job. + ``%(check_job_stdout)s``, The name of the file containing the standard output of the associated run job. + ``%(check_job_submit_time_us)s``, The submission time of the associated run job, in microseconds since the Epoch (see :attr:`~reframe.core.schedulers.Job.submit_time`). ``%(check_keep_files)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.keep_files` attribute. ``%(check_local)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.local` attribute. ``%(check_maintainers)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.maintainers` attribute. @@ -1356,6 +1361,7 @@ All logging handlers share the following set of common attributes: ``%(check_stagedir)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.stagedir` attribute. ``%(check_strict_check)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.strict_check` attribute. ``%(check_system)s``, The name of the test's :attr:`~reframe.core.pipeline.RegressionTest.current_system`. + ``%(check_sysenv)s``, The combination of the test's current system, partition and programming environment, in the form ``:+``. ``%(check_tags)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.tags` attribute. ``%(check_time_limit)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.time_limit` attribute. ``%(check_unique_name)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.unique_name` attribute. @@ -1371,6 +1377,8 @@ All logging handlers share the following set of common attributes: ReFrame allows you to log any test variable, parameter or property if they are marked as "loggable". The log record placeholder will have the form ``%(check_NAME)s`` where ``NAME`` is the variable name, the parameter name or the property name that is marked as loggable. + The loggable attributes of the test's run job and, if present, its build job are also exposed, using the ``%(check_job_NAME)s`` and ``%(check_build_job_NAME)s`` placeholder forms respectively, where ``NAME`` is a loggable attribute of :class:`~reframe.core.schedulers.Job`, such as ``stdout``, ``stderr``, ``jobid``, ``exitcode``, ``state``, ``nodelist``, ``nodelist_folded``, ``scheduler``, ``script_filename``, ``script_contents``, or the ``submit_time_us``/``submit_timestamp``, ``start_time_us``/``start_timestamp`` and ``completion_time_us``/``completion_timestamp`` pairs. + There is also the special ``%(check_#ALL)s`` format placeholder which expands to all the loggable test attributes. These include all the above placeholders and any additional loggable variables or parameters defined by the test. On expanding this placeholder, ReFrame will try to guess the delimiter to use for separating the different attributes based on the existing format. @@ -1399,6 +1407,13 @@ All logging handlers share the following set of common attributes: .. versionadded:: 4.8 The ``%(hostname)s`` placeholder is added. +.. versionchanged:: 4.11 + The ``%(check_basename)s``, ``%(check_sysenv)s``, ``%(check_filename)s`` and ``%(check_fixture)s`` placeholders, as well as the ``%(check_build_job_NAME)s`` placeholder family, are added. + +.. deprecated:: 4.11 + The ``%(check_jobid)s`` and ``%(check_job_submit_time)s`` placeholders are deprecated in favor of ``%(check_job_id)s`` and ``%(check_job_submit_time_us)s`` respectively, for consistency with the rest of the ``%(check_job_NAME)s`` placeholders. + The old placeholders keep working but emit a deprecation warning; they will be removed in a future release. + .. py:attribute:: logging.handlers.format_perfvars .. py:attribute:: logging.handlers_perflog.format_perfvars @@ -1512,6 +1527,18 @@ The ``filelog`` log handler This handler is meant for performance logging only and logs the performance of a test in one or more files. The additional properties for the ``filelog`` handler are the following: +Unlike the other handlers, the ``filelog`` handler's :attr:`~config.logging.handlers_perflog.format` and :attr:`~config.logging.handlers_perflog.format_perfvars` default to values geared towards performance logging rather than to the generic, handler-wide defaults: + +.. code-block:: python + + 'format': '%(check_result)s|%(check_job_completion_time)s|%(check_#ALL)s', + 'format_perfvars': ('%(check_perf_value)s|%(check_perf_unit)s|' + '%(check_perf_ref)s|%(check_perf_lower_thres)s|' + '%(check_perf_upper_thres)s|') + +.. versionchanged:: 4.11 + The ``filelog``-specific defaults for :attr:`~config.logging.handlers_perflog.format` and :attr:`~config.logging.handlers_perflog.format_perfvars` are added; previously, a ``filelog`` handler without an explicit ``format`` would fall back to the generic ``"%(message)s"`` default, which produced empty performance log records. + .. py:attribute:: logging.handlers_perflog..filelog..basedir @@ -1523,14 +1550,37 @@ The additional properties for the ``filelog`` handler are the following: .. py:attribute:: logging.handlers_perflog..filelog..ignore_keys + :required: No + :default: See below. + A list of log record `format placeholders <#config.logging.handlers.format>`__ that will be ignored by the special ``%(check_#ALL)s`` placeholder. + By default, the following keys are ignored, since they tend to be either bulky (e.g., script or captured output contents) or not generally useful in a performance log: + + .. code-block:: python + + ['check_build_job_script_contents', 'check_build_job_stderr_contents', + 'check_build_job_stdout_contents', 'check_build_locally', + 'check_build_time_limit', 'check_display_name', 'check_hashcode', + 'check_job_script_contents', 'check_job_stderr_contents', + 'check_job_stdout_contents', 'check_keep_files', 'check_local', + 'check_maintainers', 'check_max_pending_time', 'check_outputdir', + 'check_prefix', 'check_readonly_files', 'check_stagedir', + 'check_strict_check', 'check_tags', 'check_time_limit', + 'check_variables'] + + Setting this option explicitly in your configuration replaces this default list entirely; it is not merged with it. + .. versionadded:: 4.3 + .. versionchanged:: 4.11 + A default value for this option is now provided; previously it defaulted to an empty list and the actual values was derived from the built-in configuration. + .. py:attribute:: logging.handlers_perflog..filelog..prefix - :required: Yes + :required: No + :default: ``"%(check_system)s/%(check_partition)s"`` This is a directory prefix (usually dynamic), appended to the :attr:`~config.logging.handlers_perflog..filelog..basedir`, where the performance logs of a test will be stored. This attribute accepts any of the check-specific `formatting placeholders <#config.logging.handlers_perflog.format>`__. @@ -1550,6 +1600,10 @@ The additional properties for the ``filelog`` handler are the following: system2/ ... + .. versionchanged:: 4.11 + This option is no longer required and now defaults to ``"%(check_system)s/%(check_partition)s"``. + Previously, it was being derived by the built-in configuration. + .. py:attribute:: logging.handlers_perflog..filelog..append @@ -2036,6 +2090,9 @@ General Configuration .. versionadded:: 4.7 + .. versionchanged:: 4.11 + This option now also controls the amount of stdout/stderr content captured in the ``*_stdout_contents``/``*_stderr_contents`` fields of the run report and in the JUnit XML report (see :option:`--report-junit`). + .. py:attribute:: general.flex_alloc_strict diff --git a/docs/manpage.rst b/docs/manpage.rst index fecc679f7..86ec5e24e 100644 --- a/docs/manpage.rst +++ b/docs/manpage.rst @@ -554,7 +554,7 @@ Options controlling ReFrame output Instruct ReFrame to generate a JUnit XML report in ``FILE``. - The generated report adheres to the XSD schema `here `__ where each retry is treated as an individual testsuite. + The generated report adheres to the XSD schema in `reframe/schemas/junit.xsd `__, which is a superset of the original `Apache Ant JUnit XSD `__, where each retry is treated as an individual testsuite. This option can also be set using the :envvar:`RFM_REPORT_JUNIT` environment variable or the :attr:`~config.general.report_junit` general configuration parameter. @@ -563,6 +563,15 @@ Options controlling ReFrame output .. versionchanged:: 3.6.1 Added support for retries in the JUnit XML report. + .. versionchanged:: 4.11 + Failed test cases now include ```` / ```` elements with the tail of the captured build or run output, in addition to the ```` element. + Each ```` also gets a ``file`` attribute pointing to the file where the test is defined. + + .. note:: + These additions are not part of the original Apache Ant JUnit XSD linked above, which only allows ````/```` at the ```` level and does not define a ``file`` attribute on ````. + They match what `GitLab's Test Reports `__ feature parses, but other JUnit consumers with a stricter or differently-shaped schema (e.g., Jenkins) may reject them. + If you run into such a case, please report it by opening a Github issue. + .. option:: -s, --stage=DIR Directory prefix for staging test resources. @@ -1763,6 +1772,19 @@ The following list summarizes the schema changes (version numbers refer to schem Since ReFrame 4.9, if a test's dependencies fail, the test is skipped and is put in the ``fail_deps`` state. Previously, it was treated as a normal failure. + .. admonition:: 5.0 + + This is a major schema revision that reworks how job information is reported and removes several properties that were never generally useful. + + - The following ``.runs[].testcases[]`` properties are removed with no replacement: ``dependencies_actual``, ``dependencies_conceptual``, ``session_uuid``, ``time_compile``, ``time_performance``, ``time_run``, ``time_sanity``, ``time_setup``, ``time_total`` and ``uuid``. + A unique identifier for a test case can still be reconstructed from ``session_info.uuid``, ``run_index`` and the new ``testcase_index`` property. + - ``build_jobid``, ``build_stdout`` and ``build_stderr`` are renamed to ``build_job_id``, ``build_job_stdout`` and ``build_job_stderr`` respectively. + - The loggable attributes of a test's run job and, if present, its build job (see :attr:`~config.logging.handlers_perflog.format`) are now reported in full, under the ``job_*`` and ``build_job_*`` property prefixes respectively (e.g., ``job_state``, ``job_nodelist``, ``build_job_script_contents``). + - New properties ``job_stdout_contents``, ``job_stderr_contents``, ``build_job_stdout_contents`` and ``build_job_stderr_contents`` are added, holding the tail of the captured output for failed tests (see :attr:`~config.general.failure_inspect_lines`). + - New properties ``basename``, ``sysenv`` and ``testcase_index`` are added to ``.runs[].testcases[]``. + - New properties ``start_time_us``, ``start_timestamp``, ``end_time_us`` and ``end_timestamp`` are added to ``session_info``; ``time_start``, ``time_start_unix``, ``time_end`` and ``time_end_unix`` are retained for compatibility with the SQLite results backend only. + - The set of ``required`` properties for both ``session_info`` and testcases is reduced to the minimal identifying fields (``data_version``, ``hostname`` and ``uuid`` for sessions; ``name`` and ``result`` for testcases), since almost everything else may legitimately be absent depending on how far a test got in the pipeline before failing. + Environment =========== diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 581f356cb..fe201f8dd 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -24,7 +24,7 @@ import reframe.utility.osext as osext from reframe.core.exceptions import (ConfigError, LoggingError, WarningAsError, what) -from reframe.core.warnings import suppress_deprecations +from reframe.core.warnings import suppress_deprecations, user_deprecation_warning from reframe.utility import is_trivially_callable from reframe.utility.profile import TimeProfiler @@ -172,6 +172,10 @@ def __init__(self, prefix, mode='a', encoding=None, fmt=None, self.__lockfile_mode = lockfile_mode self.__locks = {} + # Always ignore the following keys in file logging + # NOTE: Consider setting this as the default configuration parameter + self.__ignore_keys |= {'check_job_script_contents'} + def __generate_header(self, record): # Generate the header from the record and fmt @@ -331,6 +335,14 @@ def _dofmt(v): return _dofmt(val) +# Log record placeholders that were renamed; kept here so that format +# strings referencing the old names keep working, with a deprecation warning +_DEPRECATED_LOG_ALIASES = { + 'check_jobid': 'check_job_id', + 'check_job_submit_time': 'check_job_submit_time_us', +} + + class CheckFieldFormatter(logging.Formatter): '''Log formatter that dynamically looks up format specifiers inside a regression test.''' @@ -348,6 +360,25 @@ def __init__(self, fmt=None, datefmt=None, perffmt=None, self.__expanded_fmt = {} self.__ignore_keys = set(ignore_keys) if ignore_keys else set() + # Always ignore the following keys in file logging + self.__ignore_keys |= {'check_job_script_contents'} + + # Resolve any deprecated placeholders used in the format string once; + # the format string is static, so there is no need to redo this + # on every call to formatMessage() + self.__alias_map = {} + for s in self.__specs: + if (new_name := _DEPRECATED_LOG_ALIASES.get(s)) is None: + continue + + msg = (f"the '%({s})s' log record placeholder is deprecated; " + f"please use '%({new_name})s' instead") + if msg not in _WARN_ONCE: + _WARN_ONCE.add(msg) + user_deprecation_warning(msg) + + self.__alias_map[s] = new_name + def _expand_fmt(self, record): if not self.__expand_vars: return self.__fmt @@ -370,7 +401,7 @@ def _format_perf(self, perfvars): for var, info in perfvars.items(): val, ref, lower, upper, unit, result = info record = { - 'check_perf_var': var.split(':')[-1], + 'check_perf_var': var, 'check_perf_value': val, 'check_perf_unit': unit, 'check_perf_ref': ref, @@ -389,7 +420,14 @@ def _format_perf(self, perfvars): def formatMessage(self, record): fmt = self._expand_fmt(record) for s in self.__specs: - if s != 'check_#ALL' and not hasattr(record, s): + if s == 'check_#ALL' or hasattr(record, s): + continue + + # Check if placeholder has an alias + new_name = self.__alias_map.get(s) + if new_name is not None and hasattr(record, new_name): + setattr(record, s, getattr(record, new_name)) + else: setattr(record, s, None) record_proxy = dict(record.__dict__) @@ -918,6 +956,14 @@ def std_stream_handlers(self): else: return [] + def _update_job_extras(self, job, prefix): + job_type = type(job) + for attr, alt_name in job_type.loggable_attrs(): + extra_name = alt_name or attr + key = f'{prefix}_{extra_name}' + self.extra['__rfm_loggable_attrs__'].append(key) + self.extra[key] = getattr(job, attr, None) + def _update_check_extras(self): '''Return a dictionary with all the check-specific information.''' @@ -941,11 +987,25 @@ def _update_check_extras(self): self.extra['__rfm_loggable_attrs__'].append(key) self.extra[key] = val + # Add build job and job attributes + if self.check.build_job: + self._update_job_extras(self.check.build_job, 'check_build_job') + + if self.check.job: + self._update_job_extras(self.check.job, 'check_job') + # Add special extras self.extra['check_info'] = self.check.info() - self.extra['check_job_completion_time'] = _format_time_rfc3339( - self.extra['check_job_completion_time_unix'], r'%FT%T%:z' - ) + + # Add the legacy entries for the job completion times + job_completion_time_us = self.extra.get('check_job_completion_time_us') + if job_completion_time_us: + self.extra['check_job_completion_time_unix'] = ( + job_completion_time_us / 1_000_000 + ) + self.extra['check_job_completion_time'] = _format_time_rfc3339( + self.extra['check_job_completion_time_unix'], r'%FT%T%:z' + ) def log_result(self, level, task, msg=None, multiline=False): if self.check is None: diff --git a/reframe/core/pipeline.py b/reframe/core/pipeline.py index 2730d896a..c42827d6e 100644 --- a/reframe/core/pipeline.py +++ b/reframe/core/pipeline.py @@ -40,7 +40,9 @@ import reframe.utility.typecheck as typ import reframe.utility.udeps as udeps from reframe.core.backends import getlauncher, getscheduler -from reframe.core.builtins import _XFailReference, xfail +from reframe.core.builtins import (deferrable, deprecate, + loggable, loggable_as, final, + variable, _XFailReference, xfail) from reframe.core.buildsystems import BuildSystemField from reframe.core.containers import ContainerPlatform from reframe.core.fields import remove_convertible @@ -650,6 +652,7 @@ def pipeline_hooks(cls): #: #: :type: :class:`List[str]` #: :default: ``required`` + #: :loggable: No #: #: .. seealso:: #: - `Environment features @@ -671,7 +674,8 @@ def pipeline_hooks(cls): #: #: .. versionchanged:: 3.11.0 #: Extend syntax to support features and key/value pairs. - valid_prog_environs = variable(typ.List[typ.Str[_VALID_ENV_SYNTAX]]) + valid_prog_environs = variable(typ.List[typ.Str[_VALID_ENV_SYNTAX]], + loggable=False) #: List of systems or system features or system properties required by this #: test. @@ -742,6 +746,7 @@ def pipeline_hooks(cls): #: #: :type: :class:`List[str]` #: :default: ``None`` + #: :loggable: No #: #: .. seealso:: #: - `System partition features @@ -761,12 +766,14 @@ def pipeline_hooks(cls): #: .. versionchanged:: 4.10 #: Support for combining an explicit system partition combination with #: features and extras. - valid_systems = variable(typ.List[typ.Str[_VALID_SYS_SYNTAX]]) + valid_systems = variable(typ.List[typ.Str[_VALID_SYS_SYNTAX]], + loggable=False) #: A detailed description of the test. #: #: :type: :class:`str` #: :default: ``''`` + #: :loggable: Yes #: #: .. versionchanged:: 4.0 #: The default value is now the empty string. @@ -788,7 +795,8 @@ def pipeline_hooks(cls): #: #: :type: :class:`str` #: :default: ``''`` - sourcepath = variable(str, value='') + #: :loggable: No + sourcepath = variable(str, value='', loggable=False) #: The directory containing the test's resources. #: @@ -806,6 +814,7 @@ def pipeline_hooks(cls): #: :type: :class:`str` or :class:`None` #: :default: ``'src'`` if such a directory exists at the test level, #: otherwise ``None`` + #: :loggable: No #: #: .. note:: #: .. versionchanged:: 2.9 @@ -818,7 +827,8 @@ def pipeline_hooks(cls): #: .. versionchanged:: 3.0 #: Default value is now conditionally set to either ``'src'`` or #: :class:`None`. - sourcesdir = variable(str, typ.Dict[str, object], type(None), value='src') + sourcesdir = variable(str, typ.Dict[str, object], type(None), + value='src', loggable=False) #: .. versionadded:: 2.14 #: @@ -835,6 +845,7 @@ def pipeline_hooks(cls): #: #: :type: :class:`str` or :class:`reframe.core.buildsystems.BuildSystem`. #: :default: :class:`None`. + #: :loggable: No build_system = variable(type(None), field=BuildSystemField, value=None, loggable=False) @@ -848,7 +859,8 @@ def pipeline_hooks(cls): #: #: :type: :class:`List[str]` #: :default: ``[]`` - prebuild_cmds = variable(typ.List[str], value=[]) + #: :loggable: No + prebuild_cmds = variable(typ.List[str], value=[], loggable=False) #: .. versionadded:: 3.0 #: @@ -860,7 +872,8 @@ def pipeline_hooks(cls): #: #: :type: :class:`List[str]` #: :default: ``[]`` - postbuild_cmds = variable(typ.List[str], value=[]) + #: :loggable: No + postbuild_cmds = variable(typ.List[str], value=[], loggable=False) #: The name of the executable to be launched during the run phase. #: @@ -871,17 +884,19 @@ def pipeline_hooks(cls): #: #: :type: :class:`str` #: :default: :class:`required` + #: :loggable: No #: #: .. versionchanged:: 3.7.3 #: Default value changed from ``os.path.join('.', self.unique_name)`` to #: :class:`required`. - executable = variable(str) + executable = variable(str, loggable=False) #: List of options to be passed to the :attr:`executable`. #: #: :type: :class:`List[str]` #: :default: ``[]`` - executable_opts = variable(typ.List[str], value=[]) + #: :loggable: No + executable_opts = variable(typ.List[str], value=[], loggable=False) #: .. versionadded:: 2.20 #: @@ -916,6 +931,7 @@ def pipeline_hooks(cls): #: :default: the container runtime specified in the current system #: partition's configuration (see also #: :ref:`container-platform-configuration`). + #: :loggable: No #: #: .. versionchanged:: 3.12.0 #: This field is now set automatically from the current partition's @@ -933,7 +949,8 @@ def pipeline_hooks(cls): #: #: :type: :class:`List[str]` #: :default: ``[]`` - prerun_cmds = variable(typ.List[str], value=[]) + #: :loggable: No + prerun_cmds = variable(typ.List[str], value=[], loggable=False) #: .. versionadded:: 3.0 #: @@ -944,7 +961,8 @@ def pipeline_hooks(cls): #: #: :type: :class:`List[str]` #: :default: ``[]`` - postrun_cmds = variable(typ.List[str], value=[]) + #: :loggable: No + postrun_cmds = variable(typ.List[str], value=[], loggable=False) #: List of files to be kept after the test finishes. #: @@ -960,11 +978,12 @@ def pipeline_hooks(cls): #: #: :type: :class:`List[str]` #: :default: ``[]`` + #: :loggable: Yes #: #: .. versionchanged:: 3.3 #: This field accepts now also file glob patterns. #: - keep_files = variable(typ.List[str], value=[]) + keep_files = variable(typ.List[str], value=[], loggable=True) #: List of files or directories (relative to the :attr:`sourcesdir`) that #: will be symlinked in the stage directory and not copied. @@ -974,7 +993,8 @@ def pipeline_hooks(cls): #: #: :type: :class:`List[str]` #: :default: ``[]`` - readonly_files = variable(typ.List[str], value=[]) + #: :loggable: Yes + readonly_files = variable(typ.List[str], value=[], loggable=True) #: Set of tags associated with this test. #: @@ -982,7 +1002,8 @@ def pipeline_hooks(cls): #: #: :type: :class:`Set[str]` #: :default: an empty set - tags = variable(typ.Set[str], value=set()) + #: :loggable: Yes + tags = variable(typ.Set[str], value=set(), loggable=True) #: List of people responsible for this test. #: @@ -990,7 +1011,8 @@ def pipeline_hooks(cls): #: #: :type: :class:`List[str]` #: :default: ``[]`` - maintainers = variable(typ.List[str], value=[]) + #: :loggable: Yes + maintainers = variable(typ.List[str], value=[], loggable=True) #: Mark this test as a strict performance test. #: @@ -1000,7 +1022,8 @@ def pipeline_hooks(cls): #: #: :type: boolean #: :default: :class:`True` - strict_check = variable(typ.Bool, value=True) + #: :loggable: Yes + strict_check = variable(typ.Bool, value=True, loggable=True) #: Number of tasks required by this test. #: @@ -1033,6 +1056,7 @@ def pipeline_hooks(cls): #: #: :type: integral or :obj:`None` #: :default: ``1`` + #: :loggable: Yes #: #: .. note:: #: .. versionchanged:: 2.15 @@ -1045,7 +1069,7 @@ def pipeline_hooks(cls): #: Allow :attr:`num_tasks` to be :obj:`None`. #: .. versionchanged:: 4.8 #: ``pbs`` and ``torque`` backends interpret ``num_tasks=None``. - num_tasks = variable(int, type(None), value=1) + num_tasks = variable(int, type(None), value=1, loggable=True) #: Number of tasks per node required by this test. #: @@ -1053,7 +1077,8 @@ def pipeline_hooks(cls): #: #: :type: integral or :class:`None` #: :default: :class:`None` - num_tasks_per_node = variable(int, type(None), value=None) + #: :loggable: Yes + num_tasks_per_node = variable(int, type(None), value=None, loggable=True) #: Number of GPUs per node required by this test. #: This attribute is translated internally to the ``_rfm_gpu`` resource. @@ -1062,10 +1087,11 @@ def pipeline_hooks(cls): #: #: :type: integral or :const:`None` #: :default: :const:`None` + #: :loggable: Yes #: #: .. versionchanged:: 4.0.0 #: The default value changed to :const:`None`. - num_gpus_per_node = variable(int, type(None), value=None) + num_gpus_per_node = variable(int, type(None), value=None, loggable=True) #: Number of CPUs per task required by this test. #: @@ -1073,7 +1099,8 @@ def pipeline_hooks(cls): #: #: :type: integral or :class:`None` #: :default: :class:`None` - num_cpus_per_task = variable(int, type(None), value=None) + #: :loggable: Yes + num_cpus_per_task = variable(int, type(None), value=None, loggable=True) #: Number of tasks per core required by this test. #: @@ -1081,7 +1108,8 @@ def pipeline_hooks(cls): #: #: :type: integral or :class:`None` #: :default: :class:`None` - num_tasks_per_core = variable(int, type(None), value=None) + #: :loggable: Yes + num_tasks_per_core = variable(int, type(None), value=None, loggable=True) #: Number of tasks per socket required by this test. #: @@ -1089,7 +1117,8 @@ def pipeline_hooks(cls): #: #: :type: integral or :class:`None` #: :default: :class:`None` - num_tasks_per_socket = variable(int, type(None), value=None) + #: :loggable: Yes + num_tasks_per_socket = variable(int, type(None), value=None, loggable=True) #: Specify whether this tests needs simultaneous multithreading enabled. #: @@ -1097,7 +1126,9 @@ def pipeline_hooks(cls): #: #: :type: boolean or :class:`None` #: :default: :class:`None` - use_multithreading = variable(typ.Bool, type(None), value=None) + #: :loggable: Yes + use_multithreading = variable(typ.Bool, type(None), value=None, + loggable=True) #: .. versionadded:: 3.0 #: @@ -1107,20 +1138,23 @@ def pipeline_hooks(cls): #: #: :type: :class:`str` or :class:`datetime.timedelta` #: :default: :class:`None` + #: :loggable: Yes max_pending_time = variable(type(None), typ.Duration, value=None, - allow_implicit=True) + allow_implicit=True, loggable=True) #: Specify whether this test needs exclusive access to nodes. #: #: :type: boolean #: :default: :class:`False` - exclusive_access = variable(typ.Bool, value=False) + #: :loggable: Yes + exclusive_access = variable(typ.Bool, value=False, loggable=True) #: Always execute this test locally. #: #: :type: boolean #: :default: :class:`False` - local = variable(typ.Bool, value=False) + #: :loggable: Yes + local = variable(typ.Bool, value=False, loggable=True) #: The performance reference values for this test. #: @@ -1377,6 +1411,7 @@ def pipeline_hooks(cls): #: :type: A dictionary with a special structure as described above. #: The elements of reference tuples cannot be deferrable expressions. #: :default: ``{}`` + #: :loggable: No #: #: .. note:: #: The reference values dictionary is implemented as a special case of @@ -1415,6 +1450,7 @@ def pipeline_hooks(cls): #: #: :type: boolean #: :default: :const:`False` + #: :loggable: No #: #: .. versionadded:: 4.0.0 require_reference = variable(typ.Bool, value=False, loggable=False) @@ -1427,6 +1463,7 @@ def pipeline_hooks(cls): #: :type: A deferrable expression (i.e., the result of a :doc:`sanity #: function `) #: :default: :class:`required` + #: :loggable: No #: #: .. note:: #: .. versionchanged:: 2.9 @@ -1459,6 +1496,7 @@ def pipeline_hooks(cls): #: `) as values. #: :class:`None` is also allowed. #: :default: :class:`None` + #: :loggable: No #: #: .. note:: #: @@ -1497,6 +1535,7 @@ def pipeline_hooks(cls): #: the member functions decorated with the :func:`@performance_function #: ` #: decorator. + #: :loggable: No #: #: .. versionadded:: 3.8.0 perf_variables = variable(typ.Dict[str, _DeferredPerformanceExpression], @@ -1508,8 +1547,9 @@ def pipeline_hooks(cls): #: #: :type: :class:`List[str]` or :class:`Dict[str, object]` #: :default: ``[]`` + #: :loggable: Yes modules = variable(typ.List[str], typ.List[typ.Dict[str, object]], - value=[]) + value=[], loggable=True) #: Environment variables to be set before running this test. #: @@ -1518,10 +1558,11 @@ def pipeline_hooks(cls): #: #: :type: :class:`Dict[str, object]` #: :default: ``{}`` + #: :loggable: Yes #: #: .. versionadded:: 4.0.0 env_vars = variable(typ.Dict[str, str], - typ.Dict[str, object], value={}) + typ.Dict[str, object], value={}, loggable=True) # NOTE: We still keep the original type, just to allow setting this # variable from the command line, because otherwise, ReFrame will not know # how to convert a value to an arbitrary object. @@ -1546,6 +1587,7 @@ def pipeline_hooks(cls): #: #: :type: :class:`str` or :class:`float` or :class:`int` #: :default: :class:`None` + #: :loggable: Yes #: #: .. note:: #: .. versionchanged:: 2.15 @@ -1564,7 +1606,7 @@ def pipeline_hooks(cls): #: The default value is now :class:`None` and it can be set globally #: per partition via the configuration. time_limit = variable(type(None), typ.Duration, value=None, - allow_implicit=True) + allow_implicit=True, loggable=True) #: .. versionadded:: 3.5.1 #: @@ -1574,8 +1616,9 @@ def pipeline_hooks(cls): #: #: :type: :class:`str` or :class:`float` or :class:`int` #: :default: :class:`None` + #: :loggable: Yes build_time_limit = variable(type(None), typ.Duration, value=None, - allow_implicit=True) + allow_implicit=True, loggable=True) #: .. versionadded:: 2.8 #: @@ -1642,13 +1685,14 @@ def pipeline_hooks(cls): #: #: :type: :class:`Dict[str, Dict[str, object]]` #: :default: ``{}`` + #: :loggable: No #: #: .. note:: #: .. versionchanged:: 2.9 #: A new more powerful syntax was introduced #: that allows also custom job script directive prefixes. extra_resources = variable(typ.Dict[str, typ.Dict[str, object]], - value={}) + value={}, loggable=False) #: .. versionadded:: 3.3 #: @@ -1671,7 +1715,8 @@ def pipeline_hooks(cls): #: #: :type: boolean #: :default: :class:`True` - build_locally = variable(typ.Bool, value=True) + #: :loggable: Yes + build_locally = variable(typ.Bool, value=True, loggable=True) #: .. versionadded:: 4.2 #: @@ -1694,12 +1739,15 @@ def pipeline_hooks(cls): #: #: :type: :class:`dict` #: :default: ``{}`` + #: :loggable: No ci_extras = variable(typ.Dict[typ.Str['gitlab'], object], value={}, loggable=False) # Special variables #: Dry-run mode + #: + #: :loggable: No _rfm_dry_run = variable(typ.Bool, value=False, loggable=False) def __new__(cls, *args, **kwargs): @@ -1817,6 +1865,10 @@ def __rfm_init__(self): if isinstance(self.reference, _ReferenceDict): self.reference.resolve_external_references(self) + # Default format for loggable timestamps in the test report + # Logging handlers will override this formatting + self._rfm_datefmt = r'%FT%T:z' + @classmethod def _process_hook_registry(cls): '''Process and validate the pipeline hooks.''' @@ -1882,6 +1934,7 @@ def unique_name(self): '''The unique name of this test. :type: :class:`str` + :loggable: Yes .. versionadded:: 3.10.0 ''' @@ -1896,6 +1949,8 @@ def name(self): parameters starting with ``.`` that are inserted by the :option:`--repeat`, :option:`--distribute` and other similar options. + :loggable: Yes + .. versionchanged:: 4.7 The implicit parameters starting with special characters are now @@ -1924,6 +1979,7 @@ def display_name(self): of this specific test variant. :type: :class:`str` + :loggable: Yes .. note:: The display name may not be unique. @@ -1970,6 +2026,11 @@ def _format_params(cls, info, prefix=' %'): @loggable @property def hashcode(self): + '''The unique hash associated with this test. + + :type: :class:`str` + :loggable: Yes + ''' if hasattr(self, '_rfm_hashcode'): return self._rfm_hashcode @@ -1994,6 +2055,8 @@ def short_name(self): simple tests and combines the test's class name and a hash code for parameterised tests. + :loggable: Yes + .. versionadded:: 4.0.0 ''' @@ -2111,6 +2174,8 @@ def perfvalues(self): or ``fail`` string denoting whether the achieved performance for this variable is within bounds or not. + :loggable: Yes + .. versionadded:: 2.18 .. versionchanged:: 3.11 @@ -2147,6 +2212,7 @@ def prefix(self): '''The prefix directory of the test. :type: :class:`str`. + :loggable: Yes ''' return self._rfm_prefix @@ -2158,6 +2224,7 @@ def stagedir(self): This is set during the :func:`setup` phase. :type: :class:`str`. + :loggable: Yes ''' return self._stagedir @@ -2171,6 +2238,7 @@ def outputdir(self): .. versionadded:: 2.13 :type: :class:`str`. + :loggable: Yes ''' return self._outputdir @@ -2220,51 +2288,55 @@ def build_stderr(self): # Various properties useful only for logging - @loggable_as('system') + @loggable_as('basename') @property - def _system_name(self): - return self.current_system.name + def _basename(self): + '''The test's class name, without any parameter suffixes. - @loggable_as('partition') - @property - def _partition_name(self): - if self.current_partition: - return self.current_partition.name + :loggable: Yes (logged as ``basename``) + ''' + return type(self).__name__ - @loggable_as('environ') + @loggable_as('system') @property - def _environ_name(self): - if self.current_environ: - return self.current_environ.name + def _system(self): + '''The name of the test's :attr:`current_system`. - @loggable_as('jobid') - @property - def _jobid(self): - if self.job: - return self.job.jobid + :loggable: Yes (logged as ``system``) + ''' + return self.current_system.name - @loggable_as('job_submit_time') + @loggable_as('sysenv') @property - def _job_submit_time(self): - if self.job: - return self.job.submit_time + def _sysenv(self): + '''The combination of the test's current system, partition and + programming environment, in the form + ``:+``. - @loggable_as('job_completion_time_unix') - @property - def _job_completion_time(self): - if self.job: - return self.job.completion_time + :loggable: Yes (logged as ``sysenv``) + ''' + if self.current_partition and self.current_environ: + return (f'{self.current_system.name}:' + f'{self.current_partition.name}+' + f'{self.current_environ.name}') - @loggable_as('job_exitcode') + @loggable_as('filename') @property - def _job_exitcode(self): - if self.job: - return self.job.exitcode + def _filename(self): + '''The file where this test is defined. - @loggable_as('job_nodelist') + :loggable: Yes (logged as ``filename``) + ''' + return inspect.getfile(type(self)) + + @loggable_as('fixture') @property - def _job_nodelist(self): - return self.job.nodelist if self.job else [] + def _fixture(self): + '''Whether this test is a fixture. + + :loggable: Yes (logged as ``fixture``) + ''' + return self.is_fixture() def info(self): '''Provide live information for this test. @@ -3072,22 +3144,22 @@ def check_performance(self): # Evaluate the performance function and retrieve the metrics xfailures = {} with osext.change_dir(self._stagedir): - for tag, expr in self.perf_variables.items(): + for var, expr in self.perf_variables.items(): try: value = expr.evaluate() if not self.is_dry_run() else None unit = expr.unit except Exception as e: getlogger().warning( f'skipping evaluation of performance variable ' - f'{tag!r}: {e}' + f'{var!r}: {e}' ) continue - key = f'{self._current_partition.fullname}:{tag}' + key = f'{self._current_partition.fullname}:{var}' try: ref = reference[key] if isinstance(ref, _XFailReference): - xfailures[key] = ref.message + xfailures[var] = ref.message ref = ref.data # If units are also provided in the reference, raise @@ -3096,8 +3168,8 @@ def check_performance(self): if len(ref) == 4: if ref[3] != unit: getlogger().warning( - f'reference unit ({key!r}) for the ' - f'performance variable {tag!r} ' + f'reference unit for the ' + f'performance variable {var!r} ' f'does not match the unit specified ' f'in the performance function ({unit!r}): ' f'{unit!r} will be used' @@ -3109,13 +3181,13 @@ def check_performance(self): if self.require_reference: raise PerformanceError( f'no reference value found for ' - f'performance variable {tag!r} on ' + f'performance variable {var!r} on ' f'system {self._current_partition.fullname!r}' ) from None ref = (0, None, None) - self._perfvalues[key] = [value, *ref, unit, None] + self._perfvalues[var] = [value, *ref, unit, None] if self.is_dry_run(): return @@ -3184,15 +3256,14 @@ def _fmt_errors(errlist, indent=''): # Check the performance variables against their references. errors = _PerfErrorBuilder() - for key, values in self._perfvalues.items(): - tag = key.split(':')[-1] - val, ref, low_thres, high_thres, unit, _ = values + for var, reftuple in self._perfvalues.items(): + val, ref, low_thres, high_thres, unit, _ = reftuple # Verify that val is a number if not isinstance(val, numbers.Number): raise SanityError( f'the value extracted for performance variable ' - f'{key!r} is not a number: {val}' + f'{var!r} is not a number: {val}' ) try: @@ -3200,19 +3271,19 @@ def _fmt_errors(errlist, indent=''): sn.assert_reference(val, ref, low_thres, high_thres) ) except SanityError: - if key in xfailures: - errors.add_xfail(xfailures[key]) - self._perfvalues[key][-1] = 'xfail' + if var in xfailures: + errors.add_xfail(xfailures[var]) + self._perfvalues[var][-1] = 'xfail' else: - errors.add_fail(tag, val, unit, ref, low_thres, high_thres) - self._perfvalues[key][-1] = 'fail' + errors.add_fail(var, val, unit, ref, low_thres, high_thres) + self._perfvalues[var][-1] = 'fail' else: - if key in xfailures: - errors.add_xpass(tag, val, unit, ref, + if var in xfailures: + errors.add_xpass(var, val, unit, ref, low_thres, high_thres) - self._perfvalues[key][-1] = 'xpass' + self._perfvalues[var][-1] = 'xpass' else: - self._perfvalues[key][-1] = 'pass' + self._perfvalues[var][-1] = 'pass' errors.raise_error() diff --git a/reframe/core/schedulers/__init__.py b/reframe/core/schedulers/__init__.py index f26a562e0..cc2c7a0f8 100644 --- a/reframe/core/schedulers/__init__.py +++ b/reframe/core/schedulers/__init__.py @@ -15,10 +15,12 @@ import reframe.core.shell as shell import reframe.utility.jsonext as jsonext import reframe.utility.typecheck as typ +from reframe.core.builtins import loggable, loggable_as, variable from reframe.core.exceptions import JobError, JobNotStartedError, SkipTestError from reframe.core.launchers import JobLauncher -from reframe.core.logging import getlogger, DEBUG2 +from reframe.core.logging import getlogger, DEBUG2, _format_time_rfc3339 from reframe.core.meta import RegressionTestMeta +from reframe.utility import nodelist_abbrev class JobMeta(RegressionTestMeta, abc.ABCMeta): @@ -104,23 +106,21 @@ def filternodes_by_state(self, nodelist, state): '''Filter nodes by their state :arg nodelist: List of :class:`Node` instances to filter. - :arg state: The state of the nodes. - If ``all``, the initial list is returned untouched. - If ``avail``, only the available nodes will be returned. - All other values are interpreted as a state string. - The pipe character ``|`` can be used as to specify multiple - alternative node states. - State match is exclusive unless the ``*`` is added at the end of the - state string. - When defining multiple states using ``|``, ``*`` has to be added at - the end of each alternative state for which a non-exclusive match is - required. + :arg state: The state of the nodes. If ``all``, the initial list is + returned untouched. If ``avail``, only the available nodes will be + returned. All other values are interpreted as a state string. The + pipe character ``|`` can be used as to specify multiple + alternative node states. State match is exclusive unless the ``*`` + is added at the end of the state string. When defining multiple + states using ``|``, ``*`` has to be added at the end of each + alternative state for which a non-exclusive match is required. :returns: the filtered node list .. versionchanged:: 4.9 - Support the ``|`` character to filter according to alternative states. + Support the ``|`` character to filter according to alternative + states. .. versionchanged:: 4.10 @@ -231,6 +231,7 @@ class Job(jsonext.JSONSerializable, metaclass=JobMeta): #: #: :type: integral #: :default: ``1`` + #: :loggable: No #: #: .. note:: #: This attribute is set by the framework just before submitting the job @@ -240,111 +241,123 @@ class Job(jsonext.JSONSerializable, metaclass=JobMeta): #: #: .. versionchanged:: 4.1 #: Allow :obj:`None` values - num_tasks = variable(int, type(None), value=1) + num_tasks = variable(int, type(None), value=1, loggable=False) #: Number of tasks per node for this job. #: #: :type: integral or :class:`NoneType` #: :default: ``None`` + #: :loggable: No #: #: .. note:: #: This attribute is set by the framework just before submitting the job #: based on the test information. #: #: .. versionadded:: 3.11.0 - num_tasks_per_node = variable(int, type(None), value=None) + num_tasks_per_node = variable(int, type(None), value=None, loggable=False) #: Number of tasks per core for this job. #: #: :type: integral or :class:`NoneType` #: :default: ``None`` + #: :loggable: No #: #: .. note:: #: This attribute is set by the framework just before submitting the job #: based on the test information. #: #: .. versionadded:: 3.11.0 - num_tasks_per_core = variable(int, type(None), value=None) + num_tasks_per_core = variable(int, type(None), value=None, loggable=False) #: Number of tasks per socket for this job. #: #: :type: integral or :class:`NoneType` #: :default: ``None`` + #: :loggable: No #: #: .. note:: #: This attribute is set by the framework just before submitting the job #: based on the test information. #: #: .. versionadded:: 3.11.0 - num_tasks_per_socket = variable(int, type(None), value=None) + num_tasks_per_socket = variable(int, type(None), value=None, + loggable=False) #: Number of processing elements associated with each task for this job. #: #: :type: integral or :class:`NoneType` #: :default: ``None`` + #: :loggable: No #: #: .. note:: #: This attribute is set by the framework just before submitting the job #: based on the test information. #: #: .. versionadded:: 3.11.0 - num_cpus_per_task = variable(int, type(None), value=None) + num_cpus_per_task = variable(int, type(None), value=None, loggable=False) #: Enable SMT for this job. #: #: :type: :class:`bool` or :class:`NoneType` #: :default: ``None`` + #: :loggable: No #: #: .. note:: #: This attribute is set by the framework just before submitting the job #: based on the test information. #: #: .. versionadded:: 3.11.0 - use_smt = variable(bool, type(None), value=None) + use_smt = variable(bool, type(None), value=None, loggable=False) #: Request exclusive access on the nodes for this job. #: #: :type: :class:`bool` #: :default: ``false`` + #: :loggable: No #: #: .. note:: #: This attribute is set by the framework just before submitting the job #: based on the test information. #: #: .. versionadded:: 3.11.0 - exclusive_access = variable(bool, value=False) + exclusive_access = variable(bool, value=False, loggable=False) #: Time limit for this job. #: #: See :attr:`reframe.core.pipeline.RegressionTest.time_limit` for more #: details. #: + #: :loggable: No + #: #: .. note:: #: This attribute is set by the framework just before submitting the job #: based on the test information. #: #: .. versionadded:: 3.11.0 - time_limit = variable(type(None), typ.Duration, - value=None, allow_implicit=True) + time_limit = variable(type(None), typ.Duration, value=None, + allow_implicit=True, loggable=False) #: Maximum pending time for this job. #: #: See :attr:`reframe.core.pipeline.RegressionTest.max_pending_time` for #: more details. #: + #: :loggable: No + #: #: .. note:: #: This attribute is set by the framework just before submitting the job #: based on the test information. #: #: .. versionadded:: 3.11.0 - max_pending_time = variable(type(None), typ.Duration, - value=None, allow_implicit=True) + max_pending_time = variable(type(None), typ.Duration, value=None, + allow_implicit=True, loggable=False) #: Arbitrary options to be passed to the backend job scheduler. #: #: :type: :class:`List[str]` #: :default: ``[]`` - options = variable(typ.List[str], value=[]) + #: :loggable: No + options = variable(typ.List[str], value=[], loggable=False) #: The (parallel) program launcher that will be used to launch the #: (parallel) executable of this job. @@ -366,7 +379,8 @@ class Job(jsonext.JSONSerializable, metaclass=JobMeta): #: self.job.launcher = getlauncher('local')() #: #: :type: :class:`reframe.core.launchers.JobLauncher` - launcher = variable(JobLauncher) + #: :loggable: No + launcher = variable(JobLauncher, loggable=False) #: Pin the jobs on the given nodes. #: @@ -376,9 +390,13 @@ class Job(jsonext.JSONSerializable, metaclass=JobMeta): #: #: :type: :class:`List[str]` #: :default: ``[]`` + #: :loggable: No #: #: .. versionadded:: 3.11.0 - pin_nodes = variable(typ.List[str], value=[]) + pin_nodes = variable(typ.List[str], value=[], loggable=False) + + # FIXME: Make this a configuration variable + _DATEFMT = r'%Y%m%dT%H%M%S%z' # The sched_* arguments are exposed also to the frontend def __init__(self, @@ -395,6 +413,7 @@ def __init__(self, self._name = name self._workdir = workdir self._script_filename = script_filename or f'{name}.sh' + self._script_contents = '' basename, _ = os.path.splitext(self._script_filename) self._stdout = stdout or f'{basename}.out' @@ -411,6 +430,7 @@ def __init__(self, self._state = None self._nodelist = [] self._submit_time = None + self._start_time = None self._completion_time = None # Job errors discovered while polling; if not None this will be raised @@ -424,47 +444,86 @@ def create(cls, scheduler, launcher, *args, **kwargs): ret.launcher = launcher return ret + def format_timestamp(self, ts): + return _format_time_rfc3339(ts, self._DATEFMT) + @property def name(self): - '''The name of this job.''' + '''The name of this job. + + :loggable: No + ''' return self._name @property def workdir(self): - '''The working directory for this job.''' + '''The working directory for this job. + + :loggable: No + ''' return self._workdir @property def cli_options(self): '''The scheduler options passed through the :option:`-J` command line - options.''' + options. + + :loggable: No + ''' return self._cli_options + @loggable @property def script_filename(self): - '''The filename of the generated job script.''' + '''The filename of the generated job script. + + :loggable: Yes + ''' return self._script_filename + @loggable + @property + def script_contents(self) -> str: + '''The contents of the generated job script + + :loggable: Yes + ''' + return self._script_contents + + @loggable @property def stdout(self): - '''The file where the standard output of the job is saved.''' + '''The file where the standard output of the job is saved. + + :loggable: Yes + ''' return self._stdout + @loggable @property def stderr(self): - '''The file where the standard error of the job is saved.''' + '''The file where the standard error of the job is saved. + + :loggable: Yes + ''' return self._stderr @property def sched_flex_alloc_nodes(self): '''The argument of the :option:`--flex-alloc-nodes` command line - option.''' + option. + + :loggable: No + ''' return self._sched_flex_alloc_nodes @property def sched_access(self): '''The partition's :attr:`~config.systems.partitions.access` - options.''' + options. + + :loggable: No + ''' return self._sched_access @property @@ -486,23 +545,63 @@ def completion_time(self): significantly. :type: :class:`float` or :class:`None` + :loggable: No ''' return self._completion_time + @loggable + @property + def completion_time_us(self) -> int | None: + '''Same as :attr:`completion_time`, but expressed in microseconds + since the Epoch. + + :loggable: Yes + ''' + if self._completion_time is not None: + return int(self._completion_time * 1_000_000) + + @loggable + @property + def completion_timestamp(self): + '''The :attr:`completion_time` formatted as an RFC3339 timestamp. + + :loggable: Yes + ''' + return self.format_timestamp(self.completion_time) + @property def scheduler(self): - '''The scheduler where this job is assigned to.''' + '''The scheduler where this job is assigned to. + + :loggable: No; see :attr:`_scheduler_name` for the loggable form + of this property, logged as ``scheduler``. + ''' return self._scheduler + @loggable_as('scheduler') + @property + def _scheduler_name(self): + '''The registered name of this job's scheduler. + + This is the value actually reported when logging the ``scheduler`` + attribute; see :attr:`scheduler` for the full scheduler object. + + :loggable: Yes (logged as ``scheduler``) + ''' + return self._scheduler.registered_name + @property def exception(self): '''The last exception that this job encountered. The scheduler will raise this exception the next time the status of this job is queried. + + :loggable: No ''' return self._exception + @loggable_as('id') @property def jobid(self): '''The ID of this job. @@ -513,9 +612,11 @@ def jobid(self): Job ID type is now a string. :type: :class:`str` or :class:`None` + :loggable: Yes (logged as ``id``) ''' return str(self._jobid) if self._jobid is not None else None + @loggable @property def exitcode(self): '''The exit code of this job. @@ -525,9 +626,11 @@ def exitcode(self): .. versionadded:: 2.21 :type: :class:`int` or :class:`None` + :loggable: Yes ''' return self._exitcode + @loggable @property def state(self): '''The state of this job. @@ -537,9 +640,11 @@ def state(self): .. versionadded:: 2.21 :type: :class`str` or :class:`None` + :loggable: Yes ''' return self._state + @loggable @property def nodelist(self): '''The list of node names assigned to this job. @@ -567,9 +672,19 @@ def nodelist(self): Default value is the empty list. :type: :class:`List[str]` + :loggable: Yes ''' return self._nodelist + @loggable + @property + def nodelist_folded(self): + '''The folded :attr:`nodelist` in hostlist format. + + :loggable: Yes + ''' + return nodelist_abbrev(self.nodelist) + @property def submit_time(self): '''The submission time of this job as a floating point number @@ -582,9 +697,63 @@ def submit_time(self): scheduler. :type: :class:`float` or :class:`None` + :loggable: No ''' return self._submit_time + @loggable + @property + def submit_time_us(self) -> int | None: + '''Same as :attr:`submit_time`, but expressed in microseconds since + the Epoch. + + :loggable: Yes + ''' + if self._submit_time is not None: + return int(self._submit_time * 1_000_000) + + @loggable + @property + def submit_timestamp(self): + '''The :attr:`submit_time` formatted as an RFC3339 timestamp. + + :loggable: Yes + ''' + return self.format_timestamp(self._submit_time) + + @property + def start_time(self): + '''The time this job started running, as a floating point number + expressed in seconds since the epoch, in UTC. + + This attribute is :class:`None` if the job hasn't started running + yet. + + :type: :class:`float` or :class:`None` + :loggable: No + ''' + return self._start_time + + @loggable + @property + def start_time_us(self) -> int | None: + '''Same as :attr:`start_time`, but expressed in microseconds since + the Epoch. + + :loggable: Yes + ''' + if self._start_time is not None: + return int(self._start_time * 1_000_000) + + @loggable + @property + def start_timestamp(self): + '''The :attr:`start_time` formatted as an RFC3339 timestamp. + + :loggable: Yes + ''' + return self.format_timestamp(self._start_time) + def prepare(self, commands, environs=None, prepare_cmds=None, strict_flex=False, **gen_opts): environs = environs or [] @@ -622,6 +791,8 @@ def prepare(self, commands, environs=None, prepare_cmds=None, for c in commands: builder.write_body(c) + self._script_contents = builder.finalize() + def guess_num_tasks(self): num_tasks_per_node = self.num_tasks_per_node or 1 if isinstance(self.sched_flex_alloc_nodes, int): diff --git a/reframe/core/schedulers/local.py b/reframe/core/schedulers/local.py index e6b85261c..ff6ebe805 100644 --- a/reframe/core/schedulers/local.py +++ b/reframe/core/schedulers/local.py @@ -82,6 +82,7 @@ def submit(self, job): job._f_stdout = f_stdout job._f_stderr = f_stderr job._submit_time = time.time() + job._start_time = job._submit_time job._state = 'RUNNING' def emit_preamble(self, job): diff --git a/reframe/core/schedulers/slurm.py b/reframe/core/schedulers/slurm.py index 5892a936f..58e129aec 100644 --- a/reframe/core/schedulers/slurm.py +++ b/reframe/core/schedulers/slurm.py @@ -467,18 +467,28 @@ def _get_nodes_by_name(self, nodespec): node_descriptions = completed.stdout.splitlines() return _create_nodes(node_descriptions) - def _update_completion_time(self, job, timestamps): - if job._completion_time is not None: + def _update_timestamp(self, job, timestamp_attr, + jobarr_timestamps_secs, reduce_fn): + '''Update a job local timestamp from a job array + + :arg job: The job to update the timestamp for. + :arg timestamp_attr: The job timestamp attribute. + :arg jobarr_timestamps_secs: The job array timestamp values in + formatted as `%s` + :arg reduce_fn: A callable taking the list of converted timestamp + values in seconds and returning a single float value + ''' + if getattr(job, timestamp_attr) is not None: return # Convert timestamps to floats ct = [] - for ts in timestamps: + for ts in jobarr_timestamps_secs: with suppress(ValueError): ct.append(float(ts)) if ct: - job._completion_time = max(ct) + setattr(job, timestamp_attr, reduce_fn(ct)) def poll(self, *jobs): '''Update the status of the jobs.''' @@ -496,9 +506,9 @@ def poll(self, *jobs): ) try: completed = _run_strict( - f'{self._sacct} -S {t_start} -P ' + f'{self._sacct} --noheader -X -S {t_start} -P ' f'-j {",".join(job.jobid for job in jobs)} ' - f'-o jobid,state,exitcode,end,nodelist' + f'-o jobid,state,exitcode,start,end,nodelist' ) # Reset the retry counter if the command succeeds self._num_sacct_failures = 0 @@ -519,8 +529,8 @@ def poll(self, *jobs): # We need the match objects, so we have to use finditer() state_match = list(re.finditer( fr'^(?P{self._jobid_patt})\|(?P\S+)([^\|]*)\|' - fr'(?P\d+)\:(?P\d+)\|(?P\S+)\|' - fr'(?P.*)', completed.stdout, re.MULTILINE) + fr'(?P\d+)\:(?P\d+)\|(?P\S+)\|' + fr'(?P\S+)\|(?P.*)', completed.stdout, re.MULTILINE) ) if not state_match: self.log( @@ -552,8 +562,12 @@ def poll(self, *jobs): # Use ',' to join nodes to be consistent with Slurm syntax job._nodespec = ','.join(m.group('nodespec') for m in jobarr_info) - self._update_completion_time( - job, (m.group('end') for m in jobarr_info) + self._update_timestamp( + job, '_completion_time', + [m.group('end') for m in jobarr_info], max + ) + self._update_timestamp( + job, '_start_time', [m.group('start') for m in jobarr_info], min ) # Cancel jobs that blocked or pending for too long @@ -691,15 +705,16 @@ def poll(self, *jobs): # We don't run the command with check=True, because if the job has # finished already, squeue might return an error about an invalid # job id. - completed = osext.run_command( - f'{self._squeue} -h -j {",".join(job.jobid for job in jobs)} ' - f'-o "%%i|%%T|%%N|%%r"' - ) + with rt.temp_environment(env_vars={'SLURM_TIME_FORMAT': '%s'}): + completed = osext.run_command( + f'{self._squeue} -h -j {",".join(job.jobid for job in jobs)} ' + f'-o "%%i|%%S|%%T|%%N|%%r"' + ) # We need the match objects, so we have to use finditer() state_match = list(re.finditer( - fr'^(?P{self._jobid_patt})\|(?P\S+)\|' - fr'(?P\S*)\|(?P.+)', + fr'^(?P{self._jobid_patt})\|(?P\S+)\|' + fr'(?P\S+)\|(?P\S*)\|(?P.+)', completed.stdout, re.MULTILINE) ) jobinfo = {} @@ -723,6 +738,10 @@ def poll(self, *jobs): # Use ',' to join nodes to be consistent with Slurm syntax job._nodespec = ','.join(m.group('nodespec') for m in job_match) + # Update job start times + self._update_timestamp(job, '_start_time', + [m.group('start') for m in job_match], min) + pending_reasons = {} for jobid, states in jobinfo.items(): pending_reasons[jobid] = [s.group('reason') for s in states] diff --git a/reframe/core/settings.py b/reframe/core/settings.py index 6cdd0599e..c8c460676 100644 --- a/reframe/core/settings.py +++ b/reframe/core/settings.py @@ -51,45 +51,7 @@ ], 'handlers_perflog': [ { - 'type': 'filelog', - 'prefix': '%(check_system)s/%(check_partition)s', - 'level': 'info', - 'format': ('%(check_result)s|' - '%(check_job_completion_time)s|%(check_#ALL)s'), - 'ignore_keys': [ - 'check_build_locally', - 'check_build_time_limit', - 'check_display_name', - 'check_executable', - 'check_executable_opts', - 'check_hashcode', - 'check_keep_files', - 'check_local', - 'check_maintainers', - 'check_max_pending_time', - 'check_outputdir', - 'check_prebuild_cmds', - 'check_prefix', - 'check_prerun_cmds', - 'check_postbuild_cmds', - 'check_postrun_cmds', - 'check_readonly_files', - 'check_sourcepath', - 'check_sourcesdir', - 'check_stagedir', - 'check_strict_check', - 'check_tags', - 'check_time_limit', - 'check_valid_prog_environs', - 'check_valid_systems', - 'check_variables' - ], - 'format_perfvars': ( - '%(check_perf_value)s|%(check_perf_unit)s|' - '%(check_perf_ref)s|%(check_perf_lower_thres)s|' - '%(check_perf_upper_thres)s|' - ), - 'append': True + 'type': 'filelog' } ] } diff --git a/reframe/frontend/printer.py b/reframe/frontend/printer.py index fefacc110..79eb7cd77 100644 --- a/reframe/frontend/printer.py +++ b/reframe/frontend/printer.py @@ -3,7 +3,6 @@ # # SPDX-License-Identifier: BSD-3-Clause -import os import shutil import time import traceback @@ -12,8 +11,6 @@ import reframe.core.logging as logging import reframe.core.runtime as rt import reframe.utility.color as color -import reframe.utility.osext as osext -from reframe.core.exceptions import BuildError, SanityError from reframe.core.runtime import runtime from reframe.frontend.reporting import format_testcase_from_json from reframe.utility import nodelist_abbrev @@ -104,19 +101,27 @@ def __setattr__(self, attr, value): def failure_report(self, report, rerun_info=True, global_stats=False): '''Print a failure report''' - def _file_info(filename, prefix): - # filename and prefix are `None` before setup - if filename is None or prefix is None: - return [] + def _contents(rec, job_key): + stdout = rec.get(f'{job_key}_stdout') + stdout_contents = rec.get(f'{job_key}_stdout_contents') + stderr = rec.get(f'{job_key}_stderr') + stderr_contents = rec.get(f'{job_key}_stderr_contents') num_lines = runtime().get_option('general/0/failure_inspect_lines') - lines = [f'--- {filename} (last {num_lines} lines) ---\n'] - try: - lines += osext.tail(os.path.join(prefix, filename), num_lines) - except (OSError, UnicodeError) as e: - lines += [f'--- {filename} (ERROR: {e}) ---'] - else: - lines += [f'--- {filename} ---'] + lines = [] + if stdout is not None and stdout_contents is not None: + lines += [ + f'--- {stdout} (last {num_lines} lines) ---\n', + stdout_contents, + f'--- {stdout} ---\n' + ] + + if stderr is not None and stderr_contents is not None: + lines += [ + f'--- {stderr} (last {num_lines} lines) ---\n', + stderr_contents, + f'--- {stderr} ---' + ] return lines @@ -131,13 +136,11 @@ def _print_failure_info(rec, runid, total_runs): self.info(f" * Test file: {rec['filename']}") self.info(f" * Stage directory: {rec['stagedir']}") self.info(f" * Node list: " - f"{nodelist_abbrev(rec['job_nodelist'])}") + f"{nodelist_abbrev(rec.get('job_nodelist', []))}") job_type = 'local' if rec['scheduler'] == 'local' else 'batch job' - self.info(f" * Job type: {job_type} (id={rec['jobid']})") - self.info(f" * Dependencies (conceptual): " - f"{rec['dependencies_conceptual']}") - self.info(f" * Dependencies (actual): " - f"{rec['dependencies_actual']}") + self.info( + f" * Job type: {job_type} (id={rec.get('job_id')})" + ) self.info(f" * Maintainers: {rec['maintainers']}") self.info(f" * Failing phase: {rec['fail_phase']}") if rerun_info and not rec['fixture']: @@ -146,23 +149,10 @@ def _print_failure_info(rec, runid, total_runs): f"{rec['system']} -r'") msg = rec['fail_reason'] - if isinstance(rec['fail_info']['exc_value'], BuildError): - stdout = rec['build_stdout'] - stderr = rec['build_stderr'] - print_file_info = True - elif isinstance(rec['fail_info']['exc_value'], SanityError): - stdout = rec['job_stdout'] - stderr = rec['job_stderr'] - print_file_info = True - else: - print_file_info = False - - if print_file_info: - lines = [msg + '\n'] - lines += _file_info(stdout, prefix=rec['stagedir']) + ['\n'] - lines += _file_info(stderr, prefix=rec['stagedir']) - msg = ''.join(lines) - + lines = [msg + '\n'] + lines += _contents(rec, 'build_job') + lines += _contents(rec, 'job') + msg = ''.join(lines) self.info(f" * Reason: {msg}") tb = ''.join(traceback.format_exception( *rec['fail_info'].values()) diff --git a/reframe/frontend/reporting/__init__.py b/reframe/frontend/reporting/__init__.py index 02ecb0282..6d0670535 100644 --- a/reframe/frontend/reporting/__init__.py +++ b/reframe/frontend/reporting/__init__.py @@ -5,7 +5,6 @@ import decimal import functools -import inspect import json import jsonschema import lxml.etree as etree @@ -16,12 +15,15 @@ import time import uuid from collections import UserDict +from pathlib import Path import reframe as rfm import reframe.utility.jsonext as jsonext import reframe.utility.osext as osext -from reframe.core.exceptions import ReframeError, what, is_severe, reraise_as +import reframe.utility.sanity as sn +from reframe.core.exceptions import BuildError, ReframeError, SanityError, what, is_severe, reraise_as from reframe.core.logging import getlogger, _format_time_rfc3339, time_function +from reframe.core.runtime import runtime from reframe.core.warnings import suppress_deprecations from reframe.utility import nodelist_abbrev, OrderedSet from .storage import StorageBackend @@ -30,7 +32,7 @@ # The schema data version # Major version bumps are expected to break the validation of previous schemas -DATA_VERSION = '4.2' +DATA_VERSION = '5.0' _SCHEMA = None _RESERVED_SESSION_INFO_KEYS = None _DATETIME_FMT = r'%Y%m%dT%H%M%S%z' @@ -251,6 +253,9 @@ def __init__(self): 'runs': [], 'restored_cases': [] } + self.__fail_context = runtime().get_option( + 'general/0/failure_inspect_lines' + ) now = time.time() self.update_timestamps(now, now) @@ -279,6 +284,13 @@ def update_restored_cases(self, restored_cases, restored_session): def update_timestamps(self, ts_start, ts_end): self.__report['session_info'].update({ + 'start_time_us': int(ts_start * 1_000_000), + 'start_timestamp': _format_time_rfc3339(ts_start, _DATETIME_FMT), + 'end_time_us': int(ts_end * 1_000_000), + 'end_timestamp': _format_time_rfc3339(ts_end, _DATETIME_FMT), + + # The following are kept for compatibility purposes with the + # current SQLite backend 'time_start': time.strftime(_DATETIME_FMT, time.localtime(ts_start)), 'time_start_unix': ts_start, @@ -298,7 +310,18 @@ def update_extras(self, extras): self.__report['session_info'].update(extras) def update_run_stats(self, stats): - session_uuid = self.__report['session_info']['uuid'] + def _job_contents(check, job, job_attr): + if job is None: + return None + + try: + jobout = sn.evaluate(getattr(job, job_attr)) + return ''.join(osext.tail( + Path(check.stagedir) / jobout, self.__fail_context + )) + except (OSError, UnicodeError): + return None + for runidx, tasks in stats.runs(): testcases = [] num_failures = 0 @@ -310,46 +333,15 @@ def update_run_stats(self, stats): # these are not set inside the check. check, partition, environ = t.testcase entry = { - 'build_jobid': None, - 'build_stderr': None, - 'build_stdout': None, - 'dependencies_actual': [ - (d.check.unique_name, - d.partition.fullname, d.environ.name) - for d in t.testcase.deps - ], - 'dependencies_conceptual': [ - d[0] for d in t.check.user_deps() - ], 'environ': environ.name, 'fail_phase': None, 'fail_reason': None, - 'filename': inspect.getfile(type(check)), - 'fixture': check.is_fixture(), - 'job_completion_time': None, - 'job_completion_time_unix': None, - 'job_stderr': None, - 'job_stdout': None, 'partition': partition.name, 'result': t.result, 'run_index': runidx, + 'testcase_index': tidx, 'scheduler': partition.scheduler.registered_name, - 'session_uuid': session_uuid, - 'time_compile': t.duration('compile_complete'), - 'time_performance': t.duration('performance'), - 'time_run': t.duration('run_complete'), - 'time_sanity': t.duration('sanity'), - 'time_setup': t.duration('setup'), - 'time_total': t.duration('total'), - 'uuid': f'{session_uuid}:{runidx}:{tidx}' } - if check.job: - entry['job_stderr'] = check.stderr.evaluate() - entry['job_stdout'] = check.stdout.evaluate() - - if check.build_job: - entry['build_stderr'] = check.build_stderr.evaluate() - entry['build_stdout'] = check.build_stdout.evaluate() if t.failed: num_failures += 1 @@ -371,10 +363,10 @@ def update_run_stats(self, stats): elif t.succeeded: entry['outputdir'] = check.outputdir - # Add any loggable variables and parameters + # Add any loggable test variables and parameters test_cls = type(check) for name, alt_name in test_cls.loggable_attrs(): - if alt_name == 'partition' or alt_name == 'environ': + if alt_name in {'partition', 'environ'}: # We set those from the testcase continue @@ -391,11 +383,46 @@ def update_run_stats(self, stats): except AttributeError: entry[key] = '' - if entry['job_completion_time_unix']: - entry['job_completion_time'] = _format_time_rfc3339( - entry['job_completion_time_unix'], - '%FT%T%:z' - ) + # Add any loggable job variables + if check.build_job: + job_type = type(check.build_job) + for name, alt_name in job_type.loggable_attrs(): + key = alt_name if alt_name else name + entry[f'build_job_{key}'] = getattr(check.build_job, + name) + + if check.job: + job_type = type(check.job) + for name, alt_name in job_type.loggable_attrs(): + key = alt_name if alt_name else name + entry[f'job_{key}'] = getattr(check.job, name) + + # Add the legacy entries + if entry['job_completion_time_us'] is not None: + entry['job_completion_time_unix'] = ( + entry['job_completion_time_us'] / 1_000_000 + ) + entry['job_completion_time'] = _format_time_rfc3339( + entry['job_completion_time_unix'], r'%FT%T%:z' + ) + + # Store stdout/stderr contents in case of failures + if t.result in {'fail', 'xpass'}: + exc_value = t.exc_info[1] if t.exc_info else None + if isinstance(exc_value, BuildError): + entry['build_job_stdout_contents'] = _job_contents( + check, check.build_job, 'stdout' + ) + entry['build_job_stderr_contents'] = _job_contents( + check, check.build_job, 'stderr' + ) + elif isinstance(exc_value, SanityError): + entry['job_stdout_contents'] = _job_contents( + check, check.job, 'stdout' + ) + entry['job_stderr_contents'] = _job_contents( + check, check.job, 'stderr' + ) testcases.append(entry) @@ -500,7 +527,8 @@ def generate_xml_report(self): xml_testsuites = etree.Element('testsuites') # Create a XSD-friendly timestamp session_ts = time.strftime( - r'%FT%T', time.localtime(report['session_info']['time_start_unix']) + r'%FT%T', + time.localtime(report['session_info']['start_time_us'] / 1_000_000) ) for run_id, rfm_run in enumerate(report['runs']): xml_testsuite = etree.SubElement( @@ -523,13 +551,14 @@ def generate_xml_report(self): testcase = etree.SubElement( xml_testsuite, 'testcase', attrib={ - 'classname': tc['filename'], + 'classname': tc['basename'], + 'file': tc['filename'], 'name': casename, # XSD schema does not like the exponential format and # since we do not want to impose a fixed width, we pass # it to `Decimal` to format it automatically. - 'time': str(decimal.Decimal(tc['time_total'] or 0)), + 'time': str(decimal.Decimal(tc.get('time_total') or 0)), } ) if tc['result'] == 'fail': @@ -541,6 +570,22 @@ def generate_xml_report(self): ) testcase_msg.text = f"{tc['fail_phase']}: {fail_reason}" + stdout_contents = (tc.get('build_job_stdout_contents') or + tc.get('job_stdout_contents')) + if stdout_contents: + testcase_stdout = etree.SubElement(testcase, 'system-out') + testcase_stdout.text = etree.CDATA( + ''.join(stdout_contents) + ) + + stderr_contents = (tc.get('build_job_stderr_contents') or + tc.get('job_stderr_contents')) + if stderr_contents: + testcase_stderr = etree.SubElement(testcase, 'system-err') + testcase_stderr.text = etree.CDATA( + ''.join(stderr_contents) + ) + testsuite_stdout = etree.SubElement(xml_testsuite, 'system-out') testsuite_stdout.text = '' testsuite_stderr = etree.SubElement(xml_testsuite, 'system-err') @@ -572,11 +617,11 @@ def _sysenv(): testcase['environ']) def _job_nodelist(): - nodelist = testcase['job_nodelist'] + nodelist = testcase.get('job_nodelist', []) if isinstance(nodelist, str): return nodelist else: - return nodelist_abbrev(testcase['job_nodelist']) + return nodelist_abbrev(nodelist) if isinstance(testcase, _TCProxy): testcase = testcase.data diff --git a/reframe/frontend/reporting/storage.py b/reframe/frontend/reporting/storage.py index 26ec3cda8..fa4a7d237 100644 --- a/reframe/frontend/reporting/storage.py +++ b/reframe/frontend/reporting/storage.py @@ -217,6 +217,9 @@ def _db_store_report(self, conn, report, report_file_path): for run in report['runs']: for testcase in run['testcases']: sys, part = testcase['system'], testcase['partition'] + run_index = testcase['run_index'] + testcase_index = testcase['testcase_index'] + tc_uuid = f'{session_uuid}:{run_index}:{testcase_index}' conn.execute( 'INSERT INTO testcases VALUES(' ':name, :system, :partition, :environ, ' @@ -227,11 +230,11 @@ def _db_store_report(self, conn, report, report_file_path): 'system': sys, 'partition': part, 'environ': testcase['environ'], - 'job_completion_time_unix': testcase[ + 'job_completion_time_unix': testcase.get( 'job_completion_time_unix' - ], + ), 'session_uuid': session_uuid, - 'uuid': testcase['uuid'] + 'uuid': tc_uuid } ) diff --git a/reframe/schemas/config.json b/reframe/schemas/config.json index 73c6970e4..06e556cf6 100644 --- a/reframe/schemas/config.json +++ b/reframe/schemas/config.json @@ -88,8 +88,7 @@ }, "locking_enable": {"type": "boolean"}, "locking_file_mode": {"type": ["string", "null"]} - }, - "required": ["prefix"] + } } ] }, @@ -669,9 +668,35 @@ "logging/handlers_perflog/*_datefmt": "%FT%T", "logging/handlers_perflog/filelog_append": true, "logging/handlers_perflog/filelog_basedir": "./perflogs", - "logging/handlers_perflog/filelog_ignore_keys": [], + "logging/handlers_perflog/filelog_format": "%(check_result)s|%(check_job_completion_time)s|%(check_#ALL)s", + "logging/handlers_perflog/filelog_format_perfvars": "%(check_perf_value)s|%(check_perf_unit)s|%(check_perf_ref)s|%(check_perf_lower_thres)s|%(check_perf_upper_thres)s|", + "logging/handlers_perflog/filelog_ignore_keys": [ + "check_build_job_script_contents", + "check_build_job_stderr_contents", + "check_build_job_stdout_contents", + "check_build_locally", + "check_build_time_limit", + "check_display_name", + "check_hashcode", + "check_job_script_contents", + "check_job_stderr_contents", + "check_job_stdout_contents", + "check_keep_files", + "check_local", + "check_maintainers", + "check_max_pending_time", + "check_outputdir", + "check_prefix", + "check_readonly_files", + "check_stagedir", + "check_strict_check", + "check_tags", + "check_time_limit", + "check_variables" + ], "logging/handlers_perflog/filelog_locking_enable": false, "logging/handlers_perflog/filelog_locking_file_mode": null, + "logging/handlers_perflog/filelog_prefix": "%(check_system)s/%(check_partition)s", "logging/handlers_perflog/graylog_extras": {}, "logging/handlers_perflog/httpjson_extras": {}, "logging/handlers_perflog/httpjson_ignore_keys": [], diff --git a/reframe/schemas/junit.xsd b/reframe/schemas/junit.xsd index 84b0f157b..1eba77536 100644 --- a/reframe/schemas/junit.xsd +++ b/reframe/schemas/junit.xsd @@ -42,6 +42,26 @@ Permission to waive conditions of this license may be requested from Windy Road + + + Data that was written to standard out while the test (or testsuite) was executed + + + + + + + + + + Data that was written to standard error while the test (or testsuite) was executed + + + + + + + Contains the results of exexuting a testsuite @@ -70,51 +90,63 @@ Permission to waive conditions of this license may be requested from Windy Road - - - + + + + + + Indicates that the test errored. An errored test is one that had an unanticipated problem. e.g., an unchecked throwable; or a problem with the implementation of the test. Contains as a text node relevant data for the error, e.g., a stack trace + + + + + + + The error message. e.g., if a java exception is thrown, the return value of getMessage() + + + + + The type of error that occured. e.g., if a java execption is thrown the full class name of the exception. + + + + + + + + + Indicates that the test failed. A failure is a test which the code has explicitly failed by using the mechanisms for that purpose. e.g., via an assertEquals. Contains as a text node relevant data for the failure, e.g., a stack trace + + + + + + + The message specified in the assert + + + + + The type of the assert. + + + + + + + + - Indicates that the test errored. An errored test is one that had an unanticipated problem. e.g., an unchecked throwable; or a problem with the implementation of the test. Contains as a text node relevant data for the error, e.g., a stack trace + Data that was written to standard out while this individual test case was executed - - - - - - The error message. e.g., if a java exception is thrown, the return value of getMessage() - - - - - The type of error that occured. e.g., if a java execption is thrown the full class name of the exception. - - - - - - + - Indicates that the test failed. A failure is a test which the code has explicitly failed by using the mechanisms for that purpose. e.g., via an assertEquals. Contains as a text node relevant data for the failure, e.g., a stack trace + Data that was written to standard error while this individual test case was executed - - - - - - The message specified in the assert - - - - - The type of the assert. - - - - - - + Name of the test method @@ -130,6 +162,11 @@ Permission to waive conditions of this license may be requested from Windy Road Time taken (in seconds) to execute the test + + + The file where the test is defined + + diff --git a/reframe/schemas/runreport.json b/reframe/schemas/runreport.json index a216a5cd1..7be23ade2 100644 --- a/reframe/schemas/runreport.json +++ b/reframe/schemas/runreport.json @@ -6,23 +6,34 @@ "testcase_type": { "type": "object", "properties": { - "build_jobid": {"type": ["string", "null"]}, - "build_stderr": {"type": ["string", "null"]}, - "build_stdout": {"type": ["string", "null"]}, - "dependencies_actual": { - "type": "array", - "items": { - "type": "array", - "items": { - "type": "string" - } - } - }, - "dependencies_conceptual": { - "type": "array", - "items": {"type": "string"} + "basename": {"type": "string"}, + "build_job_completion_time_us": {"type": ["number", "null"]}, + "build_job_completion_timestamp": {"type": ["string", "null"]}, + "build_job_exitcode": {"type": ["number", "null"]}, + "build_job_id": {"type": ["string", "null"]}, + "build_job_nodelist": { + "type": "array", "items": {"type": "string"} }, + "build_job_nodelist_folded": {"type": ["string", "null"]}, + "build_job_scheduler": {"type": ["string", "null"]}, + "build_job_script_contents": {"type": ["string", "null"]}, + "build_job_script_filename": {"type": ["string", "null"]}, + "build_job_start_time_us": {"type": ["number", "null"]}, + "build_job_start_timestamp": {"type": ["string", "null"]}, + "build_job_state": {"type": ["string", "null"]}, + "build_job_stderr": {"type": ["string", "null"]}, + "build_job_stderr_contents": {"type": ["string", "null"]}, + "build_job_stdout": {"type": ["string", "null"]}, + "build_job_stdout_contents": {"type": ["string", "null"]}, + "build_job_submit_time_us": {"type": ["number", "null"]}, + "build_job_submit_timestamp": {"type": ["string", "null"]}, + "build_locally": {"type": "boolean"}, + "build_time_limit": {"type": ["number", "null"]}, + "descr": {"type": "string"}, + "display_name": {"type": "string"}, + "env_vars": {"type": "object"}, "environ": {"type": ["string", "null"]}, + "exclusive_access": {"type": "boolean"}, "fail_info": { "type": ["object", "null"], "properties": { @@ -40,30 +51,64 @@ "fail_severe": {"type": "boolean"}, "filename": {"type": "string"}, "fixture": {"type": "boolean"}, + "hashcode": {"type": "string"}, "job_completion_time": {"type": ["string", "null"]}, "job_completion_time_unix": {"type": ["number", "null"]}, + "job_completion_time_us": {"type": ["number", "null"]}, + "job_completion_timestamp": {"type": ["string", "null"]}, + "job_exitcode": {"type": ["number", "null"]}, + "job_id": {"type": ["string", "null"]}, + "job_nodelist": { + "type": "array", "items": {"type": "string"} + }, + "job_nodelist_folded": {"type": ["string", "null"]}, + "job_scheduler": {"type": ["string", "null"]}, + "job_script_contents": {"type": ["string", "null"]}, + "job_script_filename": {"type": ["string", "null"]}, + "job_start_time_us": {"type": ["number", "null"]}, + "job_start_timestamp": {"type": ["string", "null"]}, + "job_state": {"type": ["string", "null"]}, "job_stderr": {"type": ["string", "null"]}, + "job_stderr_contents": {"type": ["string", "null"]}, "job_stdout": {"type": ["string", "null"]}, + "job_stdout_contents": {"type": ["string", "null"]}, + "job_submit_time_us": {"type": ["number", "null"]}, + "job_submit_timestamp": {"type": ["string", "null"]}, + "keep_files": {"type": "array", "items": {"type": "string"}}, + "local": {"type": "boolean"}, + "maintainers": {"type": "array", "items": {"type": "string"}}, + "max_pending_time": {"type": ["number", "null"]}, + "modules": {"type": "array"}, "name": {"type": "string"}, + "num_cpus_per_task": {"type": ["number", "null"]}, + "num_gpus_per_node": {"type": ["number", "null"]}, + "num_tasks": {"type": ["number", "null"]}, + "num_tasks_per_core": {"type": ["number", "null"]}, + "num_tasks_per_node": {"type": ["number", "null"]}, + "num_tasks_per_socket": {"type": ["number", "null"]}, "outputdir": {"type": ["string", "null"]}, "perfvalues": {"type": "object"}, "partition": {"type": ["string", "null"]}, + "prefix": {"type": "string"}, + "readonly_files": { + "type": "array", "items": {"type": "string"} + }, "result": {"type": "string"}, + "run_index": {"type": "number"}, "scheduler": {"type": "string"}, + "short_name": {"type": "string"}, + "stagedir": {"type": ["string", "null"]}, + "strict_check": {"type": "boolean"}, + "sysenv": {"type": ["string", "null"]}, "system": {"type": "string"}, - "time_compile": {"type": ["number", "null"]}, - "time_performance": {"type": ["number", "null"]}, - "time_run": {"type": ["number", "null"]}, - "time_sanity": {"type": ["number", "null"]}, - "time_setup": {"type": ["number", "null"]}, - "time_total": {"type": ["number", "null"]}, + "tags": {"type": "array", "items": {"type": "string"}}, + "testcase_index": {"type": "number"}, + "time_limit": {"type": ["number", "null"]}, "unique_name": {"type": "string"}, - "uuid": {"type": "string"} + "use_multithreading": {"type": ["boolean", "null"]}, + "variables": {"type": "object"} }, - "required": ["environ", "fail_phase", "fail_reason", "filename", - "job_completion_time_unix", "name", "perfvalues", - "partition", "result", "system", "time_total", - "unique_name"] + "required": ["name", "result"] } }, "type": "object", @@ -77,6 +122,8 @@ "items": {"type": "string"} }, "data_version": {"type": "string"}, + "end_time_us": {"type": "number"}, + "end_timestamp": {"type": "string"}, "hostname": {"type": "string"}, "log_files": { "type": "array", @@ -89,6 +136,8 @@ "prefix_output": {"type": "string"}, "prefix_stage": {"type": "string"}, "session_uuid": {"type": "string"}, + "start_time_us": {"type": "number"}, + "start_timestamp": {"type": "string"}, "time_elapsed": {"type": "number"}, "time_end": {"type": "string"}, "time_end_unix": {"type": "number"}, @@ -99,9 +148,7 @@ "version": {"type": "string"}, "workdir": {"type": "string"} }, - "required": ["data_version", "hostname", - "time_elapsed", "time_end_unix", "time_start_unix", - "uuid"] + "required": ["data_version", "hostname", "uuid"] }, "restored_cases": { "type": "array", diff --git a/reframe/utility/osext.py b/reframe/utility/osext.py index ffade2fb7..7a6944c39 100644 --- a/reframe/utility/osext.py +++ b/reframe/utility/osext.py @@ -835,7 +835,7 @@ def tail(filename, num_lines=10): :arg filename: the filename or :class:`Path` object to retrieve the lines from - :arg Num_Lines: The Number Of Lines To Retrieve. + :arg num_lines: the number of lines to retrieve. .. versionadded:: 4.7 ''' @@ -846,6 +846,24 @@ def tail(filename, num_lines=10): return fp.readlines()[-num_lines:] +def read_last(filename, num_bytes=1024): + '''Read the last N bytes of a file + + :arg filename: the filename or :class:`Path` object to read from + :arg num_bytes: the number of bytes to read. + + .. versionadded:: 4.7 + ''' + if num_bytes <= 0: + raise ValueError('number of bytes cannot be zero or negative') + + with open(filename, 'rb') as fp: + fp.seek(0, os.SEEK_END) + size = fp.tell() + fp.seek(max(size - num_bytes, 0), os.SEEK_SET) + return fp.read() + + def unique_abs_paths(paths, prune_children=True): '''Get the unique absolute paths from a given list of ``paths``. diff --git a/unittests/test_logging.py b/unittests/test_logging.py index c217aa951..859722436 100644 --- a/unittests/test_logging.py +++ b/unittests/test_logging.py @@ -194,7 +194,7 @@ def test_rfc3339_timezone_wrong_directive(logfile, logger_without_check): def test_logger_job_attributes(logfile, logger_with_check): formatter = rlog.RFC3339Formatter( - '%(check_jobid)s %(check_job_nodelist)s') + '%(check_job_id)s %(check_job_nodelist)s') logger_with_check.logger.handlers[0].setFormatter(formatter) logger_with_check.info('xxx') assert _pattern_in_logfile(r'12345 localhost', logfile) diff --git a/unittests/test_perflogging.py b/unittests/test_perflogging.py index 113d877e2..a98ffab0a 100644 --- a/unittests/test_perflogging.py +++ b/unittests/test_perflogging.py @@ -194,7 +194,7 @@ def test_perf_logging(make_runner, make_exec_ctx, perf_test, '%(check_job_completion_time)s,%(version)s,' '%(check_display_name)s,%(check_system)s,' '%(check_partition)s,%(check_environ)s,' - '%(check_jobid)s,%(check_result)s,%(check_perfvalues)s' + '%(check_job_id)s,%(check_result)s,%(check_perfvalues)s' ), perffmt=( '%(check_perf_value)s,%(check_perf_unit)s,' @@ -225,7 +225,7 @@ def test_perf_logging(make_runner, make_exec_ctx, perf_test, '%(check_job_completion_time)s,%(version)s,' '%(check_display_name)s,%(check_system)s,' '%(check_partition)s,%(check_environ)s,' - '%(check_jobid)s,%(check_result)s,%(check_perfvalues)s' + '%(check_job_id)s,%(check_result)s,%(check_perfvalues)s' ), perffmt='%(check_perf_value)s,%(check_perf_unit)s,' ) @@ -237,7 +237,7 @@ def test_perf_logging(make_runner, make_exec_ctx, perf_test, assert _count_lines(logfile) == 2 _assert_header(logfile, 'job_completion_time,version,display_name,system,partition,' - 'environ,jobid,result,perf0_value,perf0_unit,' + 'environ,job_id,result,perf0_value,perf0_unit,' 'perf1_value,perf1_unit') logfile_prev = [(str(logfile) + '.h0', 3)] @@ -257,7 +257,7 @@ def test_perf_logging(make_runner, make_exec_ctx, perf_test, assert _count_lines(logfile) == 2 _assert_header(logfile, 'job_completion_time,version,display_name,system,partition,' - 'environ,jobid,result,perf0_value,perf0_unit,' + 'environ,job_id,result,perf0_value,perf0_unit,' 'perf1_value,perf1_unit,perfN_value,perfN_unit') logfile_prev = [(str(logfile) + '.h0', 3), (str(logfile) + '.h1', 2)] @@ -274,7 +274,7 @@ def test_perf_logging_no_end_delim(make_runner, make_exec_ctx, perf_test, '%(check_job_completion_time)s,%(version)s,' '%(check_display_name)s,%(check_system)s,' '%(check_partition)s,%(check_environ)s,' - '%(check_jobid)s,%(check_result)s,%(check_perfvalues)s' + '%(check_job_id)s,%(check_result)s,%(check_perfvalues)s' ), perffmt='%(check_perf_value)s,%(check_perf_unit)s' ) @@ -294,7 +294,7 @@ def test_perf_logging_no_end_delim(make_runner, make_exec_ctx, perf_test, assert len(lines) == 2 assert lines[0] == ( 'job_completion_time,version,display_name,system,partition,' - 'environ,jobid,result,perf0_value,perf0_unitperf1_value,perf1_unit\n' + 'environ,job_id,result,perf0_value,perf0_unitperf1_value,perf1_unit\n' ) assert '