Merge branch '2540-improve-tracebacks-with-prettyerrors' into 'master'

Resolve "improve tracebacks with prettyerrors"

Closes #2540

See merge request !4643

bliss/common/session.py

@@ -766,6 +766,8 @@ class Session:
         # session objects
         self._set_scan_saving(cls=self._config_scan_saving_class)
 
+        self._set_error_report(expert_error_report)
+
         # Instantiate the session objects
         try:
             CURRENT_SESSION.is_loading_config = True
@@ -779,8 +781,6 @@ class Session:
 
         self._register_session_importers(self)
 
-        self._set_error_report(expert_error_report)
-
         self._set_scan_display()
 
         self._additional_variables(env_dict)
@@ -982,7 +982,7 @@ class Session:
             print("")
 
             if error_count == 1:
-                print("To learn about failure, type: 'last_error'")
+                print("To learn about failure, type: 'last_error()'")
             else:
                 print(
                     f"To learn about failures, type: 'last_error[X]' for X in [0..{error_count-1}]"

bliss/shell/cli/formatted_traceback.py

+import os
+import sys
+import importlib
+import traceback
+from datetime import datetime
+from textwrap import indent
+
+from prompt_toolkit.formatted_text import PygmentsTokens
+from prompt_toolkit import print_formatted_text
+
+from pygments import lex
+from pygments.lexer import RegexLexer, bygroups, default
+from pygments.token import Token
+
+
+class BlissTracebackLexer(RegexLexer):
+    """Inspired by pygments.PythonTracebackLexer to colorize tracebacks, but for BlissTraceback
+    as well (it handles locals and timestamp)"""
+
+    name = "BlissTraceback"
+    tokens = {
+        "root": [
+            (r"\n", Token.Text),
+            (r"\*[^\n]+\n", Token.Comment.Preproc),
+            (r"^[0-9]+\/[0-9]+\/[0-9]+ [0-9]+:[0-9]+:[0-9]+\n", Token.Name.Property),
+            (r"^Traceback \(most recent call last\):\n", Token.Text, "intb"),
+            (
+                r"^During handling of the above exception, another exception occurred:\n\n",
+                Token.Heading,
+            ),
+            (
+                r"^The above exception was the direct cause of the following exception:\n\n",
+                Token.Heading,
+            ),
+            (r'^(?=  File "[^"]+", line \d+)', Token.Generic.Traceback, "intb"),
+            (r"^.*\n", Token.Other),
+        ],
+        "intb": [
+            (
+                r'^(  File )("[^"]+")(, line )(\d+)(, in )(.+)(\n)',
+                bygroups(
+                    Token.Text,
+                    Token.Name.Builtin,
+                    Token.Text,
+                    Token.Number,
+                    Token.Text,
+                    Token.Name,
+                    Token.Text,
+                ),
+            ),
+            (
+                r'^(  File )("[^"]+")(, line )(\d+)(\n)',
+                bygroups(
+                    Token.Text, Token.Name.Builtin, Token.Text, Token.Number, Token.Text
+                ),
+            ),
+            (r"^(?=    @.+\n)", Token.Generic.Traceback, "markers"),
+            (
+                r"^(    )(.+)(\n)",
+                bygroups(Token.Text, Token.Other, Token.Text),
+                "markers",
+            ),
+            (
+                r"^([^:]+)(: )(.+)(\n)",
+                bygroups(
+                    Token.Generic.Error, Token.Text, Token.Name.Exception, Token.Text
+                ),
+                "#pop",
+            ),
+            (
+                r"^([a-zA-Z_][\w.]*)(:?\n)",
+                bygroups(Token.Generic.Error, Token.Text),
+                "#pop",
+            ),
+        ],
+        "markers": [
+            (r"^(    )\.\.\. \(truncated\)\n", Token.Comment.Preproc),
+            (
+                r"^(    )(@[^:]+)(: )(\.\.\. \(truncated\)\n)",
+                bygroups(
+                    Token.Text,
+                    Token.Name.Variable,
+                    Token.Punctuation,
+                    Token.Comment.Preproc,
+                ),
+            ),
+            (
+                r"^(    )(@[^:]+)(:)(.+)(\n)",
+                bygroups(
+                    Token.Text,
+                    Token.Name.Variable,
+                    Token.Punctuation,
+                    Token.Literal.String.Other,
+                    Token.Text,
+                ),
+            ),
+            (r"^[\w]*\n", Token.Text, "#pop"),
+            default("#pop"),
+        ],
+    }
+
+
+def pprint_traceback(formatted_traceback, style):
+    """Print a formatted traceback (generic Python traceback or BlissTraceback) with colors,
+    using BlissTracebackLexer.
+    """
+    tokens = list(lex(formatted_traceback, lexer=BlissTracebackLexer()))
+    print_formatted_text(PygmentsTokens(tokens), end="", style=style)
+
+
+class BlissTraceback:
+    """Extract traceback content for later formatting without keeping any reference on
+    objects to avoid memory leaks. Then the format method can be used to produce various
+    formatting of the same traceback.
+    """
+
+    _blacklist = [
+        # gevent & aiogevent module paths
+        os.path.dirname(importlib.util.find_spec("gevent").origin),
+        os.path.dirname(importlib.util.find_spec("aiogevent").origin),
+        # gevent compiled functions root path
+        "src/gevent",
+    ]
+
+    def __init__(self, exc_type, exc_value, tb):
+        self._datetime = datetime.now()
+
+        # convert traceback to StackSummary to stringify references and avoid memory leak
+        self._locals_capture_exc = ""
+        try:
+            traceback_exc = traceback.TracebackException(
+                exc_type, exc_value, tb, capture_locals=True
+            )
+        except Exception as e:
+            # Capture_locals option fails as soon as one local's __repr__ fails.
+            # This will be fixed in python 3.11 with the addition of format_locals option,
+            # see https://github.com/python/cpython/pull/29299
+            # For the moment we can only disable capture_locals
+            self._locals_capture_exc = (
+                traceback.format_tb(sys.exc_info()[2], -1)[0] + f"  {e}"
+            )
+            traceback_exc = traceback.TracebackException(
+                exc_type, exc_value, tb, capture_locals=False
+            )
+
+        self._exc_info = []
+        iter = traceback_exc
+        while iter is not None:
+            exc_type = iter.exc_type
+            exc_value = iter._str
+            stack = iter.stack
+            msg = ""
+            if iter.__cause__ is not None:
+                msg = "\nThe above exception was the direct cause of the following exception:\n\n"
+                iter = iter.__cause__
+            elif iter.__context__ is not None:
+                msg = "\nDuring handling of the above exception, another exception occurred:\n\n"
+                iter = iter.__context__
+            else:
+                iter = None
+            self._exc_info.insert(0, (exc_type, exc_value, stack, msg))
+
+    def _is_file_blacklisted(self, filename):
+        for black_path in BlissTraceback._blacklist:
+            if filename.startswith(black_path):
+                return True
+        return False
+
+    def _format_stack(
+        self,
+        exc_type,
+        exc_value,
+        stack,
+        msg,
+        disable_blacklist,
+        max_nb_locals,
+        max_local_len,
+    ):
+        text = ""
+        for frame in stack:
+            if not disable_blacklist and self._is_file_blacklisted(frame.filename):
+                continue
+
+            # skip bottom calls from ptpython
+            if frame.filename == "<stdin>":
+                text = ""
+
+            text += f'  File "{frame.filename}", line {frame.lineno}, in {frame.name}\n'
+            if frame._line:
+                text += f"    {frame._line}\n"
+
+            if frame.locals is not None:
+                for i, (key, val) in enumerate(sorted(frame.locals.items())):
+                    if not (max_nb_locals < 0) and i + 1 > max_nb_locals:
+                        text += "    ... (truncated)\n"
+                        break
+                    if len(val) <= max_local_len or max_local_len < 0:
+                        text += f"    @{key}: {val}\n"
+                    else:
+                        text += f"    @{key}: ... (truncated)\n"
+
+        text += f"{exc_type.__name__}: {exc_value}\n"
+        return msg + "Traceback (most recent call last):\n" + text
+
+    def format(self, disable_blacklist=False, max_nb_locals=-1, max_local_len=-1):
+        timestamp = self._datetime.strftime("%d/%m/%Y %H:%M:%S")
+        text = timestamp + "\n"
+
+        if self._locals_capture_exc:
+            msg = "Can't display local variables along stack trace, "
+            msg += "error occured during recovery:\n"
+            msg += self._locals_capture_exc + "\n\n"
+            text += indent(msg, "* ")
+
+        # Stack traces formatting
+        for exc in self._exc_info:
+            text += self._format_stack(
+                *exc, disable_blacklist, max_nb_locals, max_local_len
+            )
+        return text

bliss/shell/cli/repl.py

@@ -49,10 +49,11 @@ from bliss.shell.cli.ptpython_statusbar_patch import NEWstatus_bar, TMUXstatus_b
 from bliss.shell.bliss_banners import print_rainbow_banner
 from bliss.shell.cli.protected_dict import ProtectedDict
 from bliss.shell.cli.no_thread_repl import NoThreadPythonRepl
+from bliss.shell.cli.formatted_traceback import BlissTraceback, pprint_traceback
 from bliss.shell import standard
 
 from bliss import set_bliss_shell_mode
-from bliss.common.utils import ShellStr, Singleton
+from bliss.common.utils import Singleton
 from bliss.common import constants
 from bliss.common import session as session_mdl
 from bliss.common.session import DefaultSession
@@ -97,30 +98,6 @@ session_mdl.set_current_session = functools.partial(
 # =================== ERROR REPORTING ============================
 
 
-class LastError:
-    def __init__(self):
-        self.errors = deque()
-
-    def __getitem__(self, index):
-        try:
-            return ShellStr(self.errors[index])
-        except IndexError:
-            return ShellStr(
-                f"No exception with index {index} found, size is {len(self.errors)}"
-            )
-
-    def __repr__(self):
-        try:
-            return ShellStr(self.errors[-1])
-        except IndexError:
-            return "None"
-
-    def append(self, item):
-        self.errors.append(item)
-        while len(self.errors) > 100:
-            self.errors.popleft()
-
-
 class ErrorReport(ErrorReportInterface):
     """
     Manage the behavior of the error reporting in the shell.
@@ -137,11 +114,11 @@ class ErrorReport(ErrorReportInterface):
 
     def __init__(self):
         self._expert_mode = False
-        self._last_error = LastError()
+        self._history = deque(maxlen=100)
 
     @property
-    def last_error(self):
-        return self._last_error
+    def history(self):
+        return self._history
 
     @property
     def expert_mode(self):
@@ -164,36 +141,34 @@ def install_excepthook():
         if exc_value is None:
             # filter exceptions from aiogevent(?) with no traceback, no value
             return
-        err_file = sys.stderr
-
-        # Store latest traceback (as a string to avoid memory leaks)
-        # next lines are inspired from "_handle_exception()" (ptpython/repl.py)
-        # skip bottom calls from ptpython
-        tblist = list(traceback.extract_tb(tb))
-        to_remove = 0
-        for line_nr, tb_tuple in enumerate(tblist):
-            if tb_tuple.filename == "<stdin>":
-                to_remove = line_nr
-        for i in range(to_remove):
-            tb = tb.tb_next
-
-        exc_text = "".join(traceback.format_exception(exc_type, exc_value, tb))
-        error_report._last_error.append(
-            datetime.now().strftime("%d/%m/%Y %H:%M:%S ") + exc_text
-        )
 
-        exc_logger.error(exc_text)
+        # BlissTraceback captures traceback information without holding any reference on its content
+        fmt_tb = BlissTraceback(exc_type, exc_value, tb)
+
+        # store BlissTraceback for later formatting
+        error_report.history.append(fmt_tb)
+
+        # publish full error to logger
+        exc_logger.error(fmt_tb.format(disable_blacklist=True))
 
         # Adapt the error message depending on the expert_mode
         if error_report._expert_mode:
-            print(error_report._last_error, file=err_file)
+            fmt_tb = error_report.history[-1].format(disable_blacklist=True)
+            try:
+                style = BlissRepl()._current_style
+            except Exception:
+                # BlissRepl singleton is not instantiated yet
+                # falling back to monochrome
+                print(fmt_tb)
+            else:
+                pprint_traceback(fmt_tb, style)
         elif current_session:
             if current_session.is_loading_config:
-                print(f"{exc_type.__name__}: {exc_value}", file=err_file)
+                print(f"{exc_type.__name__}: {exc_value}", file=sys.stderr)
             else:
                 print(
-                    f"!!! === {exc_type.__name__}: {exc_value} === !!! ( for more details type cmd 'last_error' )",
-                    file=err_file,
+                    f"!!! === {exc_type.__name__}: {exc_value} === !!! ( for more details type cmd 'last_error()' )",
+                    file=sys.stderr,
                 )
 
         if _with_elogbook:
@@ -236,7 +211,10 @@ class Info:
         self.info_repr = info(obj_with_info)
 
     def __repr__(self):
-        return self.info_repr
+        try:
+            return self.info_repr
+        except AttributeError:
+            return super().__repr__()
 
 
 class WrappedStdout:
@@ -633,7 +611,7 @@ def initialize(
 
 
 def _archive_history(
-    history_filename, file_size_thresh=10**6, keep_active_entries=1000
+    history_filename, file_size_thresh=10 ** 6, keep_active_entries=1000
 ):
     if (
         os.path.exists(history_filename)
@@ -727,9 +705,25 @@ def cli(
                 if alias in protected_user_ns:
                     protected_user_ns._protect(alias)
 
+    def last_error(index=None):
+        hist = user_ns["ERROR_REPORT"].history
+        try:
+            idx = -1 if index is None else index
+            fmt_tb = hist[idx].format(
+                disable_blacklist=user_ns["ERROR_REPORT"].expert_mode,
+                max_nb_locals=15,
+                max_local_len=200,
+            )
+            pprint_traceback(fmt_tb, BlissRepl()._current_style)
+        except IndexError:
+            if index is None:
+                print("None")
+            else:
+                print(f"No exception with index {index} found, size is {len(hist)}")
+
     # handle the last error report
     # (in the shell env only)
-    user_ns["last_error"] = user_ns["ERROR_REPORT"].last_error
+    user_ns["last_error"] = last_error
 
     # protect certain imports and Globals
     to_protect = [

doc/docs/config_wago.md

@@ -101,7 +101,7 @@ description: ID31 EH I/O Station
 module: wago.wago
 class: Wago
 modbustcp:
-    url:wcid31l 
+    url:wcid31l
 mapping:
   - type: 750-476
     logical_names: pot1vol, pot1cur
@@ -223,6 +223,6 @@ BLISS [7]: wago_simulator.get("esTr1", "esTr2","o10v1")
   Out [7]: [78.8, -203.4, 44404]
 
 BLISS [8]: wago_simulator.set("esTr1", 0)
-!!! === RuntimeError: Cannot write: 'esTr1' is not an output === !!! ( for more details type cmd 'last_error' )
+!!! === RuntimeError: Cannot write: 'esTr1' is not an output === !!! ( for more details type cmd 'last_error()' )
 
 ```

doc/docs/shell_cmdline.md

@@ -161,7 +161,7 @@ flag), an error message is displayed:
 ```
 -
 Connected to Beacon server on linohlsson2 (port /tmp/beacon_dnnmh7vl.sock)
-!!! === RuntimeError: demo is already running on host:linohlsson2,pid:8173 cmd: **bliss -s demo** === !!! ( for more details type cmd 'last_error' )
+!!! === RuntimeError: demo is already running on host:linohlsson2,pid:8173 cmd: **bliss -s demo** === !!! ( for more details type cmd 'last_error()' )
 ```
 
 ### To quit Tmux

doc/docs/shell_obj_protection.md

@@ -15,10 +15,10 @@ TEST_SESSION [1]: roby
                        backlash (R): 2.00000
                        sign (R): 1
                        steps_per_unit (R): 10000.00
-                       ...                  
+                       ...
 
 TEST_SESSION [2]: roby = 1
-!!! === RuntimeError: roby is protected and can not be modified! === !!! ( for more details type cmd 'last_error' )
+!!! === RuntimeError: roby is protected and can not be modified! === !!! ( for more details type cmd 'last_error()' )
 
 TEST_SESSION [3]: roby
          Out [3]: AXIS:
@@ -29,7 +29,7 @@ TEST_SESSION [3]: roby
                        sign (R): 1
                        steps_per_unit (R): 10000.00
                        ...
-                  
+
 ```
 
 
@@ -43,7 +43,7 @@ TEST_SESSION [6]: my_important_variable
          Out [6]: 3.141
 
 TEST_SESSION [7]: my_important_variable=1
-!!! === RuntimeError: my_important_variable is protected and can not be modified! === !!! ( for more details type cmd 'last_error' )
+!!! === RuntimeError: my_important_variable is protected and can not be modified! === !!! ( for more details type cmd 'last_error()' )
 
 TEST_SESSION [8]: unprotect('my_important_variable')
 TEST_SESSION [9]: my_important_variable=1

tests/shell/test_bliss_shell_basics.py

@@ -703,7 +703,7 @@ def test_excepthook(shell_excepthook, default_session):
 
     assert (
         "".join(print_output)
-        == "!!! === RuntimeError: excepthook test === !!! ( for more details type cmd 'last_error' )"
+        == "!!! === RuntimeError: excepthook test === !!! ( for more details type cmd 'last_error()' )"
     )
 
 

tests/shell/test_error_handling.py

@@ -7,8 +7,11 @@
 
 import pytest
 import gevent
-from bliss.shell.cli import repl
 from datetime import date as datetime
+from pygments import lex
+from pygments.token import Token
+from bliss.shell.cli import repl
+from bliss.shell.cli.formatted_traceback import BlissTracebackLexer
 
 
 @pytest.fixture
@@ -21,8 +24,8 @@ def error_report():
 
 
 def test_error_report(beacon, error_report):
-    errors = error_report._last_error.errors
-    assert len(errors) == 0
+    err_hist = error_report.history
+    assert len(err_hist) == 0
     MYERROR = "MYERROR"
 
     def raise_exception():
@@ -31,11 +34,11 @@ def test_error_report(beacon, error_report):
     def raise_hub_exception(nerrors=1):
         w = gevent.get_hub().loop.async_()
         w.start(raise_exception)
-        n = len(errors) + nerrors
+        n = len(err_hist) + nerrors
         try:
             w.send()
             with gevent.Timeout(10):
-                while len(errors) != n:
+                while len(err_hist) != n:
                     gevent.sleep(0.1)
         finally:
             w.stop()
@@ -44,19 +47,17 @@ def test_error_report(beacon, error_report):
     # Exception in greenlet
     MYERROR = "MYERROR1"
     gevent.spawn(raise_exception).join()
-    assert len(errors) == 1
-    assert f"RuntimeError: {MYERROR}" in errors[-1]
+    assert len(err_hist) == 1
+    assert f"RuntimeError: {MYERROR}" in err_hist[-1].format()
 
     # Exception in gevent loop callback
     MYERROR = "MYERROR2"
     raise_hub_exception()
-    assert len(errors) == 2
-    assert f"RuntimeError: {MYERROR}" in errors[-1]
+    assert len(err_hist) == 2
+    assert f"RuntimeError: {MYERROR}" in err_hist[-1].format()
 
 
 def test_error_report_chained(error_report):
-    errors = error_report._last_error.errors
-
     def func1():
         raise RuntimeError("LEVEL 0")
 
@@ -68,7 +69,206 @@ def test_error_report_chained(error_report):
 
     gevent.spawn(func2).join()
 
-    assert len(errors) == 1
-    assert "\nRuntimeError: LEVEL 0" in errors[0]
-    assert "\nRuntimeError: LEVEL 1" in errors[0]
-    assert datetime.today().strftime("%d/%m/%Y") in errors[0]
+    assert len(error_report.history) == 1
+    last_error = error_report.history[-1].format()
+    assert "\nRuntimeError: LEVEL 0" in last_error
+    assert "\nRuntimeError: LEVEL 1" in last_error
+    assert datetime.today().strftime("%d/%m/%Y") in last_error
+
+
+def test_error_report_format(error_report):
+    def func1():
+        # variable longer than max_local_len
+        longvar = "bar" * 100  # noqa: F841
+        raise RuntimeError("LEVEL 0")
+
+    def func2():
+        # number of variables exceeding max_nb_locals
+        a = 0  # noqa: F841
+        b = 0  # noqa: F841
+        c = 0  # noqa: F841
+        d = 0  # noqa: F841
+        try:
+            func1()
+        except Exception as e:
+            # will cause "The above exception was the direct cause..." message
+            raise RuntimeError("LEVEL 1") from e
+
+    def func3():
+        foo = 42  # noqa: F841
+        try:
+            func2()
+        except Exception:
+            # will cause "During handling of the above..." message
+            raise RuntimeError("LEVEL 2")
+
+    gevent.spawn(func3).join()
+
+    assert len(error_report.history) == 1
+    formatted_error = error_report.history[-1].format(max_nb_locals=3, max_local_len=50)
+    lines = formatted_error.splitlines()
+
+    assert lines[0].startswith(datetime.today().strftime("%d/%m/%Y"))
+    assert lines[1] == "Traceback (most recent call last):"
+    assert (
+        "During handling of the above exception, another exception occurred:" in lines
+    )
+    assert (
+        "The above exception was the direct cause of the following exception:" in lines
+    )
+    assert "    @foo: 42" in lines
+    assert "    @longvar: ... (truncated)" in lines
+    assert "    ... (truncated)" in lines
+    assert "RuntimeError: LEVEL 0" in lines
+    assert "RuntimeError: LEVEL 1" in lines
+    assert "RuntimeError: LEVEL 2" in lines
+
+
+# =================== TRACEBACK LEXER TESTS ===================
+# Following tests are only written for non-regression purpose,
+# as there is no specific requirements on coloration.
+
+
+def test_error_report_lexer(error_report):
+    tb = """\
+01/01/1970 01:02:03