Chained tracebacks are confusing because the first traceback is minimal

[bitdancer]

BPO	12535
Nosy	@birkenfeld, @rhettinger, @terryjreedy, @ncoghlan, @benjaminp, @ezio-melotti, @merwok, @bitdancer, @ericsnowcurrently, @iritkatriel

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = None
created_at = <Date 2011-07-11.17:33:03.089>
labels = ['interpreter-core', 'type-feature', 'library', '3.9', '3.10']
title = 'Chained tracebacks are confusing because the first traceback is minimal'
updated_at = <Date 2021-12-30.00:05:54.431>
user = 'https://github.com/bitdancer'

bugs.python.org fields:

activity = <Date 2021-12-30.00:05:54.431>
actor = 'iritkatriel'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Interpreter Core', 'Library (Lib)']
creation = <Date 2011-07-11.17:33:03.089>
creator = 'r.david.murray'
dependencies = []
files = []
hgrepos = []
issue_num = 12535
keywords = []
message_count = 10.0
messages = ['140153', '140158', '140159', '140160', '140176', '140471', '140478', '164670', '188653', '409337']
nosy_count = 11.0
nosy_names = ['georg.brandl', 'rhettinger', 'terry.reedy', 'ncoghlan', 'benjamin.peterson', 'ezio.melotti', 'eric.araujo', 'r.david.murray', 'eric.snow', 'isoschiz', 'iritkatriel']
pr_nums = []
priority = 'normal'
resolution = None
stage = None
status = 'open'
superseder = None
type = 'enhancement'
url = 'https://bugs.python.org/issue12535'
versions = ['Python 3.9', 'Python 3.10']

[bitdancer]

Consider the following traceback:

Traceback (most recent call last):
  File "/home/rdmurray/python/email6/Lib/email/message.py", line 466, in __getattr__
    return getattr(self._headers, key)
AttributeError: '_Header_List' object has no attribute 'header_factory'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/home/rdmurray/python/email6/Lib/mailbox.py", line 1631, in set_flags
    self.replace_header('Status', status_flags)
  File "/home/rdmurray/python/email6/Lib/email/message.py", line 495, in replace_header
    print('rep', self.header_factory)
  File "/home/rdmurray/python/email6/Lib/email/message.py", line 469, in __getattr__
    self.__class__.__name__, key))
AttributeError: 'mboxMessage' object has no attribute 'header_factory'

The first traceback, which is supposed to be the "primary" error, gives
no indication of where the problem occured. It starts with a fairly
deeply nested call. The second traceback does show the line where the
error occured in the except statement, but you have to read the lines
above it to find the line that actually triggered the original
traceback.

I think it would be much better if either the full traceback were
given for the first traceback, or for both of them. I realize
that the short traceback for the first traceback is how things
have "traditionally" worked when exceptions are caught, but as
evidenced by bpo-1553375 this is often not the desired behavior
even before the existence of chained exceptions.

[bitdancer]

I think the reason the chained tracebacks look backward to me is twofold: I'm used to the last one in the list being the *only* one I get (in python2), and the last one in the list is often the one I want to deal with first. This is especially true if my try/except is transforming the more-specific-but-not-application-meaningful exception into one that is meaningful for the application.

So another possibility would be to reverse the order in which the tracebacks are printed, and instead of saying "during the handling of the above exception...", we'd say "this exception occurred during the handling of the following exception:". Doing this would probably greatly reduce the desire for a way to suppress the traceback chaining.

[benjaminp]

There _is_ no full traceback for the first exception. It stops as soon as it's handled.

[bitdancer]

One can argue that it is necessary to read the traceback in reverse order, so that reading the chain in reverse order is a logical extension of that. So I guess I have no serious objection to this being rejected.

[ncoghlan]

The ordering is as it is so that the last line in the displayed traceback corresponds to the exception that was actually caught. That is, the last line remains the same regardless of whether or not there was an earlier exception in the chain. Without that, the caught exception would be buried in the middle of a wall of text:

Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/home/rdmurray/python/email6/Lib/mailbox.py", line 1631, in set_flags
    self.replace_header('Status', status_flags)
  File "/home/rdmurray/python/email6/Lib/email/message.py", line 495, in replace_header
    print('rep', self.header_factory)
  File "/home/rdmurray/python/email6/Lib/email/message.py", line 469, in __getattr__
    self.__class__.__name__, key))
AttributeError: 'mboxMessage' object has no attribute 'header_factory'
^^^^^^^^^^^^^^^^CAUGHT THIS
This exception was caught while handling:
Traceback (most recent call last):
  File "/home/rdmurray/python/email6/Lib/email/message.py", line 466, in __getattr__
    return getattr(self._headers, key)
AttributeError: '_Header_List' object has no attribute 'header_factory'
^^^^^^^^^^^^^^^^NOT THIS

The consequence is that the outermost call in the call stack ends up buried in the middle of a wall of text instead. That's not optimal either, but we have to choose one or the other and I think the status quo is the better choice.

However, not closing this yet, as I think RDM may have a valid point: should we put something at the *start* of the truncated traceback to indicate that it was cut short due to another exception? For example:

Traceback (truncated due to later exception, most recent call last):
File "/home/rdmurray/python/email6/Lib/email/message.py", line 466, in __getattr__
return getattr(self._headers, key)
AttributeError: '_Header_List' object has no attribute 'header_factory'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/home/rdmurray/python/email6/Lib/mailbox.py", line 1631, in set_flags
    self.replace_header('Status', status_flags)
  File "/home/rdmurray/python/email6/Lib/email/message.py", line 495, in replace_header
    print('rep', self.header_factory)
  File "/home/rdmurray/python/email6/Lib/email/message.py", line 469, in __getattr__
    self.__class__.__name__, key))
AttributeError: 'mboxMessage' object has no attribute 'header_factory'

[terryjreedy]

I agree with Nick's rationale for the current order, and also like his idea of indicating that the first traceback is truncated (which has not been completely obvious to me). Bike-shedding a bit, I would prefer something more like:

Truncated traceback of caught exception:

The '(most recent call last)' bit is nonsensical when only the most recent call is given.

[ncoghlan]

The redundancy of the "(most recent call last)" when there's only one frame in the stack is a separate problem (as it happens even for unchained tracebacks), but feel free to create a new issue if you'd like to see it changed (I expect it would needlessly break doctests, so I don't like your chances of getting agreement on it, though)

+1 for the short and to the point "Truncated traceback" phrasing in the header line to address the current issue, though.

I've removed 3.2 from the affected releases due to the same "may break doctests" concern (error handling doctests are so inherently fragile that I don't mind breaking cases like this in a major version upgrade)

[ncoghlan]

I've thought of a different approach to this which should be less hazardous to doctests: include the truncation warning in the *traceback* section, rather than in the header. doctests already ignore the details of that section because checking it is too fragile.

cc'ing Georg because I think this a potentially big win for the usability of chained tracebacks, but also think it is dubious from a feature vs fix point of view.

With the change I'm considering, truncated tracebacks would look something like:

Traceback (most recent call last):
  <truncated: another exception occurred>
  File "/home/rdmurray/python/email6/Lib/email/message.py", line 466, in __getattr__
    return getattr(self._headers, key)
AttributeError: '_Header_List' object has no attribute 'header_factory'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/home/rdmurray/python/email6/Lib/mailbox.py", line 1631, in set_flags
    self.replace_header('Status', status_flags)
  File "/home/rdmurray/python/email6/Lib/email/message.py", line 495, in replace_header
    print('rep', self.header_factory)
  File "/home/rdmurray/python/email6/Lib/email/message.py", line 469, in __getattr__
    self.__class__.__name__, key))
AttributeError: 'mboxMessage' object has no attribute 'header_factory'

[ncoghlan]

Marking this as Library as well, since the traceback module should also be updated.