classification
Title: Regression in python3.10 with traceback frame having lineno of -1
Type: Stage: resolved
Components: Versions: Python 3.11, Python 3.10
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Mark.Shannon Nosy List: Anthony Sottile, Mark.Shannon, gvanrossum, nedbat, pablogsal, petr.viktorin, vstinner
Priority: release blocker Keywords: patch

Created on 2021-04-24 19:56 by Anthony Sottile, last changed 2021-06-07 20:58 by vstinner. This issue is now closed.

Pull Requests
URL Status Linked Edit
PR 25717 merged Mark.Shannon, 2021-04-29 12:15
PR 25719 merged Mark.Shannon, 2021-04-29 12:54
PR 26054 merged Mark.Shannon, 2021-05-12 09:30
PR 26061 merged Mark.Shannon, 2021-05-12 10:35
Messages (27)
msg391795 - (view) Author: Anthony Sottile (Anthony Sottile) * Date: 2021-04-24 19:56
This is breaking pytest for failed assertions: https://github.com/pytest-dev/pytest/pull/8227

It also breaks the traceback in the output below

Here's a minimal example:

```python
class Boom:
    def __enter__(self):
        return self
    def __exit__(self, *_):
        raise AssertionError('boom!')


def main() -> int:
    with Boom():
        raise AssertionError('hi')


if __name__ == '__main__':
    exit(main())
```

On python3.9 you get this:

```
Traceback (most recent call last):
  File "/home/asottile/workspace/cpython/t.py", line 10, in main
    raise AssertionError('hi')
AssertionError: hi

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/asottile/workspace/cpython/t.py", line 14, in <module>
    exit(main())
  File "/home/asottile/workspace/cpython/t.py", line 10, in main
    raise AssertionError('hi')
  File "/home/asottile/workspace/cpython/t.py", line 5, in __exit__
    raise AssertionError('boom!')
AssertionError: boom!
```

output in python3.10:

```
Traceback (most recent call last):
  File "/home/asottile/workspace/cpython/t.py", line 10, in main
    raise AssertionError('hi')
AssertionError: hi

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/asottile/workspace/cpython/t.py", line 14, in <module>
    exit(main())
  File "/home/asottile/workspace/cpython/t.py", line -1, in main
  File "/home/asottile/workspace/cpython/t.py", line 5, in __exit__
    raise AssertionError('boom!')
AssertionError: boom!
```

Notice the second to last frame is now missing and invalid (line -1)

I bisected this and found this is the culprit:


https://github.com/python/cpython/commit/3bd6035b6baf1a7d51b7cc2c6bb2c81886236b67
https://github.com/python/cpython/pull/24202

```
3bd6035b6baf1a7d51b7cc2c6bb2c81886236b67 is the first bad commit
commit 3bd6035b6baf1a7d51b7cc2c6bb2c81886236b67
Author: Mark Shannon <mark@hotpy.org>
Date:   Wed Jan 13 12:05:43 2021 +0000

    bpo-42908: Mark cleanup code at end of try-except and with artificial (#24202)
    
    * Mark bytecodes at end of try-except as artificial.
    
    * Make sure that the CFG is consistent throughout optimiization.
    
    * Extend line-number propagation logic so that implicit returns after 'try-except' or 'with' have the correct line numbers.
    
    * Update importlib

 Lib/test/test_dis.py          |    2 +-
 Lib/test/test_sys_settrace.py |   40 +
 Python/compile.c              |  135 +-
 Python/importlib.h            | 3153 ++++++++++++++---------------
 Python/importlib_external.h   | 4489 ++++++++++++++++++++---------------------
 Python/importlib_zipimport.h  | 1013 +++++-----
 6 files changed, 4473 insertions(+), 4359 deletions(-)
bisect run success
```

which appears to be due to bpo-42908
msg391798 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2021-04-24 20:25
Marking as release blocker since is breaking pytest
msg391799 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2021-04-24 20:26
Thanks for the bisection, Anthony
msg391893 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2021-04-26 10:16
What exactly is the issue here?
That the line number is -1, or that is different from 3.9?

The `-1` should be `None`. I can fix that, but there is the issue of whether the cleanup code in a with statement should have a line number or not.

The traceback for 3.9 is incorrect, the program is not on line 10 when __exit__ is called.

Currently we mark the cleanup code for the with statement as artificial meaning that it has no line number.
We could give it the line number of the `with` keyword, but that might break coverage and profiling tools.

PEP 626 says that the "with" keyword is executable, and should be traced, but nothing about whether that includes the cleanup call to __exit__.
msg391897 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2021-04-26 10:42
Mark, you say:

> The traceback for 3.9 is incorrect, the program is not on line 10 when __exit__ is called.

It's kind of not on any line in main(), but line 10 is the most useful line to indicate.  It's the last bit of the user's code that was running, and it is the reason for leaving the with statement.
msg391908 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2021-04-26 12:31
In this case, if happens that line 10 was the last line of code executing in the body of the with statement.
But the reason it was listed, was that it was statically the last line of code in the body.

If the body is something like:

1. if TRUE:
2.     ...
3. else:
4.     ...

Then the reported last line will be 4, even though it is never executed.
We can fix this, at the cost of extra compiler complexity and increased bytecode size for the non-exceptional case, but it is very difficult for the exceptional case, because we don't know statically where the exception has come from.
msg391915 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2021-04-26 12:55
This test case was added for 3.10.
In 3.9 it reports that the pass statement executes, even though it is unreachable.

https://github.com/python/cpython/blob/master/Lib/test/test_sys_settrace.py#L919
msg392066 - (view) Author: Petr Viktorin (petr.viktorin) * (Python committer) Date: 2021-04-27 12:53
Please don't lose the big picture here.
Previously, the reported line number was *somewhere close* to the currently executing code. That's typically all I need from a traceback: the fix for a bug often needs to go a few lines above/below where it's reported.

If, in an effort to make line numbers *exact*, we determine that there's no good line number to report and use -1 or None, we're introducing a regression.


> We could give it the line number of the `with` keyword, but that might break coverage and profiling tools.

That sounds like a reasonable idea, despite the drawback. As we can see from the report, *any* change will probably break *some* tools.
msg392303 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2021-04-29 12:20
I'm going to set the line number for executing the `__exit__()` function as that of the `with` keyword.

This should give a sensible traceback, and not break coverage, as the with statement is already executed.
It will impact traces and profiles, which is why the __exit__ call was not given a line number before.

Anthony, Ned,
please let me know if you disagree.
msg392343 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2021-04-29 18:28
New changeset 088a15c49d99ecb4c3bef93f8f40dd513c6cae3b by Mark Shannon in branch 'master':
bpo-43933: Show frame.f_lineno as None, rather than -1, if there is no line number. (GH-25717)
https://github.com/python/cpython/commit/088a15c49d99ecb4c3bef93f8f40dd513c6cae3b
msg392431 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2021-04-30 13:32
New changeset 5979e81a212949c62c2490167c9137d233d7de64 by Mark Shannon in branch 'master':
bpo-43933:  Set frame.f_lineno during call to __exit__ (GH-25719)
https://github.com/python/cpython/commit/5979e81a212949c62c2490167c9137d233d7de64
msg392432 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2021-04-30 13:34
I'm claiming that this is fixed.

Feel free to reopen if the additional line in tracing causes a problem.
msg392448 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2021-04-30 15:34
Thanks Mark for the quick fix!

Can someone confirm if the pytest issue is fixed?
msg392463 - (view) Author: Anthony Sottile (Anthony Sottile) * Date: 2021-04-30 16:08
can confirm that pytest no longer crashes
msg392604 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2021-05-01 16:04
I'm trying to see if these changes affect coverage.py, but pytest 6.2.3 fails with:

=== CPython 3.10.0a7+ (rev 558df90109) with Python tracer (.tox/anypy/bin/python) ===
ImportError while loading conftest '/Users/nedbatchelder/coverage/trunk/tests/conftest.py'.
TypeError: required field "lineno" missing from alias


Is this something I am doing wrong?
msg392605 - (view) Author: Anthony Sottile (Anthony Sottile) * Date: 2021-05-01 16:09
ah yeah that's the `asname` ast change -- if you use the unreleased main branch it has a fix for that
msg392888 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2021-05-04 13:15
Thanks, tip of pytest works for me.  Is this error going to happen for everyone testing with 3.10b1?  If so, can we get a release of pytest?
msg392895 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2021-05-04 13:43
>  Is this error going to happen for everyone testing with 3.10b1?

3.10.0b1 includes both of these PRs so people testing the beta should not get affected. That's why I marked this as release blocker.
msg392897 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2021-05-04 14:01
The pytest failure still happens with 3.10.0b1 and pytest 6.2.3.  I'm asking if pytest can make a release to update.
msg392915 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2021-05-04 16:12
> The pytest failure still happens with 3.10.0b1 and pytest 6.2.3.

What I am missing? 3.10.0b1 includes the fixes for this issue, no? Is it because the fixes still require some changes in the source? If that's the case, we should mention it in the What's New

> I'm asking if pytest can make a release to update.

In any case, shouldn't that be requested in the pytest issue tracker?
msg392916 - (view) Author: Anthony Sottile (Anthony Sottile) * Date: 2021-05-04 16:30
I've released pytest 6.2.4 for the other breakage (which is unrelated to this bpo -- it was the asname source position issue)
msg392970 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2021-05-05 01:50
Mark, I'm not clear if the line number can still be None in some circumstances. 

With this code (from site.py in the stdlib):

545: def execsitecustomize():
546:     """Run custom site specific code, if available."""
547:     try:
548:         try:
549:             import sitecustomize
550:         except ImportError as exc:
551:             if exc.name == 'sitecustomize':
552:                 pass
553:             else:
554:                 raise
555:     except Exception as err:
556:         if sys.flags.verbose:
557:             sys.excepthook(*sys.exc_info())
558:         else:
559:             sys.stderr.write(
560:                 "Error in sitecustomize; set PYTHONVERBOSE for traceback:\n"
561:                 "%s: %s\n" %
562:                 (err.__class__.__name__, err))

I get traces with these events and line numbers:

exception 549 (ModuleNotFoundError("No module named 'sitecustomize'"))
line 550
line 551
line 552
return None

Is this what you expected?
msg393376 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2021-05-10 11:12
Ned, no line numbers should never be None.
(Except under very unusual circumstances, like the trace function raising an error)

Taking a look at the disassembly of execsitecustomize, there is a return with no line number, which shouldn't happen.
msg393481 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2021-05-12 00:06
BTW, I created a separate issue about this: https://bugs.python.org/issue44088 because I wasn't sure if I should continue on this one, sorry.  Feel free to close either one.
msg393579 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2021-05-13 13:11
New changeset 0acdf255a51b836c0b44f3676797620322974af3 by Mark Shannon in branch '3.10':
[3.10] bpo-43933: Force RETURN_VALUE bytecodes to have line numbers (GH-26061)
https://github.com/python/cpython/commit/0acdf255a51b836c0b44f3676797620322974af3
msg393596 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2021-05-13 18:09
Thanks, this fixes my issue.
msg395286 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2021-06-07 20:58
See also bpo-44297.
History
Date User Action Args
2021-06-07 20:58:11vstinnersetnosy: + vstinner
messages: + msg395286
2021-05-13 18:09:37nedbatsetmessages: + msg393596
2021-05-13 13:11:49Mark.Shannonsetmessages: + msg393579
2021-05-12 10:35:00Mark.Shannonsetpull_requests: + pull_request24702
2021-05-12 09:30:32Mark.Shannonsetpull_requests: + pull_request24694
2021-05-12 00:06:48nedbatsetmessages: + msg393481
2021-05-10 13:26:54Mark.Shannonsetmessages: - msg393388
2021-05-10 13:26:32Mark.Shannonsetmessages: + msg393388
2021-05-10 11:12:20Mark.Shannonsetmessages: + msg393376
2021-05-05 01:50:13nedbatsetmessages: + msg392970
2021-05-04 16:30:11Anthony Sottilesetmessages: + msg392916
2021-05-04 16:12:22pablogsalsetmessages: + msg392915
2021-05-04 14:01:22nedbatsetmessages: + msg392897
2021-05-04 13:43:51pablogsalsetmessages: + msg392895
2021-05-04 13:15:44nedbatsetmessages: + msg392888
2021-05-01 16:09:31Anthony Sottilesetmessages: + msg392605
2021-05-01 16:04:42nedbatsetmessages: + msg392604
2021-04-30 16:08:34Anthony Sottilesetmessages: + msg392463
2021-04-30 15:34:16pablogsalsetmessages: + msg392448
2021-04-30 13:34:44Mark.Shannonsetstatus: open -> closed
resolution: fixed
messages: + msg392432

stage: patch review -> resolved
2021-04-30 13:32:54Mark.Shannonsetmessages: + msg392431
2021-04-29 18:28:57Mark.Shannonsetmessages: + msg392343
2021-04-29 12:54:12Mark.Shannonsetpull_requests: + pull_request24410
2021-04-29 12:20:10Mark.Shannonsetmessages: + msg392303
2021-04-29 12:15:11Mark.Shannonsetkeywords: + patch
stage: patch review
pull_requests: + pull_request24408
2021-04-27 12:53:47petr.viktorinsetnosy: + petr.viktorin
messages: + msg392066
2021-04-26 17:00:52gvanrossumsetnosy: + gvanrossum
2021-04-26 12:55:50Mark.Shannonsetmessages: + msg391915
2021-04-26 12:31:03Mark.Shannonsetmessages: + msg391908
2021-04-26 10:42:20nedbatsetmessages: + msg391897
2021-04-26 10:16:29Mark.Shannonsetnosy: + nedbat
messages: + msg391893
2021-04-24 20:26:43pablogsalsetmessages: + msg391799
2021-04-24 20:25:55pablogsalsetpriority: normal -> release blocker

messages: + msg391798
2021-04-24 20:25:27pablogsalsetassignee: Mark.Shannon
2021-04-24 19:56:33Anthony Sottilecreate