Traceback from __exit__ method is misleading

[bitdancer]

BPO	25538
Nosy	@terryjreedy, @bitdancer, @vadmium, @1st1, @RazerM, @kuraga
Files	with_traceback_monkeypatch.py: python code to change line shown in tracebacks to point to with statement when error is thrown in exit. with_traceback_fixed+async.py: python code to change line shown in tracebacks to point to with or async with statement when error is thrown in exit.

^{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 2015-11-02.23:08:02.983>
labels = []
title = 'Traceback from __exit__ method is misleading'
updated_at = <Date 2020-11-27.10:52:59.697>
user = 'https://github.com/bitdancer'

bugs.python.org fields:

activity = <Date 2020-11-27.10:52:59.697>
actor = 'kuraga'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = []
creation = <Date 2015-11-02.23:08:02.983>
creator = 'r.david.murray'
dependencies = []
files = ['49322', '49323']
hgrepos = []
issue_num = 25538
keywords = []
message_count = 9.0
messages = ['253949', '253964', '253997', '254244', '254245', '254252', '290632', '373821', '373827']
nosy_count = 7.0
nosy_names = ['terry.reedy', 'r.david.murray', 'martin.panter', 'yselivanov', 'RazerM', 'Tadhg McDonald-Jensen', 'kuraga']
pr_nums = []
priority = 'normal'
resolution = None
stage = None
status = 'open'
superseder = None
type = None
url = 'https://bugs.python.org/issue25538'
versions = []

[bitdancer]

This is at least the second time that I've wasted a bunch of debugging time being mislead by the traceback from __exit__. Perhaps I will remember from now on, but...I wonder if it would be possible/practical to improve the situation. The problem is that in the traceback printed when __exit__ throws an error, the source line printed before the source line from inside the __exit__ is the last line of the 'with' block. I kept staring at that line trying to figure out how the exception could possibly be getting raised from that line...which of course it wasn't really, it was the "line" in between that one and the next one, a psuedo-line representing the exit from the block.

I don't know if it would be worth the effort that would be required to somehow clarify this in the traceback (I'm not even sure what that would *look* like...maybe the first line of the with block instead?), but I thought I'd raise the issue to see if anyone had any clever ideas.

(Hopefully I haven't done this before...I tried searching for similar issues and didn't find anything.)

[vadmium]

I guess you are mainly complaining about when __exit__() implementation is built into the interpreter. E.g., given demo.py:

with open("/dev/full", "wb") as file:
    file.write(b"data")
    print("All is well")
print("Not executed")

the output looks like

All is well
Traceback (most recent call last):
  File "demo.py", line 3, in <module>
    print("All is well")
OSError: [Errno 28] No space left on device

When __exit__() is implemented natively in Python, you get more of a hint:

Traceback (most recent call last):
  File "demo.py", line 4, in <module>
    print("All is well")
  File "/home/proj/python/cpython/Lib/_pyio.py", line 457, in __exit__
    self.close()
  File "/home/proj/python/cpython/Lib/_pyio.py", line 773, in close
    self.flush()
  File "/home/proj/python/cpython/Lib/_pyio.py", line 1210, in flush
    self._flush_unlocked()
  File "/home/proj/python/cpython/Lib/_pyio.py", line 1217, in _flush_unlocked
    n = self.raw.write(self._write_buf)
  File "/home/proj/python/cpython/Lib/_pyio.py", line 1614, in write
    return os.write(self._fd, b)
OSError: [Errno 28] No space left on device

Maybe another option would be to insert a virtual frame in the built-in version of the traceback:

Traceback (most recent call last):
  File "demo.py", line 3, in <module>
    print("All is well")
  File "<built in>", line ???, in <context manager exit>
OSError: [Errno 28] No space left on device

[bitdancer]

What caught me out was more like this (but more complicated so it wasn't obvious the line mentioned wasn't part of the exception chain; in fact it looked like it was since it was a line that could very well have raised the exception in question):

rdmurray@pydev:~/python/p36>cat temp.py
def do_something():
    try:
        foo()
    except Exception:
        print('caught in do_something')
        raise

    def foo():
        with cm():
            print('all is well')

    class cm:

        def __enter__(self):
            return self

        def __exit__(*args, **kw):
            raise Exception('exception in __exit__')

    do_something()
    rdmurray@pydev:~/python/p36>./python temp.py
    all is well
    caught in do_something
    Traceback (most recent call last):
      File "temp.py", line 20, in <module>
        do_something()
      File "temp.py", line 3, in do_something
        foo()
      File "temp.py", line 10, in foo
        print('all is well')
      File "temp.py", line 18, in __exit__
        raise Exception('exception in __exit__')
    Exception: exception in __exit__

The confusing line in the traceback is "print('all is well')", which obviously isn't raising the exception.

[terryjreedy]

In Martin's example, I would expect the first line of the traceback to be the file write that raised the exception, not the print that is never executed. If print were writing to a different device than the first line, the traceback would be positively misleading.

In David's example, the print executed just fine, so it should not appear in the traceback either. The replacement, if any, might be the with statement itself. The 'pseudo-line' that triggers the __exit__ call is really the dedent on the next line, but printing the whole next line would be wrong too.

[vadmium]

Explanation of my example because it is tricky: The print is actually executed. Then the context manager exits, and the built-in buffered file object tries to flush its buffer and fails. The earlier write() call succeeds, because it only writes to the Python buffer, not the OS file descriptor.

[bitdancer]

Yes, I think the line that should be in the traceback in my example is the 'with' line. I have no clue how hard that would be to achieve.

[bitdancer]

See also bpo-29922.

[TadhgMcDonald-Jensen]

This is doable, the feature that decides which line is shown in the traceback is the lnotab structure in the relevant code object, the structure is described here (https://github.com/python/cpython/blob/3.8/Objects/lnotab_notes.txt) and it supports negative line offsets so it'd be possible to get the with statement closing statements to backup the line numbers to point to the with statement in question.

I have attached a python script which actually achieves this. correct_with_cleanup_traceback when passed a function changes the relevant line numbers so the traceback actually point to the with statement when the error is thrown in the exit, most of the relevant work is just dealing with the weird format of lnotab.

This is the error thrown by the test script, it has 2 cascading failures in exit so that I could confirm it worked for nested withs and it absolutely points to the relevant with statement as I have highlighted on the traceback,

    Traceback (most recent call last):
      File "/Users/tadhgmcdonald-jensen/Documents/test.py", line 71, in my_test
    >>  with Test(True) as will_fail_first:                             <<<--------- HERE
      File "/Users/tadhgmcdonald-jensen/Documents/test.py", line 67, in __exit__
        raise Exception("error in exit")
    Exception: error in exit

    During handling of the above exception, another exception occurred:

    Traceback (most recent call last):
      File "/Users/tadhgmcdonald-jensen/Documents/test.py", line 78, in <module>
        my_test()
      File "/Users/tadhgmcdonald-jensen/Documents/test.py", line 70, in my_test
    >>  with Test(True) as fail_during_handling:                        <<<--------- HERE 
      File "/Users/tadhgmcdonald-jensen/Documents/test.py", line 67, in __exit__
        raise Exception("error in exit")
    Exception: error in exit

[TadhgMcDonald-Jensen]

uploaded with_traceback_fixed+async.py because I forgot to include async with in my first code.

[iritkatriel]

This is fix since 3.10, I'm guessing by @markshannon 's work on line numbers?
I don't think we'll do anything about 3.9, so I'm closing.

iritkatriel@Irits-MBP cpython % ./python.exe xx.py             
all is well
caught in do_something
Traceback (most recent call last):
  File "/Users/iritkatriel/src/python/xx.py", line 20, in <module>
    do_something()
    ^^^^^^^^^^^^^^
  File "/Users/iritkatriel/src/cpython/xx.py", line 3, in do_something
    foo()
    ^^^^^
  File "/Users/iritkatriel/src/cpython/xx.py", line 9, in foo
    with cm():
    ^^^^^^^^^^
  File "/Users/iritkatriel/src/cpython/xx.py", line 18, in __exit__
    raise Exception('exception in __exit__')
    ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Exception: exception in __exit__

And in 3.10 as well:

iritkatriel@Irits-MBP cpython-654 % /usr/local/bin/python3.10 xx.py
all is well
caught in do_something
Traceback (most recent call last):
  File "/Users/iritkatriel/src/cpython/xx.py", line 20, in <module>
    do_something()
  File "/Users/iritkatriel/src/cpython/xx.py", line 3, in do_something
    foo()
  File "/Users/iritkatriel/src/cpython/xx.py", line 9, in foo
    with cm():
  File "/Users/iritkatriel/src/cpython/xx.py", line 18, in __exit__
    raise Exception('exception in __exit__')
Exception: exception in __exit__