classification
Title: Python 3.9.0a2 changed how finally/return is traced
Type: behavior Stage: patch review
Components: Versions: Python 3.9
process
Status: open Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: Mark.Shannon, nedbat, pablogsal, serhiy.storchaka, xtreak
Priority: normal Keywords: 3.9regression, patch

Created on 2019-12-21 13:40 by nedbat, last changed 2020-01-02 11:38 by pablogsal.

Pull Requests
URL Status Linked Edit
PR 17737 merged Mark.Shannon, 2019-12-29 18:48
PR 17769 merged pablogsal, 2019-12-31 08:53
Messages (8)
msg358771 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2019-12-21 13:40
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)
msg358773 - (view) Author: Karthikeyan Singaravelan (xtreak) * (Python committer) Date: 2019-12-21 14:52
Looking at changes to alpha2 I think it bisects to https://github.com/python/cpython/pull/6641


➜  cpython git:(5dcc06f6e0) git checkout fee552669f21ca294f57fe0df826945edc779090 && make -s -j4 > /dev/null 
Previous HEAD position was 5dcc06f6e0... bpo-38858: Allocate small integers on the heap (GH-17301)
HEAD is now at fee552669f... Produce cleaner bytecode for 'with' and 'async with' by generating separate code for normal and exceptional paths. (#6641)
➜  cpython git:(fee552669f) ./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:(fee552669f) git checkout fee552669f21ca294f57fe0df826945edc779090~1 && make -s -j4 > /dev/null
Previous HEAD position was fee552669f... Produce cleaner bytecode for 'with' and 'async with' by generating separate code for normal and exceptional paths. (#6641)
HEAD is now at 5dcc06f6e0... bpo-38858: Allocate small integers on the heap (GH-17301)
➜  cpython git:(5dcc06f6e0) ./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
msg358998 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2019-12-29 18:40
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.
msg359000 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2019-12-29 18:50
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
msg359035 - (view) Author: Mark Shannon (Mark.Shannon) * (Python committer) Date: 2019-12-30 11:21
Ned, I think this is fixed. Feel free to re-open if you disagree.
msg359037 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2019-12-30 12:39
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
msg359038 - (view) Author: Ned Batchelder (nedbat) * (Python triager) Date: 2019-12-30 12:55
BTW: this is not a regression in your fix. 3.9a2 behaved this way also.
msg359192 - (view) Author: Pablo Galindo Salgado (pablogsal) * (Python committer) Date: 2020-01-02 11:38
New changeset 04ec7a1f7a5b92187a73cd02670958444c6f2220 by Pablo Galindo in branch 'master':
bpo-39114: Fix tracing of except handlers with name binding (GH-17769)
https://github.com/python/cpython/commit/04ec7a1f7a5b92187a73cd02670958444c6f2220
History
Date User Action Args
2020-01-02 11:38:55pablogsalsetmessages: + msg359192
2019-12-31 08:53:24pablogsalsetkeywords: + patch
stage: resolved -> patch review
pull_requests: + pull_request17205
2019-12-30 12:55:04nedbatsetmessages: + msg359038
2019-12-30 12:39:54nedbatsetstatus: closed -> open

messages: + msg359037
2019-12-30 11:21:02Mark.Shannonsetstatus: open -> closed
resolution: fixed
messages: + msg359035

stage: resolved
2019-12-29 18:50:07Mark.Shannonsetkeywords: - patch

messages: + msg359000
stage: patch review -> (no value)
2019-12-29 18:48:04Mark.Shannonsetkeywords: + patch
stage: patch review
pull_requests: + pull_request17180
2019-12-29 18:40:50Mark.Shannonsetmessages: + msg358998
2019-12-23 16:45:03pablogsalsetnosy: + pablogsal
2019-12-21 19:45:12serhiy.storchakasetnosy: + serhiy.storchaka
2019-12-21 16:03:39zach.waresetkeywords: + 3.9regression
2019-12-21 14:52:40xtreaksetnosy: + Mark.Shannon
messages: + msg358773
2019-12-21 14:44:37xtreaksetnosy: + xtreak
2019-12-21 13:40:45nedbatcreate