Issue 39166: Python 3.9.0a2 changed how "async for" traces its final iteration

3.9.0a2 changed how the final iteration of "async for" is traced.  The body of the loop is traced when the body is not executed.  Standard "for" loops don't show the same effect.

In the output below, notice that 3.9.0a2 and 3.9.0a2+ both show one last execution of line 32, but that line is not actually executed (there is no output).  The standard for loop doesn't show line 27 doing that in any version.

--- 8< ----------------------------------------------------
import linecache, sys

def trace(frame, event, arg):
    # The weird globals here is to avoid a NameError on shutdown...
    if frame.f_code.co_filename == globals().get("__file__"):
        lineno = frame.f_lineno
        print("{} {}: {}".format(event[:4], lineno, linecache.getline(__file__, lineno).rstrip()))
    return trace

import asyncio

class AsyncIteratorWrapper:
    def __init__(self, obj):
        self._it = iter(obj)

    def __aiter__(self):
        return self

    async def __anext__(self):
        try:
            return next(self._it)
        except StopIteration:
            raise StopAsyncIteration

def doit_sync():
    for letter in "ab":
        print(letter)
    print(".")

async def doit_async():
    async for letter in AsyncIteratorWrapper("ab"):
        print(letter)
    print(".")

print(sys.version)
sys.settrace(trace)

doit_sync()

loop = asyncio.new_event_loop()
loop.run_until_complete(doit_async())
loop.close()
--- 8< ----------------------------------------------------



$ /usr/local/pythonz/pythons/CPython-3.9.0a1/bin/python3.9 /tmp/bpo2.py
3.9.0a1 (default, Nov 20 2019, 18:52:14)
[Clang 10.0.0 (clang-1000.10.44.4)]
call 25: def doit_sync():
line 26:     for letter in "ab":
line 27:         print(letter)
a
line 26:     for letter in "ab":
line 27:         print(letter)
b
line 26:     for letter in "ab":
line 28:     print(".")
.
retu 28:     print(".")
call 30: async def doit_async():
line 31:     async for letter in AsyncIteratorWrapper("ab"):
call 13:     def __init__(self, obj):
line 14:         self._it = iter(obj)
retu 14:         self._it = iter(obj)
call 16:     def __aiter__(self):
line 17:         return self
retu 17:         return self
call 19:     async def __anext__(self):
line 20:         try:
line 21:             return next(self._it)
retu 21:             return next(self._it)
exce 31:     async for letter in AsyncIteratorWrapper("ab"):
line 32:         print(letter)
a
line 31:     async for letter in AsyncIteratorWrapper("ab"):
call 19:     async def __anext__(self):
line 20:         try:
line 21:             return next(self._it)
retu 21:             return next(self._it)
exce 31:     async for letter in AsyncIteratorWrapper("ab"):
line 32:         print(letter)
b
line 31:     async for letter in AsyncIteratorWrapper("ab"):
call 19:     async def __anext__(self):
line 20:         try:
line 21:             return next(self._it)
exce 21:             return next(self._it)
line 22:         except StopIteration:
line 23:             raise StopAsyncIteration
exce 23:             raise StopAsyncIteration
retu 23:             raise StopAsyncIteration
exce 31:     async for letter in AsyncIteratorWrapper("ab"):
line 33:     print(".")
.
retu 33:     print(".")

$ /usr/local/pythonz/pythons/CPython-3.9.0a2/bin/python3.9 /tmp/bpo2.py
3.9.0a2 (default, Dec 19 2019, 08:42:29)
[Clang 10.0.0 (clang-1000.10.44.4)]
call 25: def doit_sync():
line 26:     for letter in "ab":
line 27:         print(letter)
a
line 26:     for letter in "ab":
line 27:         print(letter)
b
line 26:     for letter in "ab":
line 28:     print(".")
.
retu 28:     print(".")
call 30: async def doit_async():
line 31:     async for letter in AsyncIteratorWrapper("ab"):
call 13:     def __init__(self, obj):
line 14:         self._it = iter(obj)
retu 14:         self._it = iter(obj)
call 16:     def __aiter__(self):
line 17:         return self
retu 17:         return self
call 19:     async def __anext__(self):
line 20:         try:
line 21:             return next(self._it)
retu 21:             return next(self._it)
exce 31:     async for letter in AsyncIteratorWrapper("ab"):
line 32:         print(letter)
a
line 31:     async for letter in AsyncIteratorWrapper("ab"):
call 19:     async def __anext__(self):
line 20:         try:
line 21:             return next(self._it)
retu 21:             return next(self._it)
exce 31:     async for letter in AsyncIteratorWrapper("ab"):
line 32:         print(letter)
b
line 31:     async for letter in AsyncIteratorWrapper("ab"):
call 19:     async def __anext__(self):
line 20:         try:
line 21:             return next(self._it)
exce 21:             return next(self._it)
line 22:         except StopIteration:
line 23:             raise StopAsyncIteration
exce 23:             raise StopAsyncIteration
retu 23:             raise StopAsyncIteration
exce 31:     async for letter in AsyncIteratorWrapper("ab"):
line 32:         print(letter)
line 33:     print(".")
.
retu 33:     print(".")

$ /usr/local/cpython/bin/python3.9 /tmp/bpo2.py
3.9.0a2+ (heads/master:89aa7f0ede, Dec 30 2019, 07:52:33)
[Clang 10.0.0 (clang-1000.10.44.4)]
call 25: def doit_sync():
line 26:     for letter in "ab":
line 27:         print(letter)
a
line 26:     for letter in "ab":
line 27:         print(letter)
b
line 26:     for letter in "ab":
line 28:     print(".")
.
retu 28:     print(".")
call 30: async def doit_async():
line 31:     async for letter in AsyncIteratorWrapper("ab"):
call 13:     def __init__(self, obj):
line 14:         self._it = iter(obj)
retu 14:         self._it = iter(obj)
call 16:     def __aiter__(self):
line 17:         return self
retu 17:         return self
call 19:     async def __anext__(self):
line 20:         try:
line 21:             return next(self._it)
retu 21:             return next(self._it)
exce 31:     async for letter in AsyncIteratorWrapper("ab"):
line 32:         print(letter)
a
line 31:     async for letter in AsyncIteratorWrapper("ab"):
call 19:     async def __anext__(self):
line 20:         try:
line 21:             return next(self._it)
retu 21:             return next(self._it)
exce 31:     async for letter in AsyncIteratorWrapper("ab"):
line 32:         print(letter)
b
line 31:     async for letter in AsyncIteratorWrapper("ab"):
call 19:     async def __anext__(self):
line 20:         try:
line 21:             return next(self._it)
exce 21:             return next(self._it)
line 22:         except StopIteration:
line 23:             raise StopAsyncIteration
exce 23:             raise StopAsyncIteration
retu 23:             raise StopAsyncIteration
exce 31:     async for letter in AsyncIteratorWrapper("ab"):
line 32:         print(letter)
line 33:     print(".")
.
retu 33:     print(".")

$

Ned, can you confirm that the trace has changed from 3.8 to 3.9?

The bytecode for `doit_async` is identical for 3.8 and 3.9.

I see that you are right, the bytecode is the same in 3.8 and 3.9. Nevertheless, the trace has definitely changed.  Using the same program from the top of the issue, here are the ends of the traces for a number of Python versions.  The extra trace of line 32 appears in 3.9.0a2:


$ for v in 3.6.9 3.7.4 3.8.1 3.9.0a1 3.9.0a2; do printf "\n--------\n"; $(pythonz locate $v) -c "import sys; print(sys.version)"; $(pythonz locate $v) /tmp/bpo2.py | tail -10; done

--------
3.6.9 (default, Jul 29 2019, 08:21:55)
[GCC 4.2.1 Compatible Apple LLVM 10.0.0 (clang-1000.10.44.4)]
line 21:             return next(self._it)
exce 21:             return next(self._it)
line 22:         except StopIteration:
line 23:             raise StopAsyncIteration
exce 23:             raise StopAsyncIteration
retu 23:             raise StopAsyncIteration
exce 31:     async for letter in AsyncIteratorWrapper("ab"):
line 33:     print(".")
.
retu 33:     print(".")

--------
3.7.4 (default, Jul 11 2019, 19:53:42)
[Clang 10.0.0 (clang-1000.10.44.4)]
line 21:             return next(self._it)
exce 21:             return next(self._it)
line 22:         except StopIteration:
line 23:             raise StopAsyncIteration
exce 23:             raise StopAsyncIteration
retu 23:             raise StopAsyncIteration
exce 31:     async for letter in AsyncIteratorWrapper("ab"):
line 33:     print(".")
.
retu 33:     print(".")

--------
3.8.1 (default, Dec 19 2019, 08:38:38)
[Clang 10.0.0 (clang-1000.10.44.4)]
line 21:             return next(self._it)
exce 21:             return next(self._it)
line 22:         except StopIteration:
line 23:             raise StopAsyncIteration
exce 23:             raise StopAsyncIteration
retu 23:             raise StopAsyncIteration
exce 31:     async for letter in AsyncIteratorWrapper("ab"):
line 33:     print(".")
.
retu 33:     print(".")

--------
3.9.0a1 (default, Nov 20 2019, 18:52:14)
[Clang 10.0.0 (clang-1000.10.44.4)]
line 21:             return next(self._it)
exce 21:             return next(self._it)
line 22:         except StopIteration:
line 23:             raise StopAsyncIteration
exce 23:             raise StopAsyncIteration
retu 23:             raise StopAsyncIteration
exce 31:     async for letter in AsyncIteratorWrapper("ab"):
line 33:     print(".")
.
retu 33:     print(".")

--------
3.9.0a2 (default, Dec 19 2019, 08:42:29)
[Clang 10.0.0 (clang-1000.10.44.4)]
exce 21:             return next(self._it)
line 22:         except StopIteration:
line 23:             raise StopAsyncIteration
exce 23:             raise StopAsyncIteration
retu 23:             raise StopAsyncIteration
exce 31:     async for letter in AsyncIteratorWrapper("ab"):
line 32:         print(letter)
line 33:     print(".")
.
retu 33:     print(".")

$

Bisecting points me to fee552669f . I tried compiling latest master with the bytecode changes and the behavior is same as reported.

➜  cpython git:(5dcc06f6e0) ./python ../backups/bpo39166.py > fee552669f_before.txt
➜  cpython git:(5dcc06f6e0) ✗ git checkout fee552669f                                
➜  cpython git:(fee552669f) ✗ make -s -j4 > /dev/null 
➜  cpython git:(fee552669f) ✗ ./python ../backups/bpo39166.py > fee552669f.txt       
➜  cpython git:(fee552669f) ✗ diff fee552669f.txt fee552669f_before.txt 
1c1
< 3.9.0a1+ (tags/v3.9.0a1-43-gfee552669f:fee552669f, Jan  1 2020, 18:51:56) 
---
> 3.9.0a1+ (tags/v3.9.0a1-42-g5dcc06f6e0:5dcc06f6e0, Jan  1 2020, 18:49:53) 
47d46
< line 33:         print(letter)

With master

➜  cpython git:(master) ./python ../backups/bpo39166.py > master.txt
➜  cpython git:(master) ✗ diff fee552669f_before.txt master.txt
1c1
< 3.9.0a1+ (tags/v3.9.0a1-42-g5dcc06f6e0:5dcc06f6e0, Jan  1 2020, 18:49:53) 
---
> 3.9.0a2+ (heads/master:22424c02e5, Jan  1 2020, 18:55:29) 
46a47
> line 33:         print(letter)

Can you check if this is fixed with the changes in:

https://github.com/python/cpython/pull/17769

Pablo, thanks, but that PR does not fix this problem.

I'm a little confused: there's a program in this issue to demonstrate the problem.  Can I do something to make it easier for you to use?

> I'm a little confused: there's a program in this issue to demonstrate the problem.  Can I do something to make it easier for you to use?

Sorry for the confusion, I was asking because at the time of asking I didn't have access to a computer to check myself.

I will investigate tonight as soon as I can get to my computer.

New changeset 4c53e63cc966f98e141a09bc435b9f9c713b152d by Mark Shannon (Pablo Galindo) in branch 'master':
bpo-39166: Fix trace of last iteration of async for loops (#17800)
https://github.com/python/cpython/commit/4c53e63cc966f98e141a09bc435b9f9c713b152d

I think this is now fixed.

Ned, feel free to reopen if it still isn't fixed.

stage: patch review -> resolved