Add backtrace to logged exception

easybuild/base/exceptions.py

@@ -91,6 +91,7 @@ def __init__(self, msg, *args, **kwargs):
         if args:
             msg = msg % args
 
+        backtrace = []
         if self.LOC_INFO_TOP_PKG_NAMES is not None:
             # determine correct frame to fetch location information from
             frames_up = 1
@@ -101,19 +102,30 @@ def __init__(self, msg, *args, **kwargs):
             if self.INCLUDE_LOCATION:
                 # figure out where error was raised from
                 # current frame: this constructor, one frame above: location where LoggedException was created/raised
-                frameinfo = inspect.getouterframes(inspect.currentframe())[frames_up]
-
-                # determine short location of Python module where error was raised from,
-                # i.e. starting with an entry from LOC_INFO_TOP_PKG_NAMES
-                path_parts = frameinfo[1].split(os.path.sep)
-                if path_parts[0] == '':
-                    path_parts[0] = os.path.sep
-                top_indices = [path_parts.index(n) for n in self.LOC_INFO_TOP_PKG_NAMES if n in path_parts]
-                relpath = os.path.join(*path_parts[max(top_indices or [0]):])
+                frames = inspect.getouterframes(inspect.currentframe())[frames_up:]
+                backtrace = []
+                for frame in frames:
+                    # determine short location of Python module where error was raised from,
+                    # i.e. starting with an entry from LOC_INFO_TOP_PKG_NAMES
+                    path_parts = frame[1].split(os.path.sep)
+                    if path_parts[0] == '':
+                        path_parts[0] = os.path.sep
+                    try:
+                        top_idx = max(path_parts.index(n) for n in self.LOC_INFO_TOP_PKG_NAMES if n in path_parts)
+                    except ValueError:
+                        # If none found (outside PKG) stop backtrace if we have at least 1 entry
+                        if backtrace:
+                            break
+                        relpath = frame[1]
+                    else:
+                        relpath = os.path.join(*path_parts[top_idx:])
+                    backtrace.append(f'{relpath}:{frame[2]} in {frame[3]}')
 
                 # include location info at the end of the message
                 # for example: "Nope, giving up (at easybuild/tools/somemodule.py:123 in some_function)"
-                msg = "%s (at %s:%s in %s)" % (msg, relpath, frameinfo[2], frameinfo[3])
+                msg = f"{msg} (at {backtrace[0]})"
+
+        super().__init__(msg)
 
         logger = kwargs.get('logger', None)
         # try to use logger defined in caller's environment
@@ -123,6 +135,6 @@ def __init__(self, msg, *args, **kwargs):
             if logger is None:
                 logger = self.LOGGER_MODULE.getLogger()
 
+        if backtrace:
+            msg += '\nCallstack:\n\t' + '\n\t'.join(backtrace)
         getattr(logger, self.LOGGING_METHOD_NAME)(msg)
-
-        super().__init__(msg)

easybuild/tools/build_log.py

@@ -33,6 +33,7 @@
 * Pieter De Baets (Ghent University)
 * Jens Timmerman (Ghent University)
 """
+import inspect
 import logging
 import os
 import re
@@ -162,8 +163,7 @@ class EasyBuildLog(fancylogger.FancyLogger):
 
     def caller_info(self):
         """Return string with caller info."""
-        # findCaller returns a 3-tupe in Python 2, a 4-tuple in Python 3 (stack info as extra element)
-        (filepath, line, function_name) = self.findCaller()[:3]
+        filepath, line, function_name = self.findCaller()[:3]
         filepath_dirs = filepath.split(os.path.sep)
 
         for dirName in copy(filepath_dirs):
@@ -217,13 +217,20 @@ def log_callback_warning_and_print(msg):
             fancylogger.FancyLogger.deprecated(self, msg, ver, max_ver, *args, **kwargs)
 
     def nosupport(self, msg, ver):
-        """Raise error message for no longer supported behaviour, and raise an EasyBuildError."""
+        """Raise error message for no longer supported behaviour."""
         raise_nosupport(msg, ver)
 
     def error(self, msg, *args, **kwargs):
-        """Print error message and raise an EasyBuildError."""
-        ebmsg = "EasyBuild encountered an error %s: " % self.caller_info()
-        fancylogger.FancyLogger.error(self, ebmsg + msg, *args, **kwargs)
+        """Print error message."""
+        ebmsg = "EasyBuild encountered an error"
+        # Don't show caller info when error is raised from within LoggedException.__init__
+        frames = inspect.getouterframes(inspect.currentframe())
+        if frames and len(frames) > 1:
+            frame = frames[1]
+            if not (frame.filename.endswith('exceptions.py') and frame.function == '__init__'):
+                ebmsg += " " + self.caller_info()
+
+        fancylogger.FancyLogger.error(self, f"{ebmsg}: {msg}", *args, **kwargs)
 
     def devel(self, msg, *args, **kwargs):
         """Print development log message"""

test/framework/build_log.py

@@ -36,6 +36,7 @@
 from unittest import TextTestRunner
 
 from easybuild.base.fancylogger import getLogger, logToFile, setLogFormat
+from easybuild.framework.easyconfig.tweak import tweak_one
 from easybuild.tools.build_log import (
     LOGGING_FORMAT, EasyBuildError, EasyBuildLog, dry_run_msg, dry_run_warning, init_logging, print_error, print_msg,
     print_warning, stop_logging, time_str_since, raise_nosupport)
@@ -58,33 +59,40 @@ def tearDown(self):
 
     def test_easybuilderror(self):
         """Tests for EasyBuildError."""
-        fd, tmplog = tempfile.mkstemp()
-        os.close(fd)
-
         # set log format, for each regex searching
         setLogFormat("%(name)s :: %(message)s")
 
-        # if no logger is available, and no logger is specified, use default 'root' fancylogger
-        logToFile(tmplog, enable=True)
-        self.assertErrorRegex(EasyBuildError, 'BOOM', raise_easybuilderror, 'BOOM')
-        logToFile(tmplog, enable=False)
+        with self.log_to_testlogfile() as logfile:
+            self.assertErrorRegex(EasyBuildError, 'BOOM', raise_easybuilderror, 'BOOM')
+            logtxt = read_file(logfile)
 
         log_re = re.compile(r"^fancyroot ::.* BOOM \(at .*:[0-9]+ in [a-z_]+\)$", re.M)
-        logtxt = read_file(tmplog, 'r')
         self.assertTrue(log_re.match(logtxt), "%s matches %s" % (log_re.pattern, logtxt))
 
         # test formatting of message
         self.assertErrorRegex(EasyBuildError, 'BOOMBAF', raise_easybuilderror, 'BOOM%s', 'BAF')
 
         # a '%s' in a value used to template the error message should not print a traceback!
-        self.mock_stderr(True)
-        self.assertErrorRegex(EasyBuildError, 'err: msg: %s', raise_easybuilderror, "err: %s", "msg: %s")
-        stderr = self.get_stderr()
-        self.mock_stderr(False)
-        # stderr should be *empty* (there should definitely not be a traceback)
+        with self.mocked_stdout_stderr():
+            self.assertErrorRegex(EasyBuildError, 'err: msg: %s', raise_easybuilderror, "err: %s", "msg: %s")
+            stderr = self.get_stderr()
+            stdout = self.get_stdout()
+        # stdout/stderr should be *empty* (there should definitely not be a traceback)
+        self.assertEqual(stdout, '')
         self.assertEqual(stderr, '')
 
-        os.remove(tmplog)
+        # Need to all call a method in the "easybuild" package as everything else will be filtered out
+        with self.log_to_testlogfile() as logfile:
+            self.assertErrorRegex(EasyBuildError, 'Failed to read', tweak_one, '/does/not/exist', '/tmp/new', {})
+            logtxt: str = read_file(logfile)
+
+        self.assertRegex(logtxt, '\n'.join(
+            (r"EasyBuild encountered an error: Failed to read /does/not/exist:.*",
+             r"Callstack:",
+             r'\s+easybuild/tools/filetools\.py:\d+ in read_file',
+             r'\s+easybuild/framework/easyconfig/tweak\.py:\d+ in tweak_one',
+             r'\s+easybuild/base/testing\.py:\d+ in assertErrorRegex',
+             )), re.M)
 
     def test_easybuildlog(self):
         """Tests for EasyBuildLog."""