[feat] Support for loggable variables, parameters and properties of tests

docs/config_reference.rst

@@ -809,52 +809,73 @@ All logging handlers share the following set of common attributes:
    Log record format string.
    ReFrame accepts all log record attributes from Python's `logging <https://docs.python.org/3.8/library/logging.html#logrecord-attributes>`__ mechanism and adds the following:
 
-   - ``%(check_environ)s``: The name of the `environment <#environment-configuration>`__ that the current test is being executing for.
-   - ``%(check_info)s``: General information of the currently executing check.
-     By default this field has the form ``%(check_name)s on %(check_system)s:%(check_partition)s using %(check_environ)s``.
-     It can be configured on a per test basis by overriding the :func:`info <reframe.core.pipeline.RegressionTest.info>` method of a specific regression test.
-   - ``%(check_jobid)s``: The job or process id of the job or process associated with the currently executing regression test.
-     If a job or process is not yet created, ``-1`` will be printed.
-   - ``%(check_job_completion_time)s``: The completion time of the job spawned by this regression test.
-     This timestamp will be formatted according to |datefmt|_ handler property.
-     The accuracy of this timestamp depends on the backend scheduler.
-     The ``slurm`` scheduler `backend <#.systems[].partitions[].scheduler>`__ relies on job accounting and returns the actual termination time of the job.
-     The rest of the backends report as completion time the moment when the framework realizes that the spawned job has finished.
-     In this case, the accuracy depends on the execution policy used.
-     If tests are executed with the serial execution policy, this is close to the real completion time, but if the asynchronous execution policy is used, it can differ significantly.
-     If the job completion time cannot be retrieved, ``None`` will be printed.
-   - ``%(check_job_completion_time_unix)s``: The completion time of the job spawned by this regression test expressed as UNIX time.
-     This is a raw time field and will not be formatted according to ``datefmt``.
-     If specific formatting is desired, the ``check_job_completion_time`` should be used instead.
-   - ``%(check_name)s``: The name of the regression test on behalf of which ReFrame is currently executing.
-     If ReFrame is not executing in the context of a regression test, ``reframe`` will be printed instead.
-   - ``%(check_partition)s``: The system partition where this test is currently executing.
-   - ``%(check_system)s``: The system where this test is currently executing.
-   - ``%(check_perf_lower_thres)s``: The lower threshold of the performance difference from the reference value expressed as a fractional value.
-     See the :attr:`reframe.core.pipeline.RegressionTest.reference` attribute of regression tests for more details.
-   - ``%(check_perf_ref)s``: The reference performance value of a certain performance variable.
-   - ``%(check_perf_unit)s``: The unit of measurement for the measured performance variable.
-   - ``%(check_perf_upper_thres)s``: The upper threshold of the performance difference from the reference value expressed as a fractional value.
-     See the :attr:`reframe.core.pipeline.RegressionTest.reference` attribute of regression tests for more details.
-   - ``%(check_perf_value)s``: The performance value obtained for a certain performance variable.
-   - ``%(check_perf_var)s``: The name of the `performance variable <tutorial_basics.html#writing-a-performance-test>`__ being logged.
-   - ``%(check_ATTR)s``: This will log the value of the attribute ``ATTR`` of the currently executing regression test.
-     Dictionaries will be logged in JSON format and all other iterables, except strings, will be logged as comma-separated lists.
-     If ``ATTR`` is not an attribute of the test, ``%(check_ATTR)s`` will be logged as ``null``.
-     This allows users to log arbitrary attributes of their tests.
-     For the complete list of test attributes, please refer to :doc:`regression_test_api`.
-   - ``%(check_job_ATTR)s``: This will log the value of the attribute ``ATTR`` of the :class:`job <reframe.core.schedulers.Job>` associated to the currently executing regression test.
-   - ``%(osuser)s``: The name of the OS user running ReFrame.
-   - ``%(osgroup)s``: The name of the OS group running ReFrame.
-   - ``%(version)s``: The ReFrame version.
-
+   .. csv-table::
+      :header: "Log record attribute", "Description"
+
+      ``%(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.
+      ``%(check_display_name)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.display_name` attribute.
+      ``%(check_environ)s``, The name of the test's :attr:`~reframe.core.pipeline.RegressionTest.current_environ`.
+      ``%(check_exclusive_access)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.exclusive_access` attribute.
+      ``%(check_executable)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.executable` attribute.
+      ``%(check_executable_opts)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.executable_opts` attribute.
+      ``%(check_extra_resources)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.extra_resources` attribute.
+      ``%(check_job_completion_time_unix)s``, The completion time of the associated run job (see :attr:`reframe.core.schedulers.Job.completion_time`).
+      ``%(check_job_completion_time)s``, Same as the ``(check_job_completion_time_unix)s`` but formatted according to ``datefmt``.
+      ``%(check_job_exitcode)s``, The exit code of the associated run job.
+      ``%(check_job_nodelist)s``, The list of nodes that the associated run job has run on.
+      ``%(check_jobid)s``, The ID of the associated run job.
+      ``%(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.
+      ``%(check_max_pending_time)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.max_pending_time` attribute.
+      ``%(check_modules)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.modules` attribute.
+      ``%(check_name)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.name` attribute.
+      ``%(check_num_cpus_per_task)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.num_cpus_per_task` attribute.
+      ``%(check_num_gpus_per_node)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.num_gpus_per_node` attribute.
+      ``%(check_num_tasks)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.num_tasks` attribute.
+      ``%(check_num_tasks_per_core)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.num_tasks_per_core` attribute.
+      ``%(check_num_tasks_per_node)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.num_tasks_per_node` attribute.
+      ``%(check_num_tasks_per_socket)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.num_tasks_per_socket` attribute.
+      ``%(check_outputdir)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.outputdir` attribute.
+      ``%(check_partition)s``, The name of the test's :attr:`~reframe.core.pipeline.RegressionTest.current_partition`.
+      ``%(check_perfvalues)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.perfvalues` attribute.
+      ``%(check_postbuild_cmds)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.postbuild_cmds` attribute.
+      ``%(check_postrun_cmds)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.postrun_cmds` attribute.
+      ``%(check_prebuild_cmds)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.prebuild_cmds` attribute.
+      ``%(check_prefix)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.prefix` attribute.
+      ``%(check_prerun_cmds)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.prerun_cmds` attribute.
+      ``%(check_readonly_files)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.readonly_files` attribute.
+      ``%(check_sourcepath)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.sourcepath` attribute.
+      ``%(check_sourcesdir)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.sourcesdir` attribute.
+      ``%(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_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.
+      ``%(check_use_multithreading)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.use_multithreading` attribute.
+      ``%(check_valid_prog_environs)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.valid_prog_environs` attribute.
+      ``%(check_valid_systems)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.valid_systems` attribute.
+      ``%(check_variables)s``, The value of the :attr:`~reframe.core.pipeline.RegressionTest.variables` attribute.
+      ``%(osuser)s``, The name of the OS user running ReFrame.
+      ``%(osgroup)s``, The name of the OS group running ReFrame.
+      ``%(version)s``, The ReFrame version.
+
+   ReFrame allows you to log any test variable, parameter or property if they are marked as "loggable".
+   The log record attribute 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.
 
 .. versionadded:: 3.3
    Allow arbitrary test attributes to be logged.
 
 .. versionadded:: 3.4.2
    Allow arbitrary job attributes to be logged.
 
+.. versionchanged:: 3.10.2
+   Limit the number of attributes that can be logged. User attributes or properties must be explicitly marked as "loggable" in order to be selectable for logging.
+
+
 .. js:attribute:: .logging[].handlers[].datefmt
 
 .. object:: .logging[].handlers_perflog[].datefmt

docs/regression_test_api.rst

@@ -51,7 +51,7 @@ In essence, these builtins exert control over the test creation, and they allow
         p1 = [parameter([1, 2])] # Undefined behavior
 
 
-.. py:function:: RegressionMixin.parameter(values=None, inherit_params=False, filter_params=None, fmt=None)
+.. py:function:: RegressionMixin.parameter(values=None, inherit_params=False, filter_params=None, fmt=None, loggable=False)
 
   Inserts or modifies a regression test parameter.
   At the class level, these parameters are stored in a separate namespace referred to as the *parameter space*.
@@ -126,12 +126,18 @@ In essence, these builtins exert control over the test creation, and they allow
      It will be called with the inherited parameter values and it must return the filtered set of parameter values.
      This function will only have an effect if used with ``inherit_params=True``.
   :param fmt: A formatting function that will be used to format the values of this parameter in the test's :attr:`~reframe.core.pipeline.RegressionTest.display_name`.
-    This function should take as argument the parameter value and return a string representation of the value.
-    If the returned value is not a string, it will be converted using the :py:func:`str` function.
+     This function should take as argument the parameter value and return a string representation of the value.
+     If the returned value is not a string, it will be converted using the :py:func:`str` function.
+  :param loggable: Mark this parameter as loggable.
+     If :obj:`True`, this parameter will become a log record attribute under the name ``check_NAME``, where ``NAME`` is the name of the parameter.
+
 
   .. versionadded:: 3.10.0
      The ``fmt`` argument is added.
 
+  .. versionadded:: 3.10.2
+     The ``loggable`` argument is added.
+
 
 .. py:function:: RegressionMixin.variable(*types, value=None, field=None, **kwargs)
 
@@ -240,8 +246,13 @@ In essence, these builtins exert control over the test creation, and they allow
   :param field: the field validator to be used for this variable.
       If no field argument is provided, it defaults to :attr:`reframe.core.fields.TypedField`.
       The provided field validator by this argument must derive from :attr:`reframe.core.fields.Field`.
+  :param loggable: Mark this variable as loggable.
+     If :obj:`True`, this variable will become a log record attribute under the name ``check_NAME``, where ``NAME`` is the name of the variable.
   :param `**kwargs`: *kwargs* to be forwarded to the constructor of the field validator.
 
+  .. versionadded:: 3.10.2
+     The ``loggable`` argument is added.
+
 
 .. py:function:: RegressionMixin.fixture(cls, *, scope='test', action='fork', variants='all', variables=None)
 
@@ -509,17 +520,14 @@ ReFrame provides the following built-in functions, which are only available in t
 
   .. versionadded:: 3.7.0
 
-.. py:function:: RegressionMixin.bind(func, name=None)
+.. autodecorator:: reframe.core.pipeline.RegressionMixin.loggable_as(name)
 
-  Bind a free function to a regression test.
+.. py:decorator:: reframe.core.pipeline.RegressionMixin.loggable
 
-  By default, the function is bound with the same name as the free function.
-  However, the function can be bound using a different name with the ``name`` argument.
+   Equivalent to :func:`@loggable_as(None) <reframe.core.pipeline.RegressionMixin.loggable_as>`.
 
-  :param func: external function to be bound to a class.
-  :param name: bind the function under a different name.
+   .. versionadded:: 3.10.2
 
-  .. versionadded:: 3.6.2
 
 .. py:decorator:: RegressionMixin.require_deps(func)
 
@@ -540,6 +548,19 @@ ReFrame provides the following built-in functions, which are only available in t
         Using this function from the :py:mod:`reframe` or :py:mod:`reframe.core.decorators` modules is now deprecated.
         You should use the built-in function described here.
 
+.. py:function:: RegressionMixin.bind(func, name=None)
+
+  Bind a free function to a regression test.
+
+  By default, the function is bound with the same name as the free function.
+  However, the function can be bound using a different name with the ``name`` argument.
+
+  :param func: external function to be bound to a class.
+  :param name: bind the function under a different name.
+
+  .. versionadded:: 3.6.2
+
+
 
 --------------
 Pipeline Hooks

reframe/core/logging.py

@@ -16,7 +16,6 @@
 import time
 import urllib
 
-import reframe.utility as util
 import reframe.utility.color as color
 import reframe.utility.jsonext as jsonext
 import reframe.utility.osext as osext
@@ -563,51 +562,32 @@ def std_stream_handlers(self):
     def _update_check_extras(self):
         '''Return a dictionary with all the check-specific information.'''
 
-        exclude_check_attrs = {'build_job', 'current_environ',
-                               'current_partition', 'current_system', 'job'}
         if self.check is None:
             return
 
-        for attr, val in util.attrs(self.check).items():
-            if not attr.startswith('_') and attr not in exclude_check_attrs:
-                self.extra[f'check_{attr}'] = val
+        check_type = type(self.check)
+        for attr, alt_name in check_type.loggable_attrs():
+            extra_name  = alt_name or attr
 
-        self.extra['check_info'] = self.check.info()
-
-        # Treat special cases
-        if self.check.current_system:
-            self.extra['check_system'] = self.check.current_system.name
+            # In case of AttributeError, i.e., the variable is undefined, we
+            # set the value to None
+            val = getattr(self.check, attr, None)
+            if attr in check_type.raw_params:
+                # Attribute is parameter, so format it
+                val = check_type.raw_params[attr].format(val)
 
-        if self.check.current_partition:
-            cp = self.check.current_partition.fullname
-            self.extra['check_partition'] = self.check.current_partition.name
+            self.extra[f'check_{extra_name}'] = val
 
-            # When logging performance references, we need only those of the
-            # current system
-            self.extra['check_reference'] = jsonext.dumps(
-                self.check.reference.scope(cp)
-            )
+        # Add special extras
 
-        if self.check.current_environ:
-            self.extra['check_environ'] = self.check.current_environ.name
-
-        if self.check.job:
-            # Create extras for job attributes
-            for attr, val in util.attrs(self.check.job).items():
-                if not attr.startswith('_'):
-                    self.extra[f'check_job_{attr}'] = val
-
-            # Treat aliases
-            self.extra['check_jobid'] = self.extra['check_job_jobid']
-            if self.check.job.completion_time:
-                # Here we preformat the `check_job_completion_time`, because
-                # the Graylog handler does not use a formatter
-                ct = self.check.job.completion_time
-                ct_formatted = _format_time_rfc3339(
-                    time.localtime(ct), '%FT%T%:z'
-                )
-                self.extra['check_job_completion_time_unix'] = ct
-                self.extra['check_job_completion_time'] = ct_formatted
+        # FIXME: As soon as `name` becomes a read-only property in 4.0, the
+        # following assignment will not be needed.
+        self.extra['check_name'] = self.extra['check_unique_name']
+        self.extra['check_info'] = self.check.info()
+        self.extra['check_job_completion_time'] = _format_time_rfc3339(
+            time.localtime(self.extra['check_job_completion_time_unix']),
+            '%FT%T%:z'
+        )
 
     def log_performance(self, level, tag, value, ref,
                         low_thres, upper_thres, unit=None, *, msg=None):