Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Regression in python3.10 with traceback frame having lineno of -1 #88099

Closed
asottile mannequin opened this issue Apr 24, 2021 · 27 comments
Closed

Regression in python3.10 with traceback frame having lineno of -1 #88099

asottile mannequin opened this issue Apr 24, 2021 · 27 comments
Assignees
Labels
3.10 only security fixes 3.11 only security fixes release-blocker

Comments

@asottile
Copy link
Mannequin

asottile mannequin commented Apr 24, 2021

BPO 43933
Nosy @gvanrossum, @vstinner, @nedbat, @encukou, @markshannon, @asottile, @pablogsal
PRs
  • bpo-43933: Show frame.f_lineno as None, rather than -1, if there is no line number. #25717
  • bpo-43933: Set frame.f_lineno during call to __exit__ #25719
  • bpo-43933: Force RETURN_VALUE bytecodes to have line numbers #26054
  • [3.10] bpo-43933: Force RETURN_VALUE bytecodes to have line numbers #26061
  • 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 = 'https://github.com/markshannon'
    closed_at = <Date 2021-04-30.13:34:44.252>
    created_at = <Date 2021-04-24.19:56:33.908>
    labels = ['release-blocker', '3.10', '3.11']
    title = 'Regression in python3.10 with traceback frame having lineno of -1'
    updated_at = <Date 2021-06-07.20:58:11.753>
    user = 'https://github.com/asottile'

    bugs.python.org fields:

    activity = <Date 2021-06-07.20:58:11.753>
    actor = 'vstinner'
    assignee = 'Mark.Shannon'
    closed = True
    closed_date = <Date 2021-04-30.13:34:44.252>
    closer = 'Mark.Shannon'
    components = []
    creation = <Date 2021-04-24.19:56:33.908>
    creator = 'Anthony Sottile'
    dependencies = []
    files = []
    hgrepos = []
    issue_num = 43933
    keywords = ['patch']
    message_count = 27.0
    messages = ['391795', '391798', '391799', '391893', '391897', '391908', '391915', '392066', '392303', '392343', '392431', '392432', '392448', '392463', '392604', '392605', '392888', '392895', '392897', '392915', '392916', '392970', '393376', '393481', '393579', '393596', '395286']
    nosy_count = 7.0
    nosy_names = ['gvanrossum', 'vstinner', 'nedbat', 'petr.viktorin', 'Mark.Shannon', 'Anthony Sottile', 'pablogsal']
    pr_nums = ['25717', '25719', '26054', '26061']
    priority = 'release blocker'
    resolution = 'fixed'
    stage = 'resolved'
    status = 'closed'
    superseder = None
    type = None
    url = 'https://bugs.python.org/issue43933'
    versions = ['Python 3.10', 'Python 3.11']

    @asottile
    Copy link
    Mannequin Author

    asottile mannequin commented Apr 24, 2021

    This is breaking pytest for failed assertions: pytest-dev/pytest#8227

    It also breaks the traceback in the output below

    Here's a minimal example:

    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:

    3bd6035
    #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

    @asottile asottile mannequin added 3.10 only security fixes 3.11 only security fixes labels Apr 24, 2021
    @pablogsal
    Copy link
    Member

    Marking as release blocker since is breaking pytest

    @pablogsal
    Copy link
    Member

    Thanks for the bisection, Anthony

    @markshannon
    Copy link
    Member

    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__.

    @nedbat
    Copy link
    Member

    nedbat commented Apr 26, 2021

    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.

    @markshannon
    Copy link
    Member

    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.

    @markshannon
    Copy link
    Member

    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

    @encukou
    Copy link
    Member

    encukou commented Apr 27, 2021

    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.

    @markshannon
    Copy link
    Member

    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.

    @markshannon
    Copy link
    Member

    New changeset 088a15c 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)
    088a15c

    @markshannon
    Copy link
    Member

    New changeset 5979e81 by Mark Shannon in branch 'master':
    bpo-43933: Set frame.f_lineno during call to __exit__ (GH-25719)
    5979e81

    @markshannon
    Copy link
    Member

    I'm claiming that this is fixed.

    Feel free to reopen if the additional line in tracing causes a problem.

    @pablogsal
    Copy link
    Member

    Thanks Mark for the quick fix!

    Can someone confirm if the pytest issue is fixed?

    @asottile
    Copy link
    Mannequin Author

    asottile mannequin commented Apr 30, 2021

    can confirm that pytest no longer crashes

    @nedbat
    Copy link
    Member

    nedbat commented May 1, 2021

    I'm trying to see if these changes affect coverage.py, but pytest 6.2.3 fails with:

    === CPython 3.10.0a7+ (rev 558df90) 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?

    @asottile
    Copy link
    Mannequin Author

    asottile mannequin commented May 1, 2021

    ah yeah that's the asname ast change -- if you use the unreleased main branch it has a fix for that

    @nedbat
    Copy link
    Member

    nedbat commented May 4, 2021

    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?

    @pablogsal
    Copy link
    Member

    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.

    @nedbat
    Copy link
    Member

    nedbat commented May 4, 2021

    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.

    @pablogsal
    Copy link
    Member

    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?

    @asottile
    Copy link
    Mannequin Author

    asottile mannequin commented May 4, 2021

    I've released pytest 6.2.4 for the other breakage (which is unrelated to this bpo -- it was the asname source position issue)

    @nedbat
    Copy link
    Member

    nedbat commented May 5, 2021

    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?

    @markshannon
    Copy link
    Member

    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.

    @nedbat
    Copy link
    Member

    nedbat commented May 12, 2021

    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.

    @markshannon
    Copy link
    Member

    New changeset 0acdf25 by Mark Shannon in branch '3.10':
    [3.10] bpo-43933: Force RETURN_VALUE bytecodes to have line numbers (GH-26061)
    0acdf25

    @nedbat
    Copy link
    Member

    nedbat commented May 13, 2021

    Thanks, this fixes my issue.

    @vstinner
    Copy link
    Member

    vstinner commented Jun 7, 2021

    See also bpo-44297.

    @ezio-melotti ezio-melotti transferred this issue from another repository Apr 10, 2022
    Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
    Labels
    3.10 only security fixes 3.11 only security fixes release-blocker
    Projects
    None yet
    Development

    No branches or pull requests

    5 participants