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

Python 3.9.0a2 changed how finally/return is traced #83295

Closed
nedbat opened this issue Dec 21, 2019 · 8 comments
Closed

Python 3.9.0a2 changed how finally/return is traced #83295

nedbat opened this issue Dec 21, 2019 · 8 comments
Labels
3.9 only security fixes type-bug An unexpected behavior, bug, or error

Comments

@nedbat
Copy link
Member

nedbat commented Dec 21, 2019

BPO 39114
Nosy @nedbat, @markshannon, @serhiy-storchaka, @pablogsal, @tirkarthi
PRs
  • bpo-39114: Fix handling of line numbers around finally-blocks. #17737
  • bpo-39114: Fix tracing of except handlers with name binding #17769
  • 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 = <Date 2022-03-30.11:54:41.865>
    created_at = <Date 2019-12-21.13:40:45.498>
    labels = ['type-bug', '3.9']
    title = 'Python 3.9.0a2 changed how finally/return is traced'
    updated_at = <Date 2022-03-30.11:54:41.865>
    user = 'https://github.com/nedbat'

    bugs.python.org fields:

    activity = <Date 2022-03-30.11:54:41.865>
    actor = 'iritkatriel'
    assignee = 'none'
    closed = True
    closed_date = <Date 2022-03-30.11:54:41.865>
    closer = 'iritkatriel'
    components = []
    creation = <Date 2019-12-21.13:40:45.498>
    creator = 'nedbat'
    dependencies = []
    files = []
    hgrepos = []
    issue_num = 39114
    keywords = ['patch', '3.9regression']
    message_count = 8.0
    messages = ['358771', '358773', '358998', '359000', '359035', '359037', '359038', '359192']
    nosy_count = 5.0
    nosy_names = ['nedbat', 'Mark.Shannon', 'serhiy.storchaka', 'pablogsal', 'xtreak']
    pr_nums = ['17737', '17769']
    priority = 'normal'
    resolution = 'fixed'
    stage = 'resolved'
    status = 'closed'
    superseder = None
    type = 'behavior'
    url = 'https://bugs.python.org/issue39114'
    versions = ['Python 3.9']

    @nedbat
    Copy link
    Member Author

    nedbat commented Dec 21, 2019

    The way trace function reports return-finally has changed in Python 3.9.0a2. I don't know if this change is intentional or not.

    (BTW: I want to put a 3.9regression keyword on this, but it doesn't exist.)

    Consider this code:

    --- 8< ----------------------------------------------------

    import linecache, sys
    
    def trace(frame, event, arg):
        lineno = frame.f_lineno
        print("{} {}: {}".format(event[:4], lineno, linecache.getline(__file__, lineno).rstrip()))
        return trace
    
    print(sys.version)
    sys.settrace(trace)
    
    a = []
    def finally_return():
        try:
            return 14
        finally:
            a.append(16)
    assert finally_return() == 14
    assert a == [16]
    --- 8< 

    (My habit is to use line numbers in the lines themselves to help keep things straight.)

    In Python 3.7 (and before), the last traces are line 14, line 16, return 16.

    In Python 3.8, the last traces are line 14, line 16, line 14, return 14.

    In Python 3.9a1, the traces are the same as 3.8.

    In Python 3.9a2, the traces are now line 14, line 16, line 14, line 16, return 16.

    This doesn't make sense to me: why does it bounce back and forth?

    Full output from different versions of Python:

    % /usr/local/pythonz/pythons/CPython-3.7.1/bin/python3.7 bpo.py
    3.7.1 (default, Oct 20 2018, 18:25:32)
    [Clang 10.0.0 (clang-1000.11.45.2)]
    call 12: def finally_return():
    line 13: try:
    line 14: return 14
    line 16: a.append(16)
    retu 16: a.append(16)
    % /usr/local/pythonz/pythons/CPython-3.8.1/bin/python3.8 bpo.py
    3.8.1 (default, Dec 19 2019, 08:38:38)
    [Clang 10.0.0 (clang-1000.10.44.4)]
    call 12: def finally_return():
    line 13: try:
    line 14: return 14
    line 16: a.append(16)
    line 14: return 14
    retu 14: return 14
    % /usr/local/pythonz/pythons/CPython-3.9.0a1/bin/python3.9 bpo.py
    3.9.0a1 (default, Nov 20 2019, 18:52:14)
    [Clang 10.0.0 (clang-1000.10.44.4)]
    call 12: def finally_return():
    line 13: try:
    line 14: return 14
    line 16: a.append(16)
    line 14: return 14
    retu 14: return 14
    % /usr/local/pythonz/pythons/CPython-3.9.0a2/bin/python3.9 bpo.py
    3.9.0a2 (default, Dec 19 2019, 08:42:29)
    [Clang 10.0.0 (clang-1000.10.44.4)]
    call 12: def finally_return():
    line 13: try:
    line 14: return 14
    line 16: a.append(16)
    line 14: return 14
    line 16: a.append(16)
    retu 16: a.append(16)

    @nedbat nedbat added 3.9 only security fixes type-bug An unexpected behavior, bug, or error labels Dec 21, 2019
    @tirkarthi
    Copy link
    Member

    Looking at changes to alpha2 I think it bisects to #6641

    ➜ cpython git:(5dcc06f) git checkout fee5526 && make -s -j4 > /dev/null
    Previous HEAD position was 5dcc06f... bpo-38858: Allocate small integers on the heap (GH-17301)
    HEAD is now at fee5526... Produce cleaner bytecode for 'with' and 'async with' by generating separate code for normal and exceptional paths. (bpo-6641)
    ➜ cpython git:(fee5526) ./python ../backups/bpo39114.py
    3.9.0a1+ (tags/v3.9.0a1-43-gfee552669f:fee552669f, Dec 21 2019, 20:18:54)
    [GCC 4.8.4]
    call 12: def finally_return():
    line 13: try:
    line 14: return 14
    line 16: a.append(16)
    line 14: return 14
    line 16: a.append(16)
    retu 16: a.append(16)
    ➜ cpython git:(fee5526) git checkout fee5526~1 && make -s -j4 > /dev/null
    Previous HEAD position was fee5526... Produce cleaner bytecode for 'with' and 'async with' by generating separate code for normal and exceptional paths. (bpo-6641)
    HEAD is now at 5dcc06f... bpo-38858: Allocate small integers on the heap (GH-17301)
    ➜ cpython git:(5dcc06f) ./python ../backups/bpo39114.py
    3.9.0a1+ (tags/v3.9.0a1-42-g5dcc06f6e0:5dcc06f6e0, Dec 21 2019, 20:21:07)
    [GCC 4.8.4]
    call 12: def finally_return():
    line 13: try:
    line 14: return 14
    line 16: a.append(16)
    line 14: return 14
    retu 14: return 14

    @markshannon
    Copy link
    Member

    Exammining the bytecode for:

    def finally_return():
        try:
            return 14
        finally:
            a.append(16)

    We have:

    2 0 SETUP_FINALLY 16 (to 18)

    3 2 POP_BLOCK

    5 4 LOAD_GLOBAL 0 (a)
    6 LOAD_METHOD 1 (append)
    8 LOAD_CONST 1 (16)
    10 CALL_METHOD 1
    12 POP_TOP

    3 14 LOAD_CONST 2 (14)

    5 16 RETURN_VALUE
    >> 18 LOAD_GLOBAL 0 (a)
    20 LOAD_METHOD 1 (append)
    22 LOAD_CONST 1 (16)
    24 CALL_METHOD 1
    26 POP_TOP
    28 RERAISE
    30 LOAD_CONST 0 (None)
    32 RETURN_VALUE

    Which looks correct, except for the line number of the first RETURN_VALUE.

    Looking at the compiler it seems that we aren't preserving the original line number when emitting code for the finally block.

    @markshannon
    Copy link
    Member

    With PR 17737 the bytecode is:

    2 0 SETUP_FINALLY 16 (to 18)

    3 2 POP_BLOCK

    5 4 LOAD_GLOBAL 0 (a)
    6 LOAD_METHOD 1 (append)
    8 LOAD_CONST 1 (16)
    10 CALL_METHOD 1
    12 POP_TOP

    3 14 LOAD_CONST 2 (14)
    16 RETURN_VALUE

    5 >> 18 LOAD_GLOBAL 0 (a)
    20 LOAD_METHOD 1 (append)
    22 LOAD_CONST 1 (16)
    24 CALL_METHOD 1
    26 POP_TOP
    28 RERAISE
    30 LOAD_CONST 0 (None)
    32 RETURN_VALUE

    @markshannon
    Copy link
    Member

    Ned, I think this is fixed. Feel free to re-open if you disagree.

    @nedbat
    Copy link
    Member Author

    nedbat commented Dec 30, 2019

    Thanks, that fixes the original case in this issue.

    Here is another problem which seems related enough to append here instead of opening a new issue:

    --- 8< ----------------------------------------------------

    import linecache, sys
    
    def trace(frame, event, arg):
        lineno = frame.f_lineno
        print("{} {}: {}".format(event[:4], lineno, linecache.getline(__file__, lineno).rstrip()))
        return trace
    
    print(sys.version)
    sys.settrace(trace)
    
    def b(exc):
        print("exc is {!r}".format(exc))
        try:
            raise Exception(exc)
        except Exception as e:
            if exc != 'expected':
                raise                   # line 17
            q = "removing this line changes the behavior"
            r = "is this executed?"     # line 19
        return
    
    b('expected')
    try:
        b('unexpected')
    except:
        pass
    --- 8< 

    With your fix, it reports that the raise on line 17 is followed by line 19, which can't be right:

    3.9.0a2+ (heads/pr/17737:f2545467fa, Dec 29 2019, 15:38:57)
    [Clang 10.0.0 (clang-1000.10.44.4)]
    call 11: def b(exc):
    line 12: print("exc is {!r}".format(exc))
    exc is 'expected'
    line 13: try:
    line 14: raise Exception(exc)
    exce 14: raise Exception(exc)
    line 15: except Exception as e:
    line 16: if exc != 'expected':
    line 18: q = "removing this line changes the behavior"
    line 19: r = "is this executed?"
    line 20: return
    retu 20: return
    call 11: def b(exc):
    line 12: print("exc is {!r}".format(exc))
    exc is 'unexpected'
    line 13: try:
    line 14: raise Exception(exc)
    exce 14: raise Exception(exc)
    line 15: except Exception as e:
    line 16: if exc != 'expected':
    line 17: raise
    line 19: r = "is this executed?"
    retu 19: r = "is this executed?"

    Python 3.8 reported this:

    3.8.1 (default, Dec 19 2019, 08:38:38)
    [Clang 10.0.0 (clang-1000.10.44.4)]
    call 11: def b(exc):
    line 12: print("exc is {!r}".format(exc))
    exc is 'expected'
    line 13: try:
    line 14: raise Exception(exc)
    exce 14: raise Exception(exc)
    line 15: except Exception as e:
    line 16: if exc != 'expected':
    line 18: q = "removing this line changes the behavior"
    line 19: r = "is this executed?"
    line 20: return
    retu 20: return
    call 11: def b(exc):
    line 12: print("exc is {!r}".format(exc))
    exc is 'unexpected'
    line 13: try:
    line 14: raise Exception(exc)
    exce 14: raise Exception(exc)
    line 15: except Exception as e:
    line 16: if exc != 'expected':
    line 17: raise
    retu 17: raise

    @nedbat nedbat reopened this Dec 30, 2019
    @nedbat nedbat reopened this Dec 30, 2019
    @nedbat
    Copy link
    Member Author

    nedbat commented Dec 30, 2019

    BTW: this is not a regression in your fix. 3.9a2 behaved this way also.

    @pablogsal
    Copy link
    Member

    New changeset 04ec7a1 by Pablo Galindo in branch 'master':
    bpo-39114: Fix tracing of except handlers with name binding (GH-17769)
    04ec7a1

    @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.9 only security fixes type-bug An unexpected behavior, bug, or error
    Projects
    None yet
    Development

    No branches or pull requests

    5 participants