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)

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

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.

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

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

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

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

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