classification
Title: Traceback from __exit__ method is misleading
Type: Stage:
Components: Versions:
process
Status: open Resolution:
Dependencies: Superseder:
Assigned To: Nosy List: RazerM, Tadhg McDonald-Jensen, kuraga, martin.panter, r.david.murray, terry.reedy, yselivanov
Priority: normal Keywords:

Created on 2015-11-02 23:08 by r.david.murray, last changed 2020-11-27 10:52 by kuraga.

Files
File name Uploaded Description Edit
with_traceback_monkeypatch.py Tadhg McDonald-Jensen, 2020-07-17 11:09 python code to change line shown in tracebacks to point to with statement when error is thrown in exit.
with_traceback_fixed+async.py Tadhg McDonald-Jensen, 2020-07-17 11:36 python code to change line shown in tracebacks to point to with or async with statement when error is thrown in exit.
Messages (9)
msg253949 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-11-02 23:08
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.)
msg253964 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-11-03 03:27
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
msg253997 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-11-03 15:20
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.
msg254244 - (view) Author: Terry J. Reedy (terry.reedy) * (Python committer) Date: 2015-11-07 00:30
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.
msg254245 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-11-07 00:42
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.
msg254252 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-11-07 02:28
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.
msg290632 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2017-03-27 17:35
See also issue 29922.
msg373821 - (view) Author: Tadhg McDonald-Jensen (Tadhg McDonald-Jensen) * Date: 2020-07-17 11:09
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
msg373827 - (view) Author: Tadhg McDonald-Jensen (Tadhg McDonald-Jensen) * Date: 2020-07-17 11:36
uploaded `with_traceback_fixed+async.py` because I forgot to include async with in my first code.
History
Date User Action Args
2020-11-27 10:52:59kuragasetnosy: + kuraga
2020-11-26 23:23:08iritkatriellinkissue38638 superseder
2020-07-17 11:36:08Tadhg McDonald-Jensensetfiles: + with_traceback_fixed+async.py

messages: + msg373827
2020-07-17 11:09:41Tadhg McDonald-Jensensetfiles: + with_traceback_monkeypatch.py

messages: + msg373821
2018-04-02 21:48:36serhiy.storchakaunlinkissue29922 superseder
2017-03-29 08:45:06RazerMsetnosy: + RazerM
2017-03-27 17:35:19r.david.murraysetnosy: + yselivanov, Tadhg McDonald-Jensen
messages: + msg290632
2017-03-27 17:33:56r.david.murraylinkissue29922 superseder
2015-11-07 02:28:26r.david.murraysetmessages: + msg254252
2015-11-07 00:42:47martin.pantersetmessages: + msg254245
2015-11-07 00:30:56terry.reedysetnosy: + terry.reedy
messages: + msg254244
2015-11-03 15:20:48r.david.murraysetmessages: + msg253997
2015-11-03 03:27:24martin.pantersetnosy: + martin.panter
messages: + msg253964
2015-11-02 23:08:02r.david.murraycreate