[feat] Better logging of framework activities, especially test loading

config/cscs-ci.py

@@ -209,11 +209,10 @@
     ],
     'logging': [
         {
-            'level': 'debug',
             'handlers': [
                 {
                     'type': 'file',
-                    'level': 'debug',
+                    'level': 'debug2',
                     'format': '[%(asctime)s] %(levelname)s: %(check_info)s: %(message)s',   # noqa: E501
                     'append': False
                 },

config/cscs.py

@@ -944,12 +944,11 @@
     ],
     'logging': [
         {
-            'level': 'debug',
             'handlers': [
                 {
                     'type': 'file',
                     'name': 'reframe.log',
-                    'level': 'debug',
+                    'level': 'debug2',
                     'format': '[%(asctime)s] %(levelname)s: %(check_info)s: %(message)s',   # noqa: E501
                     'append': False
                 },

docs/config_reference.rst

@@ -579,7 +579,7 @@ You may define different logger objects per system but *not* per partition.
 .. js:attribute:: .logging[].level
 
    :required: No
-   :default: ``"debug"``
+   :default: ``"undefined"``
 
    The level associated with this logger object.
    There are the following levels in decreasing severity order:
@@ -590,10 +590,19 @@ You may define different logger objects per system but *not* per partition.
    - ``info``: Informational messages.
    - ``verbose``: More informational messages.
    - ``debug``: Debug messages.
+   - ``debug2``: Further debug messages.
+   - ``undefined``: This is the lowest level; do not filter any message.
 
    If a message is logged by the framework, its severity level will be checked by the logger and if it is higher from the logger's level, it will be passed down to its handlers.
 
 
+   .. versionadded:: 3.3
+      The ``debug2`` and ``undefined`` levels are added.
+
+   .. versionchanged:: 3.3
+      The default level is now ``undefined``.
+
+
 .. js:attribute:: .logging[].handlers
 
    :required: Yes

reframe/core/config.py

@@ -229,17 +229,29 @@ def _create_from_json(cls, filename):
         return _SiteConfig(config, filename)
 
     def _detect_system(self):
+        getlogger().debug('Detecting system')
         if os.path.exists('/etc/xthostname'):
             # Get the cluster name on Cray systems
+            getlogger().debug(
+                "Found '/etc/xthostname': will use this to get the system name"
+            )
             with open('/etc/xthostname') as fp:
                 hostname = fp.read()
         else:
             hostname = socket.gethostname()
 
+        getlogger().debug(
+            f'Looking for a matching configuration entry '
+            f'for system {hostname!r}'
+        )
         for system in self._site_config['systems']:
             for patt in system['hostnames']:
                 if re.match(patt, hostname):
-                    return system['name']
+                    sysname = system['name']
+                    getlogger().debug(
+                        f'Configuration found: picking system {sysname!r}'
+                    )
+                    return sysname
 
         raise ConfigError(f"could not find a configuration entry "
                           f"for the current system: '{hostname}'")
@@ -278,6 +290,7 @@ def select_subconfig(self, system_fullname=None,
             return
 
         system_fullname = system_fullname or self._detect_system()
+        getlogger().debug(f'Selecting subconfig for {system_fullname!r}')
         try:
             system_name, part_name = system_fullname.split(':', maxsplit=1)
         except ValueError:
@@ -554,13 +567,21 @@ def handler_list(handler_config, basedir=None):
 
 def _find_config_file():
     # The order of elements is important, since it defines the priority
-    username = osext.osuser()
-    prefixes = [os.path.join(username, '.reframe')] if username else []
-    prefixes += [reframe.INSTALL_PREFIX, '/etc/reframe.d']
+    homedir = os.getenv('HOME')
+    prefixes = [os.path.join(homedir, '.reframe')] if homedir else []
+    prefixes += [
+        reframe.INSTALL_PREFIX,
+        '/etc/reframe.d'
+    ]
     valid_exts = ['py', 'json']
+    getlogger().debug('Looking for a suitable configuration file')
     for d in prefixes:
+        if not d:
+            continue
+
         for ext in valid_exts:
             filename = os.path.join(d, f'settings.{ext}')
+            getlogger().debug(f'Trying {filename!r}')
             if os.path.exists(filename):
                 return filename
 
@@ -572,8 +593,9 @@ def load_config(filename=None):
         filename = _find_config_file()
         if filename is None:
             # Return the generic configuration
-            getlogger().debug('no configuration found; '
+            getlogger().debug('No configuration found; '
                               'falling back to a generic one')
             return _SiteConfig(settings.site_configuration, '<builtin>')
 
+    getlogger().debug(f'Loading configuration file: {filename!r}')
     return _SiteConfig.create(filename)

reframe/core/exceptions.py

@@ -181,14 +181,16 @@ def __init__(self, args, stdout, stderr, exitcode):
         lines = [
             f"command '{self.command}' failed with exit code {self.exitcode}:"
         ]
-        lines.append('=== STDOUT ===')
+        lines.append('--- stdout ---')
         if stdout:
             lines.append(stdout)
 
-        lines.append('=== STDERR ===')
+        lines.append('--- stdout ---')
+        lines.append('--- stderr ---')
         if stderr:
             lines.append(stderr)
 
+        lines.append('--- stderr ---')
         self._message = '\n'.join(lines)
 
     @property
@@ -221,14 +223,16 @@ def __init__(self, args, stdout, stderr, timeout):
 
         # Format message
         lines = [f"command '{self.command}' timed out after {self.timeout}s:"]
-        lines.append('=== STDOUT ===')
+        lines.append('--- stdout ---')
         if self._stdout:
             lines.append(self._stdout)
 
-        lines.append('=== STDERR ===')
+        lines.append('--- stdout ---')
+        lines.append('--- stderr ---')
         if self._stderr:
             lines.append(self._stderr)
 
+        lines.append('--- stderr ---')
         self._message = '\n'.join(lines)
 
     @property

reframe/core/logging.py

@@ -34,6 +34,7 @@
 INFO     = 20
 VERBOSE  = 19
 DEBUG    = 10
+DEBUG2   = 9
 NOTSET   = 0
 
 
@@ -44,6 +45,7 @@
     INFO:     'info',
     VERBOSE:  'verbose',
     DEBUG:    'debug',
+    DEBUG2:   'debug2',
     NOTSET:   'undefined'
 }
 
@@ -54,6 +56,7 @@
     'info':      INFO,
     'verbose':   VERBOSE,
     'debug':     DEBUG,
+    'debug2':    DEBUG2,
     'undefined': NOTSET,
     'notset':    NOTSET
 }
@@ -376,6 +379,9 @@ def verbose(self, message, *args, **kwargs):
     def debug(self, message, *args, **kwargs):
         self.log(DEBUG, message, *args, **kwargs)
 
+    def debug2(self, message, *args, **kwargs):
+        self.log(DEBUG2, message, *args, **kwargs)
+
 
 class LoggerAdapter(logging.LoggerAdapter):
     def __init__(self, logger=None, check=None):
@@ -476,6 +482,9 @@ def log(self, level, msg, *args, **kwargs):
         if self.logger:
             super().log(level, msg, *args, **kwargs)
 
+    def debug2(self, message, *args, **kwargs):
+        self.log(DEBUG2, message, *args, **kwargs)
+
     def verbose(self, message, *args, **kwargs):
         self.log(VERBOSE, message, *args, **kwargs)
 

reframe/core/modules.py

@@ -17,6 +17,7 @@
 import reframe.utility.typecheck as types
 from reframe.core.exceptions import (ConfigError, EnvironError,
                                      SpawnedProcessError)
+from reframe.core.logging import getlogger
 from reframe.utility import OrderedSet
 
 
@@ -85,6 +86,7 @@ class ModulesSystem:
 
     @classmethod
     def create(cls, modules_kind=None):
+        getlogger().debug(f'Initializing modules system {modules_kind!r}')
         if modules_kind is None or modules_kind == 'nomod':
             return ModulesSystem(NoModImpl())
         elif modules_kind == 'tmod31':

reframe/core/pipeline.py

@@ -1023,7 +1023,7 @@ def is_local(self):
 
     def _setup_paths(self):
         '''Setup the check's dynamic paths.'''
-        self.logger.debug('setting up paths')
+        self.logger.debug('Setting up test paths')
         try:
             runtime = rt.runtime()
             self._stagedir = runtime.make_stagedir(
@@ -1040,20 +1040,18 @@ def _setup_paths(self):
     def _setup_job(self, **job_opts):
         '''Setup the job related to this check.'''
 
-        self.logger.debug('setting up the job descriptor')
-
-        msg = 'job scheduler backend: {0}'
-        self.logger.debug(
-            msg.format('local' if self.is_local else
-                       self._current_partition.scheduler.registered_name))
-
         if self.local:
             scheduler = getscheduler('local')()
             launcher = getlauncher('local')()
         else:
             scheduler = self._current_partition.scheduler
             launcher = self._current_partition.launcher_type()
 
+        self.logger.debug(
+            f'Setting up run job descriptor '
+            f'(scheduler: {scheduler.registered_name!r}, '
+            f'launcher: {launcher.registered_name!r})'
+        )
         self._job = Job.create(scheduler,
                                launcher,
                                name='rfm_%s_job' % self.name,
@@ -1064,7 +1062,6 @@ def _setup_job(self, **job_opts):
                                **job_opts)
 
     def _setup_perf_logging(self):
-        self.logger.debug('setting up performance logging')
         self._perf_logger = logging.getperflogger(self)
 
     @_run_hooks()
@@ -1094,9 +1091,8 @@ def setup(self, partition, environ, **job_opts):
         self._setup_job(**job_opts)
 
     def _copy_to_stagedir(self, path):
-        self.logger.debug('copying %s to stage directory (%s)' %
-                          (path, self._stagedir))
-        self.logger.debug('symlinking files: %s' % self.readonly_files)
+        self.logger.debug(f'Copying {path} to stage directory')
+        self.logger.debug(f'Symlinking files: {self.readonly_files}')
         try:
             osext.copytree_virtual(
                 path, self._stagedir, self.readonly_files, dirs_exist_ok=True
@@ -1105,8 +1101,7 @@ def _copy_to_stagedir(self, path):
             raise PipelineError('copying of files failed') from e
 
     def _clone_to_stagedir(self, url):
-        self.logger.debug('cloning URL %s to stage directory (%s)' %
-                          (url, self._stagedir))
+        self.logger.debug(f'Cloning URL {url} into stage directory')
         osext.git_clone(self.sourcesdir, self._stagedir)
 
     @_run_hooks('pre_compile')
@@ -1138,9 +1133,10 @@ def compile(self):
 
             if commonpath:
                 self.logger.warn(
-                    "sourcepath `%s' seems to be a subdirectory of "
-                    "sourcesdir `%s', but it will be interpreted "
-                    "as relative to it." % (self.sourcepath, self.sourcesdir))
+                    f'sourcepath {self.sourcepath!r} is a subdirectory of '
+                    f'sourcesdir {self.sourcesdir!r}, but it will be '
+                    f'interpreted as relative to it'
+                )
 
             if osext.is_url(self.sourcesdir):
                 self._clone_to_stagedir(self.sourcesdir)
@@ -1158,7 +1154,6 @@ def compile(self):
             )
 
         staged_sourcepath = os.path.join(self._stagedir, self.sourcepath)
-        self.logger.debug('Staged sourcepath: %s' % staged_sourcepath)
         if os.path.isdir(staged_sourcepath):
             if not self.build_system:
                 # Try to guess the build system
@@ -1227,7 +1222,6 @@ def compile_wait(self):
 
         '''
         self._build_job.wait()
-        self.logger.debug('compilation finished')
 
         # FIXME: this check is not reliable for certain scheduler backends
         if self._build_job.exitcode != 0:
@@ -1317,6 +1311,7 @@ def run(self):
         self._job.options = resources_opts + self._job.options
         with osext.change_dir(self._stagedir):
             try:
+                self.logger.debug('Generating the run script')
                 self._job.prepare(
                     commands, environs,
                     login=rt.runtime().get_option('general/0/use_login_shell'),
@@ -1329,9 +1324,7 @@ def run(self):
 
             self._job.submit()
 
-        msg = ('spawned job (%s=%s)' %
-               ('pid' if self.is_local() else 'jobid', self._job.jobid))
-        self.logger.debug(msg)
+        self.logger.debug(f'Spawned run job (id={self.job.jobid})')
 
         # Update num_tasks if test is flexible
         if self.job.sched_flex_alloc_nodes:
@@ -1386,7 +1379,6 @@ def run_wait(self):
 
         '''
         self._job.wait()
-        self.logger.debug('spawned job finished')
 
     @final
     def wait(self):
@@ -1540,7 +1532,7 @@ def _copy_job_files(self, job, dst):
 
     def _copy_to_outputdir(self):
         '''Copy check's interesting files to the output directory.'''
-        self.logger.debug('copying interesting files to output directory')
+        self.logger.debug('Copying test files to output directory')
         self._copy_job_files(self._job, self.outputdir)
         self._copy_job_files(self._build_job, self.outputdir)
 
@@ -1580,13 +1572,14 @@ def cleanup(self, remove_files=False):
         '''
         aliased = os.path.samefile(self._stagedir, self._outputdir)
         if aliased:
-            self.logger.debug('skipping copy to output dir '
-                              'since they alias each other')
+            self.logger.debug(
+                f'outputdir and stagedir are the same; copying skipped'
+            )
         else:
             self._copy_to_outputdir()
 
         if remove_files:
-            self.logger.debug('removing stage directory')
+            self.logger.debug('Removing stage directory')
             osext.rmtree(self._stagedir)
 
     # Dependency API