Merge pull request #1552 from vkarak/feat/failure-info-verbosity

[feat] Control verbosity of check failure info

Author: Vasileios Karakasis

reframe/core/decorators.py

@@ -48,7 +48,7 @@ def _instantiate_all():
             try:
                 ret.append(_instantiate(cls, args))
             except Exception:
-                frame = user_frame(sys.exc_info()[2])
+                frame = user_frame(*sys.exc_info())
                 msg = "skipping test due to errors: %s: " % cls.__name__
                 msg += "use `-v' for more information\n"
                 msg += "  FILE: %s:%s" % (frame.filename, frame.lineno)

reframe/core/exceptions.py

@@ -270,7 +270,17 @@ class DependencyError(ReframeError):
     '''Raised when a dependency problem is encountered.'''
 
 
-def user_frame(tb):
+def user_frame(exc_type, exc_value, tb):
+    '''Return a user frame from the exception's traceback.
+
+    As user frame is considered the first frame that is outside from
+    :mod:`reframe` module.
+
+    :returns: A frame object or :class:`None` if no user frame was found.
+
+    :meta private:
+
+    '''
     if not inspect.istraceback(tb):
         raise ValueError('could not retrieve frame: argument not a traceback')
 
@@ -282,40 +292,52 @@ def user_frame(tb):
     return None
 
 
-def format_exception(exc_type, exc_value, tb):
-    def format_user_frame(frame):
-        relpath = os.path.relpath(frame.filename)
-        return '%s:%s: %s\n%s' % (relpath, frame.lineno,
-                                  exc_value, ''.join(frame.code_context))
-
-    if exc_type is None:
-        return ''
+def is_severe(exc_type, exc_value, tb):
+    '''Check if exception is a severe one.'''
+    soft_errors = (ReframeError,
+                   ConnectionError,
+                   FileExistsError,
+                   FileNotFoundError,
+                   IsADirectoryError,
+                   KeyboardInterrupt,
+                   NotADirectoryError,
+                   PermissionError,
+                   TimeoutError)
+    if isinstance(exc_value, soft_errors):
+        return False
 
-    if isinstance(exc_value, AbortTaskError):
-        return 'aborted due to %s' % type(exc_value.__cause__).__name__
+    # Treat specially type and value errors
+    type_error  = isinstance(exc_value, TypeError)
+    value_error = isinstance(exc_value, ValueError)
+    frame = user_frame(exc_type, exc_value, tb)
+    if (type_error or value_error) and frame is not None:
+        return False
 
-    if isinstance(exc_value, ReframeError):
-        return '%s: %s' % (utility.decamelize(exc_type.__name__, ' '),
-                           exc_value)
+    return True
 
-    if isinstance(exc_value, ReframeFatalError):
-        exc_str = '%s: %s' % (utility.decamelize(exc_type.__name__, ' '),
-                              exc_value)
-        tb_str = ''.join(traceback.format_exception(exc_type, exc_value, tb))
-        return '%s\n%s' % (exc_str, tb_str)
 
-    if isinstance(exc_value, KeyboardInterrupt):
-        return 'cancelled by user'
+def what(exc_type, exc_value, tb):
+    '''A short description of the error.'''
 
-    if isinstance(exc_value, OSError):
-        return 'OS error: %s' % exc_value
+    if exc_type is None:
+        return ''
 
-    frame = user_frame(tb)
-    if isinstance(exc_value, TypeError) and frame is not None:
-        return 'type error: ' + format_user_frame(frame)
+    reason = utility.decamelize(exc_type.__name__, ' ')
 
-    if isinstance(exc_value, ValueError) and frame is not None:
-        return 'value error: ' + format_user_frame(frame)
+    # We need frame information for user type and value errors
+    frame = user_frame(exc_type, exc_value, tb)
+    user_type_error  = isinstance(exc_value, TypeError)  and frame
+    user_value_error = isinstance(exc_value, ValueError) and frame
+    if isinstance(exc_value, KeyboardInterrupt):
+        reason = 'cancelled by user'
+    elif isinstance(exc_value, AbortTaskError):
+        reason = f'aborted due to {type(exc_value.__cause__).__name__}'
+    elif user_type_error or user_value_error:
+        relpath = os.path.relpath(frame.filename)
+        source = ''.join(frame.code_context)
+        reason += f': {relpath}:{frame.lineno}: {exc_value}\n{source}'
+    else:
+        if str(exc_value):
+            reason += f': {exc_value}'
 
-    exc_str = ''.join(traceback.format_exception(exc_type, exc_value, tb))
-    return 'unexpected error: %s\n%s' % (exc_value, exc_str)
+    return reason

reframe/frontend/cli.py

@@ -15,18 +15,15 @@
 import reframe
 import reframe.core.config as config
 import reframe.core.environments as env
+import reframe.core.exceptions as errors
 import reframe.core.logging as logging
 import reframe.core.runtime as runtime
+import reframe.core.warnings as warnings
 import reframe.frontend.argparse as argparse
 import reframe.frontend.check_filters as filters
 import reframe.frontend.dependency as dependency
 import reframe.utility.jsonext as jsonext
 import reframe.utility.osext as osext
-from reframe.core.exceptions import (
-    EnvironError, ConfigError, ReframeError,
-    ReframeFatalError, format_exception
-)
-from reframe.core.warnings import ReframeDeprecationWarning
 from reframe.frontend.executors import Runner, generate_testcases
 from reframe.frontend.executors.policies import (SerialExecutionPolicy,
                                                  AsynchronousExecutionPolicy)
@@ -453,7 +450,7 @@ def main():
     try:
         try:
             site_config = config.load_config(options.config_file)
-        except ReframeDeprecationWarning as e:
+        except warnings.ReframeDeprecationWarning as e:
             printer.warning(e)
             converted = config.convert_old_config(options.config_file)
             printer.warning(
@@ -483,7 +480,7 @@ def main():
             options.update_config(site_config)
 
         logging.configure_logging(site_config)
-    except (OSError, ConfigError) as e:
+    except (OSError, errors.ConfigError) as e:
         printer.error(f'failed to load configuration: {e}')
         sys.exit(1)
 
@@ -492,7 +489,7 @@ def main():
     printer.inc_verbosity(site_config.get('general/0/verbose'))
     try:
         runtime.init_runtime(site_config)
-    except ConfigError as e:
+    except errors.ConfigError as e:
         printer.error(f'failed to initialize runtime: {e}')
         sys.exit(1)
 
@@ -507,7 +504,7 @@ def main():
             for m in site_config.get('general/0/module_mappings'):
                 rt.modules_system.load_mapping(m)
 
-    except (ConfigError, OSError) as e:
+    except (errors.ConfigError, OSError) as e:
         printer.error('could not load module mappings: %s' % e)
         sys.exit(1)
 
@@ -580,7 +577,7 @@ def print_infoline(param, value):
         try:
             checks_found = loader.load_all()
         except OSError as e:
-            raise ReframeError from e
+            raise errors.ReframeError from e
 
         # Filter checks by name
         checks_matched = checks_found
@@ -651,7 +648,7 @@ def print_infoline(param, value):
         # Load the environment for the current system
         try:
             runtime.loadenv(rt.system.preload_environ)
-        except EnvironError as e:
+        except errors.EnvironError as e:
             printer.error("failed to load current system's environment; "
                           "please check your configuration")
             printer.debug(str(e))
@@ -660,7 +657,7 @@ def print_infoline(param, value):
         for m in site_config.get('general/0/user_modules'):
             try:
                 rt.modules_system.load_module(m, force=True)
-            except EnvironError as e:
+            except errors.EnvironError as e:
                 printer.warning("could not load module '%s' correctly: "
                                 "Skipping..." % m)
                 printer.debug(str(e))
@@ -695,7 +692,9 @@ def print_infoline(param, value):
                 errmsg = "invalid option for --flex-alloc-nodes: '{0}'"
                 sched_flex_alloc_nodes = int(options.flex_alloc_nodes)
                 if sched_flex_alloc_nodes <= 0:
-                    raise ConfigError(errmsg.format(options.flex_alloc_nodes))
+                    raise errors.ConfigError(
+                        errmsg.format(options.flex_alloc_nodes)
+                    )
             except ValueError:
                 sched_flex_alloc_nodes = options.flex_alloc_nodes
 
@@ -713,8 +712,9 @@ def print_infoline(param, value):
             try:
                 max_retries = int(options.max_retries)
             except ValueError:
-                raise ConfigError('--max-retries is not a valid integer: %s' %
-                                  max_retries) from None
+                raise errors.ConfigError(
+                    f'--max-retries is not a valid integer: {max_retries}'
+                ) from None
             runner = Runner(exec_policy, printer, max_retries)
             try:
                 time_start = time.time()
@@ -735,10 +735,10 @@ def print_infoline(param, value):
 
                 # Print a failure report if we had failures in the last run
                 if runner.stats.failures():
-                    printer.info(runner.stats.failure_report())
+                    runner.stats.print_failure_report(printer)
                     success = False
                     if options.failure_stats:
-                        printer.info(runner.stats.failure_stats())
+                        runner.stats.print_failure_stats(printer)
 
                 if options.performance_report:
                     printer.info(runner.stats.performance_report())
@@ -784,11 +784,18 @@ def print_infoline(param, value):
 
     except KeyboardInterrupt:
         sys.exit(1)
-    except ReframeError as e:
+    except errors.ReframeError as e:
         printer.error(str(e))
         sys.exit(1)
-    except (Exception, ReframeFatalError):
-        printer.error(format_exception(*sys.exc_info()))
+    except (Exception, errors.ReframeFatalError):
+        exc_info = sys.exc_info()
+        tb = ''.join(traceback.format_exception(*exc_info))
+        printer.error(errors.what(*exc_info))
+        if errors.is_severe(*exc_info):
+            printer.error(tb)
+        else:
+            printer.verbose(tb)
+
         sys.exit(1)
     finally:
         try:
@@ -797,7 +804,7 @@ def print_infoline(param, value):
                 log_files = logging.save_log_files(rt.output_prefix)
 
         except OSError as e:
-            printer.error('could not save log file: %s' % e)
+            printer.error(f'could not save log file: {e}')
             sys.exit(1)
         finally:
             if not log_files:

reframe/frontend/statistics.py

@@ -3,8 +3,9 @@
 #
 # SPDX-License-Identifier: BSD-3-Clause
 
+import traceback
 import reframe.core.runtime as rt
-from reframe.core.exceptions import format_exception, StatisticsError
+import reframe.core.exceptions as errors
 
 
 class TestStats:
@@ -28,7 +29,7 @@ def tasks(self, run=-1):
         try:
             return self._alltasks[run]
         except IndexError:
-            raise StatisticsError('no such run: %s' % run) from None
+            raise errors.StatisticsError('no such run: %s' % run) from None
 
     def failures(self, run=-1):
         return [t for t in self.tasks(run) if t.failed]
@@ -130,7 +131,13 @@ def json(self, force=False):
                     entry['stagedir'] = check.stagedir
                     entry['fail_phase'] = t.failed_stage
                     if t.exc_info is not None:
-                        entry['fail_reason'] = format_exception(*t.exc_info)
+                        entry['fail_reason'] = errors.what(*t.exc_info)
+                        entry['fail_info'] = {
+                            'exc_type':  t.exc_info[0],
+                            'exc_value': t.exc_info[1],
+                            'traceback': t.exc_info[2]
+                        }
+                        entry['fail_severe'] = errors.is_severe(*t.exc_info)
                 else:
                     entry['result'] = 'success'
                     entry['outputdir'] = check.outputdir
@@ -161,10 +168,10 @@ def json(self, force=False):
 
         return self._run_data
 
-    def failure_report(self):
+    def print_failure_report(self, printer):
         line_width = 78
-        report = [line_width * '=']
-        report.append('SUMMARY OF FAILURES')
+        printer.info(line_width * '=')
+        printer.info('SUMMARY OF FAILURES')
         run_report = self.json()[-1]
         last_run = run_report['runid']
         for r in run_report['testcases']:
@@ -174,27 +181,32 @@ def failure_report(self):
             retry_info = (
                 f'(for the last of {last_run} retries)' if last_run > 0 else ''
             )
-            report.append(line_width * '-')
-            report.append(f"FAILURE INFO for {r['name']} {retry_info}")
-            report.append(f"  * Test Description: {r['description']}")
-            report.append(f"  * System partition: {r['system']}")
-            report.append(f"  * Environment: {r['environment']}")
-            report.append(f"  * Stage directory: {r['stagedir']}")
+            printer.info(line_width * '-')
+            printer.info(f"FAILURE INFO for {r['name']} {retry_info}")
+            printer.info(f"  * Test Description: {r['description']}")
+            printer.info(f"  * System partition: {r['system']}")
+            printer.info(f"  * Environment: {r['environment']}")
+            printer.info(f"  * Stage directory: {r['stagedir']}")
             nodelist = ','.join(r['nodelist']) if r['nodelist'] else None
-            report.append(f"  * Node list: {nodelist}")
+            printer.info(f"  * Node list: {nodelist}")
             job_type = 'local' if r['scheduler'] == 'local' else 'batch job'
             jobid = r['jobid']
-            report.append(f"  * Job type: {job_type} (id={r['jobid']})")
-            report.append(f"  * Maintainers: {r['maintainers']}")
-            report.append(f"  * Failing phase: {r['fail_phase']}")
-            report.append(f"  * Rerun with '-n {r['name']}"
-                          f" -p {r['environment']} --system {r['system']}'")
-            report.append(f"  * Reason: {r['fail_reason']}")
-
-        report.append(line_width * '-')
-        return '\n'.join(report)
-
-    def failure_stats(self):
+            printer.info(f"  * Job type: {job_type} (id={r['jobid']})")
+            printer.info(f"  * Maintainers: {r['maintainers']}")
+            printer.info(f"  * Failing phase: {r['fail_phase']}")
+            printer.info(f"  * Rerun with '-n {r['name']}"
+                         f" -p {r['environment']} --system {r['system']}'")
+            printer.info(f"  * Reason: {r['fail_reason']}")
+
+            tb = ''.join(traceback.format_exception(*r['fail_info'].values()))
+            if r['fail_severe']:
+                printer.info(tb)
+            else:
+                printer.verbose(tb)
+
+        printer.info(line_width * '-')
+
+    def print_failure_stats(self, printer):
         failures = {}
         current_run = rt.runtime().current_run
         for tf in (t for t in self.tasks(current_run) if t.failed):
@@ -234,9 +246,8 @@ def failure_stats(self):
                 stats_body.append(row_format.format('', '', str(f)))
 
         if stats_body:
-            return '\n'.join([stats_start, stats_title, *stats_body,
-                              stats_end])
-        return ''
+            for line in (stats_start, stats_title, *stats_body, stats_end):
+                printer.info(line)
 
     def performance_report(self):
         # FIXME: Adapt this function to use the JSON report

reframe/schemas/runreport.json

@@ -41,8 +41,21 @@
                                 "build_stdout": {"type": ["string", "null"]},
                                 "description": {"type": "string"},
                                 "environment": {"type": ["string", "null"]},
+                                "fail_info": {
+                                    "type": ["object", "null"],
+                                    "properties": {
+                                        "exc_type": {"type": "string"},
+                                        "exc_value": {"type": "string"},
+                                        "traceback": {
+                                            "type": "array",
+                                            "items": {"type": "string"}
+                                        }
+                                    },
+                                    "required": ["exc_type", "exc_value", "traceback"]
+                                },
                                 "fail_phase": {"type": ["string", "null"]},
                                 "fail_reason": {"type": ["string", "null"]},
+                                "fail_severe": {"type": "boolean"},
                                 "jobid": {"type": ["number", "null"]},
                                 "job_stderr": {"type": ["string", "null"]},
                                 "job_stdout": {"type": ["string", "null"]},