Weirdness with traceback when resuming coroutines with coro.throw() #93592

kristjanvalur · 2022-06-07T21:29:18Z

Bug report

When a coroutine is resumed using coro.throw(), e.g. by using Task.cancel(), the frame.f_back chain becomes
mysteriously truncated at arbitrary places in the call stack.

Your environment

CPython versions tested on: 3.10.4
Operating system and architecture: Win 11

The following example pytest code demonstrates the problem. A recursive stack of coroutines is resumed, either normally (after a sleep) or by sending a CancelledError in. In the latter case, a traceback is generated and it is, in all cases, curiously truncated after just a few steps. Manually walking the stack will result in a f.f_back == None after a few steps.

I employ a few different recursions, including a manual await-like method operating directly on the coroutine protocol. Initially I suspected that coro.throw() was deliberatly engineeded to mess with the f.f_back of the frame chain, but even call stacks using regular coroutine recursion (the await keyword on async functions) appear truncated.

traceback.print_stack() is ultimately doing a f = sys._getframe() and following the f = f.f_back chain. It can just as easily be verified that this chain is broken with a None after a short bit.

import asyncio
import pytest
import types
import traceback


@types.coroutine
def myawait(coro):
    try:
        val = coro.send(None)
    except StopIteration as e:
        return e.value
    while True:
        try:
            val = yield val
        except BaseException as e:
            try:
                val = coro.throw(e)
            except StopIteration as e:
                return e.value
        else:
            try:
                val = coro.send(val)
            except StopIteration as e:
                return e.value

async def realawait(coro):
    return await coro

async def bas(result):
    return await bar(result)

async def foo1(result, n=2):
    if n:
        return await foo1(result, n-1)
    return await bas(result)

async def foo2(result, n=2):
    if n:
        return await foo2(result, n-1)
    return await realawait(bar(result))

async def foo3(result, n=2):
    if n:
        return await foo3(result, n-1)
    return await myawait(bar(result))

async def bar(result):
    try:
        await asyncio.sleep(0.1)
    except asyncio.CancelledError:
        traceback.print_stack(limit=5)
        result.append(False)
        result.append(traceback.format_stack())
    else:
        traceback.print_stack(limit=5)
        result.append(True)
        result.append(traceback.format_stack())
   
@pytest.mark.parametrize("func", [foo1, foo2, foo3])
async def test_regular(func):
    result = []
    t = asyncio.Task(func(result))
    await asyncio.sleep(0)
    await t
    ok, stack = result
    assert ok
    assert len(stack) > 5

@pytest.mark.xfail()
@pytest.mark.parametrize("func", [foo1, foo2, foo3])
async def test_truncated(func):
    result = []
    t = asyncio.Task(func(result))
    await asyncio.sleep(0)
    t.cancel()
    await t
    ok, stack = result
    assert not ok
    assert len(stack) > 5

The text was updated successfully, but these errors were encountered:

kristjanvalur · 2022-06-07T21:32:32Z

A successful run of foo1 in the test_regular run will cause a traceback.print_stack() to output the following:

  File "c:\git\python-async-df\tests\test_defects.py", line 35, in foo1
    return await foo1(result, n-1)
  File "c:\git\python-async-df\tests\test_defects.py", line 35, in foo1
    return await foo1(result, n-1)
  File "c:\git\python-async-df\tests\test_defects.py", line 36, in foo1
    return await bas(result)
  File "c:\git\python-async-df\tests\test_defects.py", line 31, in bas
    return await bar(result)
  File "c:\git\python-async-df\tests\test_defects.py", line 56, in bar
    traceback.print_stack(limit=5)

the same foo executed by test_truncated results in this output:

  File "c:\git\python-async-df\tests\test_defects.py", line 31, in bas
    return await bar(result)
  File "c:\git\python-async-df\tests\test_defects.py", line 52, in bar
    traceback.print_stack(limit=5)

kristjanvalur · 2022-06-08T08:47:09Z

I should add that this is not specific to CancelledError, its just the simplest exception to throw() into a coroutine from a Task.

markshannon · 2022-06-16T10:47:28Z

In which version(s) of Python does this happen?
(Have you tried this with 3.9 or 3.11?)

kristjanvalur · 2022-06-16T20:34:54Z

"CPython versions tested on: 3.10.4"
This being the most recent supported Python version, I see no reason to chase it down.

I used to be a regular cpython contributor but haven't built cpython from source in some 8 years, so, I cannot really help you further with the core diagnostics.

kristjanvalur · 2022-07-24T14:16:58Z

confirmed to exist in 3.7, 3.8, 3.9, 3.10. Fixed in 3.11

The following, short, test demonstrates the issue:

import types
import traceback

async def a():
    return await b()

async def b():
    return await c()

@types.coroutine
def c():
    try:
        traceback.print_stack()
        yield len(traceback.extract_stack())
    except ZeroDivisionError:
        traceback.print_stack()
        yield len(traceback.extract_stack())
        
r = a()
print(r.send(None))
print(r.throw(ZeroDivisionError))

(cherry picked from commit 771eff2) Co-authored-by: Kristján Valur Jónsson <sweskman@gmail.com>

kristjanvalur added the type-bug An unexpected behavior, bug, or error label Jun 7, 2022

kristjanvalur mentioned this issue Jul 24, 2022

[3.10] gh-93592: Fix frame chain when throwing exceptions into coroutines #95207

Merged

kristjanvalur added a commit to kristjanvalur/stackless that referenced this issue Aug 23, 2022

Port regression test for issue pythonGH-93592

2c995fd

bedevere-bot mentioned this issue Aug 23, 2022

gh-93592: Port regression test to main branch #96208

Merged

miss-islington pushed a commit to miss-islington/cpython that referenced this issue Aug 26, 2022

Port regression test for issue pythonGH-93592 (pythonGH-96208)

ac702ec

(cherry picked from commit 771eff2) Co-authored-by: Kristján Valur Jónsson <sweskman@gmail.com>

bedevere-bot mentioned this issue Aug 26, 2022

[3.11] Port regression test for issue GH-93592 (GH-96208) #96313

Merged

markshannon pushed a commit that referenced this issue Aug 26, 2022

Port regression test for issue GH-93592 (GH-96208)

771eff2

kristjanvalur closed this as completed Aug 26, 2022

markshannon pushed a commit that referenced this issue Aug 26, 2022

Port regression test for issue GH-93592 (GH-96208) (GH-96313)

acd7841

inureyes mentioned this issue Sep 9, 2022

setup: Bump python version from 3.10.5 to 3.10.7 lablup/backend.ai#719

Merged

Weirdness with traceback when resuming coroutines with coro.throw() #93592

Weirdness with traceback when resuming coroutines with coro.throw() #93592

kristjanvalur commented Jun 7, 2022 •

edited

kristjanvalur commented Jun 7, 2022

kristjanvalur commented Jun 8, 2022

markshannon commented Jun 16, 2022 •

edited

kristjanvalur commented Jun 16, 2022 •

edited

kristjanvalur commented Jul 24, 2022

Weirdness with traceback when resuming coroutines with coro.throw() #93592

Weirdness with traceback when resuming coroutines with coro.throw() #93592

Comments

kristjanvalur commented Jun 7, 2022 • edited

kristjanvalur commented Jun 7, 2022

kristjanvalur commented Jun 8, 2022

markshannon commented Jun 16, 2022 • edited

kristjanvalur commented Jun 16, 2022 • edited

kristjanvalur commented Jul 24, 2022

kristjanvalur commented Jun 7, 2022 •

edited

markshannon commented Jun 16, 2022 •

edited

kristjanvalur commented Jun 16, 2022 •

edited