asyncio: FutureIter_dealloc() crashes with negative refcount

[douglas-raillard-arm]

Crash report

What happened?

This is not a standalone reproducer as I'm still working on that, but the code triggering it is:

    @classmethod
    def _get_referred_objs(cls, obj, predicate=lambda x: True):
        visited = set()
        objs = []

        def update_refs(obj):
            obj_id = id(obj)
            # Avoid cycles. Use the id() of the objects directly since the
            # inclusion check is orders of magnitude faster than checking for
            # inclusing on the object directly. It also handles well non hashable
            # objects and broken __eq__ implementations.
            if obj_id in visited:
                return
            else:
                visited.add(obj_id)
                # Filter-out weird objects that end up in the list and that can
                # trigger a coredump on the interpreter
                with warnings.catch_warnings():
                    warnings.simplefilter("ignore")
                    has_class = hasattr(obj, '__class__')

                if has_class and predicate(obj):
                    objs.append(obj)

                for sub in gc.get_referents(obj):
                    update_refs(sub)

        update_refs(obj)
        return objs

The issue was triggered on Gentoo on an arm64 machine. For some reason, this works fine on x86-64. I then managed to trigger it again under a different Python 3.12.4 interpreter compiled from the git repo with debug symbols to get a gdb backtrace:

#6  0x0000aaaaaadfd4a0 in _PyObject_AssertFailed (obj=obj@entry=<_asyncio.FutureIter at remote 0xfffff210b3d0>, expr=expr@entry=0x0, 
    msg=msg@entry=0xaaaaaaea5c50 "object has negative ref count", file=<optimized out>, line=<optimized out>, 
    function=function@entry=0xaaaaaaed4928 <__func__.44.lto_priv.1> "_Py_NegativeRefcount") at Objects/object.c:2603
#7  0x0000aaaaaadfd550 in _Py_NegativeRefcount (filename=<optimized out>, lineno=<optimized out>, op=op@entry=<_asyncio.FutureIter at remote 0xfffff210b3d0>) at Objects/object.c:209
#8  0x0000fffff5df4bb0 in Py_DECREF (filename=filename@entry=0xfffff5dfba58 "./Modules/_asynciomodule.c", lineno=lineno@entry=1764, op=<_asyncio.FutureIter at remote 0xfffff210b3d0>)
    at ./Include/object.h:682
#9  0x0000fffff5df59a0 in FutureIter_clear (it=<optimized out>) at ./Modules/_asynciomodule.c:1764
#10 0x0000fffff5dfb57c in FutureIter_dealloc (it=0xfffff2109f50) at ./Modules/_asynciomodule.c:1601
#11 0x0000aaaaaabc9658 in _Py_Dealloc (op=op@entry=<_asyncio.FutureIter at remote 0xfffff2109f50>) at Objects/object.c:2625
#12 0x0000aaaaaabc9acc in Py_DECREF (filename=filename@entry=0xaaaaaae65f90 "./Include/object.h", lineno=lineno@entry=798, op=<_asyncio.FutureIter at remote 0xfffff2109f50>)
    at ./Include/object.h:690
#13 0x0000aaaaaabc9a68 in Py_XDECREF (op=<optimized out>) at ./Include/object.h:798
#14 0x0000aaaaaabc9780 in list_dealloc (op=0xffffdd2bc5a0) at Objects/listobject.c:356
#15 0x0000aaaaaabc9658 in _Py_Dealloc (

The Python backtrace at this point was deeply recursed in update_refs().

CPython versions tested on:

3.12

Operating systems tested on:

Linux

Output from running 'python -VV' on the command line:

Python 3.12.4 (tags/v3.12.4:8e8a4baf652, Aug 2 2024, 18:22:31) [GCC 13.3.1 20240614]

Linked PRs

• [3.12] gh-122695: Fix double-free when using gc.get_referents with a freed _asyncio.FutureIter #122834
• [3.13] gh-122695: Fix double-free when using gc.get_referents with a freed _asyncio.FutureIter #122837
• [3.12] gh-122695: Fix double-free when using gc.get_referents with a freed _asyncio.FutureIter (#122837) #122859

[ZeroIntensity]

I can take a look at this whenever you get a reproducer.

[vstinner]

Recent change related to FutureIter_dealloc(): commit 23192ab. Python 3.12.4 contains this change.

Do you reproduce this issue with Python 3.12.3?

[douglas-raillard-arm]

I'll give it a go on 3.12.3. On 3.12.4, I hit another symptom of the issue this weekend: instead of crashing on the assert, it sometimes throws the code in an infinite loop (or at least it takes more than ~20h to do a collection). It's not clear if the loop is coming from gc.get_referents() returning some sort of infinite stream of value or if the GC itself is just stuck. Here is the gdb backtrace of the process interrupted at a random point:

#0  0x0000aaaaaabced44 in _PyMem_IsPtrFreed (ptr=<optimized out>) at ./Include/internal/pycore_pymem.h:83
#1  0x0000aaaaaabceccc in _PyObject_IsFreed (op=op@entry=<_asyncio.FutureIter at remote 0xffff369d7b10>) at ./Include/object.h:220
#2  0x0000aaaaaac0c428 in visit_decref (op=<_asyncio.FutureIter at remote 0xffff369d7b10>, parent=0xfffff6427710) at Modules/gcmodule.c:463
#3  0x0000fffff5df4d84 in module_traverse (mod=<optimized out>, visit=0xaaaaaac0c410 <visit_decref>, arg=0xfffff6427710) at ./Modules/_asynciomodule.c:3610
#4  0x0000aaaaaabd600c in module_traverse (m=0xfffff6427710, visit=0xaaaaaac0c410 <visit_decref>, arg=0xfffff6427710) at Objects/moduleobject.c:874
#5  0x0000aaaaaac0b9b0 in subtract_refs (containers=containers@entry=0xaaaaab1a31e8 <_PyRuntime+92624>) at Modules/gcmodule.c:491
#6  0x0000aaaaaac0ad68 in deduce_unreachable (base=base@entry=0xaaaaab1a31e8 <_PyRuntime+92624>, unreachable=unreachable@entry=0xffffffffc1e8) at Modules/gcmodule.c:1116
#7  0x0000aaaaaac091a4 in gc_collect_main (tstate=tstate@entry=0xaaaaab200a70 <_PyRuntime+475736>, generation=generation@entry=2, n_collected=n_collected@entry=0xffffffffc270, 
    n_uncollectable=n_uncollectable@entry=0xffffffffc268, nofail=nofail@entry=0) at Modules/gcmodule.c:1242
#8  0x0000aaaaaac07e94 in gc_collect_with_callback (tstate=0xaaaaab200a70 <_PyRuntime+475736>, generation=2) at Modules/gcmodule.c:1426
#9  0x0000aaaaaac07e18 in gc_collect_generations (tstate=tstate@entry=0xaaaaab200a70 <_PyRuntime+475736>) at Modules/gcmodule.c:1481
#10 0x0000aaaaaac07c94 in _Py_RunGC (tstate=tstate@entry=0xaaaaab200a70 <_PyRuntime+475736>) at Modules/gcmodule.c:2295
#11 0x0000aaaaaac077e0 in _Py_HandlePending (tstate=tstate@entry=0xaaaaab200a70 <_PyRuntime+475736>) at Python/ceval_gil.c:1045
#12 0x0000aaaaaabf1eac in _PyEval_EvalFrameDefault (tstate=tstate@entry=0xaaaaab200a70 <_PyRuntime+475736>, frame=0xfffff74e9930, throwflag=throwflag@entry=0) at Python/ceval.c:834
#13 0x0000aaaaaabf1910 in _PyEval_EvalFrame (tstate=tstate@entry=0xaaaaab200a70 <_PyRuntime+475736>, frame=<optimized out>, throwflag=throwflag@entry=0)
    at ./Include/internal/pycore_ceval.h:89
#14 0x0000aaaaaabee828 in _PyEval_Vector (tstate=0xaaaaab200a70 <_PyRuntime+475736>, func=0xffff369baf90, locals=locals@entry=0x0, args=0xffffffffc550, argcount=1, kwnames=0x0)
    at Python/ceval.c:1683

[douglas-raillard-arm]

Now trying with Python 3.12.3 (tags/v3.12.3:f6650f9ad73, Aug 6 2024, 10:09:17) [GCC 13.3.1 20240614] and I get the same "stuck in garbage collector" symptom (I stopped and continued 10 times with random delays and I always land on a backtrace starting with Garbage-collecting):

Traceback (most recent call first):
  Garbage-collecting
  File "/home/dourai01/cpython/Lib/abc.py", line 123, in __subclasscheck__
    return _abc_subclasscheck(cls, subclass)
  File "/home/dourai01/cpython/Lib/abc.py", line 123, in __subclasscheck__
    return _abc_subclasscheck(cls, subclass)
  File "/home/dourai01/cpython/Lib/abc.py", line 123, in __subclasscheck__
    return _abc_subclasscheck(cls, subclass)
  File "/home/dourai01/cpython/Lib/abc.py", line 123, in __subclasscheck__
    return _abc_subclasscheck(cls, subclass)
  File "/home/dourai01/cpython/Lib/abc.py", line 119, in __instancecheck__
    return _abc_instancecheck(cls, instance)
  File "/home/dourai01/lisa/lisa/tests/base.py", line 1168, in predicate
    return isinstance(x, TestBundleBase)
  File "/home/dourai01/lisa/lisa/tests/base.py", line 1144, in update_refs
    if has_class and predicate(obj):
  File "/home/dourai01/lisa/lisa/tests/base.py", line 1148, in update_refs
    update_refs(sub)
  File "/home/dourai01/lisa/lisa/tests/base.py", line 1148, in update_refs
    update_refs(sub)
  File "/home/dourai01/lisa/lisa/tests/base.py", line 1148, in update_refs

[...]

The C backtrace looks like that:

#0  0x0000aaaaaabce7d8 in _PyMem_IsPtrFreed (ptr=ptr@entry=0xffff368a7490) at ./Include/internal/pycore_pymem.h:83
#1  0x0000aaaaaabce754 in _PyObject_IsFreed (op=op@entry=<_asyncio.FutureIter at remote 0xffff368a7490>) at Objects/object.c:468
#2  0x0000aaaaaac0be50 in visit_decref (op=<_asyncio.FutureIter at remote 0xffff368a7490>, parent=0xfffff64cdcd0) at Modules/gcmodule.c:463
#3  0x0000fffff5d54d84 in module_traverse (mod=<optimized out>, visit=0xaaaaaac0be38 <visit_decref>, arg=0xfffff64cdcd0) at ./Modules/_asynciomodule.c:3596
#4  0x0000aaaaaabd5a8c in module_traverse (m=0xfffff64cdcd0, visit=0xaaaaaac0be38 <visit_decref>, arg=0xfffff64cdcd0) at Objects/moduleobject.c:874
#5  0x0000aaaaaac0b3d8 in subtract_refs (containers=containers@entry=0xaaaaab1a2738 <_PyRuntime+92576>) at Modules/gcmodule.c:491
#6  0x0000aaaaaac0a790 in deduce_unreachable (base=base@entry=0xaaaaab1a2738 <_PyRuntime+92576>, unreachable=unreachable@entry=0xffffffffaeb8) at Modules/gcmodule.c:1116
#7  0x0000aaaaaac08bcc in gc_collect_main (tstate=tstate@entry=0xaaaaab1fffc0 <_PyRuntime+475688>, generation=generation@entry=2, n_collected=n_collected@entry=0xffffffffaf40, 
    n_uncollectable=n_uncollectable@entry=0xffffffffaf38, nofail=nofail@entry=0) at Modules/gcmodule.c:1242
#8  0x0000aaaaaac078bc in gc_collect_with_callback (tstate=0xaaaaab1fffc0 <_PyRuntime+475688>, generation=2) at Modules/gcmodule.c:1426
#9  0x0000aaaaaac07840 in gc_collect_generations (tstate=tstate@entry=0xaaaaab1fffc0 <_PyRuntime+475688>) at Modules/gcmodule.c:1481
#10 0x0000aaaaaac076bc in _Py_RunGC (tstate=tstate@entry=0xaaaaab1fffc0 <_PyRuntime+475688>) at Modules/gcmodule.c:2295
#11 0x0000aaaaaac07208 in _Py_HandlePending (tstate=tstate@entry=0xaaaaab1fffc0 <_PyRuntime+475688>) at Python/ceval_gil.c:1045
#12 0x0000aaaaaabf1a6c in _PyEval_EvalFrameDefault (tstate=tstate@entry=0xaaaaab1fffc0 <_PyRuntime+475688>, frame=0xfffff7f0de70, throwflag=throwflag@entry=0) at Python/ceval.c:834
#13 0x0000aaaaaabf1378 in _PyEval_EvalFrame (tstate=tstate@entry=0xaaaaab1fffc0 <_PyRuntime+475688>, frame=<optimized out>, throwflag=throwflag@entry=0)
    at ./Include/internal/pycore_ceval.h:89
#14 0x0000aaaaaabee290 in _PyEval_Vector (tstate=0xaaaaab1fffc0 <_PyRuntime+475688>, func=func@entry=0xfffff7839c10, locals=locals@entry=0x0, args=args@entry=0xffffffffb2e8, 
    argcount=argcount@entry=2, kwnames=kwnames@entry=0x0) at Python/ceval.c:1683
#15 0x0000aaaaaac4663c in _PyFunction_Vectorcall (func=func@entry=<function at remote 0xfffff7839c10>, stack=stack@entry=0xffffffffb2e8, nargsf=nargsf@entry=2, kwnames=kwnames@entry=0x0)
    at Objects/call.c:419
#16 0x0000aaaaaac8ce2c in _PyObject_VectorcallTstate (tstate=tstate@entry=0xaaaaab1fffc0 <_PyRuntime+475688>, callable=callable@entry=<function at remote 0xfffff7839c10>, 
    args=args@entry=0xffffffffb2e8, nargsf=nargsf@entry=2, kwnames=kwnames@entry=0x0) at ./Include/internal/pycore_call.h:92
#17 0x0000aaaaaac8c134 in method_vectorcall (method=<optimized out>, args=0xffffffffb2f0, nargsf=9223372036854775809, kwnames=0x0) at Objects/classobject.c:61
#18 0x0000aaaaaabdcea8 in _PyObject_VectorcallTstate (tstate=0xaaaaab1fffc0 <_PyRuntime+475688>, callable=callable@entry=<method at remote 0xffffcdcfdc10>, args=args@entry=0xffffffffb2f0, 
    nargsf=nargsf@entry=9223372036854775809, kwnames=kwnames@entry=0x0) at ./Include/internal/pycore_call.h:92
#19 0x0000aaaaaac4c2b4 in PyObject_CallOneArg (func=func@entry=<method at remote 0xffffcdcfdc10>, arg=arg@entry=<type at remote 0xaaaaab0ea7d0>) at Objects/call.c:401
#20 0x0000aaaaaac7fd1c in object_issubclass (tstate=0xaaaaab1fffc0 <_PyRuntime+475688>, derived=derived@entry=<type at remote 0xaaaaab0ea7d0>, 
    cls=cls@entry=<TestBundleMeta(__module__='lisa.tests.base', __doc__='Dummy class used as a base class for all tests.\n\n.. warning:: Arbitrary code can be executed while loading an instance from a YAML or Pickle file. To include untrusted data in YAML, use the !untrusted tag along with a string\n\n.. note:: As a subclass of :class:`lisa.tests.base.TestBundleBase`, this class is considered as "application" and its API is therefore more subject to change than other parts of :mod:`lisa`.', check_from_target=<classmethod at remote 0xffff36a61b80>, FTRACE_CONF=<FtraceConf(_key_desc_path=[], _src_prio=['TestBundle(required)', 'TestBundle'], _src_override={}, _key_map={'buffer-size': {'TestBundle': 10240}, 'events': {'TestBundle': <AndTraceEventChecker(check=True, checkers=[], op_str='and', prefix_str='') at remote 0xffff368ab440>, 'TestBundle(required)': <AndTraceEventChecker(check=True, checkers=[], op_str='and', prefix_str='') at remote 0xffff368ab990>}, 'events-namespaces': {'TestBundle': [], 'TestBundle(required)': []}, 'sav...(truncated)) at Objects/abstract.c:2736
#21 0x0000aaaaaac7fae0 in PyObject_IsSubclass (derived=derived@entry=<type at remote 0xaaaaab0ea7d0>, 
    cls=cls@entry=<TestBundleMeta(__module__='lisa.tests.base', __doc__='Dummy class used as a base class for all tests.\n\n.. warning:: Arbitrary code can be executed while loading an instance from a YAML or Pickle file. To include untrusted data in YAML, use the !untrusted tag along with a string\n\n.. note:: As a subclass of :class:`lisa.tests.base.TestBundleBase`, this class is considered as "application" and its API is therefore more subject to change than other parts of :mod:`lisa`.', check_from_target=<classmethod at remote 0xffff36a61b80>, FTRACE_CONF=<FtraceConf(_key_desc_path=[], _src_prio=['TestBundle(required)', 'TestBundle'], _src_override={}, _key_map={'buffer-size': {'TestBundle': 10240}, 'events': {'TestBundle': <AndTraceEventChecker(check=True, checkers=[], op_str='and', prefix_str='') at remote 0xffff368ab440>, 'TestBundle(required)': <AndTraceEventChecker(check=True, checkers=[], op_str='and', prefix_str='') at remote 0xffff368ab990>}, 'events-namespaces': {'TestBundle': [], 'TestBundle(required)': []}, 'sav...(truncated)) at Objects/abstract.c:2758
#22 0x0000aaaaaacbd030 in _abc__abc_subclasscheck_impl (module=module@entry=<module at remote 0xfffff7849190>, self=<optimized out>, subclass=<type at remote 0xaaaaab0ea7d0>)
    at ./Modules/_abc.c:779
#23 0x0000aaaaaacbcbf0 in _abc__abc_subclasscheck (module=<module at remote 0xfffff7849190>, args=args@entry=0xfffff7f0de60, nargs=nargs@entry=2) at ./Modules/clinic/_abc.c.h:141

[vstinner]

This is not a standalone reproducer as I'm still working on that

Obviously, the debug will be way easier with a reproducer :-)

[douglas-raillard-arm]

I've spent some time trying to get a minimal reproducer and could not get it to work. It's possible this is related to running under pytest for some reason. As it stands, the only reproducer I can offer is:

1. install lisa from the git repo: https://gitlab.arm.com/tooling/lisa

git clone https://gitlab.arm.com/tooling/lisa
cd lisa
# A few packages need to be installed, like python3 or kernelshark. Python
# modules will be installed in a venv at the next step, without touching
# any system-wide install location.
./install_base.sh --install-all

# LISA_PYTHON value cannot be a path apparently, otherwise venv gets confused. Add the relevant folder to PATH first and set LISA_PYTHON to the binary filename.
export LISA_PYTHON=<name of your python binary>

# On the first run, it will take care of creating a Python venv and populating it. This will take LISA_PYTHON into account when creating the venv
source init_env

2. Run the offending test on an arm64 platform: gdb $LISA_PYTHON -ex 'run -m pytest -s tests/test_test_bundle.py'

EDIT: remove -ex quit

[douglas-raillard-arm]

A bit of progress with gdb on v3.12.3 : the infinite loop is here:
((futureiterobject*) current)->future is set to current, so it keeps going around without making any progress.

EDIT: It looks like module_free_freelists would cause a refcount issue if current->future == current since it calls PyObject_GC_Del(current); and then will try with current->future at the next iteration. That would try to garbage collect the same object multiple times.

[douglas-raillard-arm]

I added some asserts on v3.12.3 tag:

diff --git a/Modules/_asynciomodule.c b/Modules/_asynciomodule.c
index a465090bfaa..9b47661b1fc 100644
--- a/Modules/_asynciomodule.c
+++ b/Modules/_asynciomodule.c
@@ -1597,6 +1597,7 @@ FutureIter_dealloc(futureiterobject *it)
     if (state->fi_freelist_len < FI_FREELIST_MAXLEN) {
         state->fi_freelist_len++;
         it->future = (FutureObj*) state->fi_freelist;
+        assert((void*)it->future != (void*)it);
         state->fi_freelist = it;
     }
     else {
@@ -1818,6 +1819,7 @@ future_new_iter(PyObject *fut)
     }
 
     it->future = (FutureObj*)Py_NewRef(fut);
+    assert((void*)it->future != (void*)it);
     PyObject_GC_Track(it);
     return (PyObject*)it;
 }
@@ -3595,6 +3597,7 @@ module_traverse(PyObject *mod, visitproc visit, void *arg)
         PyObject *current = next;
         Py_VISIT(current);
         next = (PyObject*) ((futureiterobject*) current)->future;
+        assert((void*)next != (void*)current);
     }
     return 0;
 }

And this one failed to pass:

static void 
FutureIter_dealloc(futureiterobject *it) 
{ 
    PyTypeObject *tp = Py_TYPE(it); 
    asyncio_state *state = get_asyncio_state_by_def((PyObject *)it); 
    PyObject_GC_UnTrack(it); 
    tp->tp_clear((PyObject *)it); 
 
    if (state->fi_freelist_len < FI_FREELIST_MAXLEN) { 
        state->fi_freelist_len++; 
        it->future = (FutureObj*) state->fi_freelist; 
        assert((void*)it->future != (void*)it); // <------- ADDED THIS ASSERT
        state->fi_freelist = it; 
    } 
    else { 
        PyObject_GC_Del(it); 
        Py_DECREF(tp); 
    } 
} 

[ZeroIntensity]

At a very speculative glance, I would guess that the infinite loop problem originates from visited and obj, or possibly the context returned by warnings.catch_warnings, being tracked by the GC. It's difficult to tell without a full reproducer, though.

[douglas-raillard-arm]

@ZeroIntensity unfortunately I could not create a reproducer beyond the existing test suite, but I'm happy to apply a patch on cpython and run with that to help diagnose further, provide coredumps etc.

What is quite strange that this only triggers an issue on arm64 where there seemingly is nothing arch-specific in that code I could see. That test has been running on x86-64 since ~2018 without problems (obviously not on Python 3.12 all this time but still).

[ZeroIntensity]

If this only happens on ARM, then I think this might be an actual bug with the garbage collector. Since we don't have a standalone reproducer, you'll have to help me here a bit:

• Is there a repository where you're running this? If we could run the test suite and reproduce the bug locally, that's still better than no reproducer.
• What line specifically causes this? (as in, if you comment things out, commenting out which line(s) prevents the segfault/infinite loop?)
• Does this happen on other CPython versions (main branch, 3.13, 3.11, etc)

[douglas-raillard-arm]

If this only happens on ARM, then I think this might be an actual bug with the garbage collector.

That was my initial guess, but then the issue seemed to be a logic issue in Modules/_asynciomodule.c . It's hard to know for sure though as it could just be an invariant the gc is supposed to provide that is broken.

Is there a repository where you're running this? If we could run the test suite and reproduce the bug locally, that's still better than no reproducer.

Yes, see #122695 (comment) . You may be able to skip the install_base.sh part and either just source init_env or create your own venv and pip install -r devmode_requirements.txt .

The issue manifests as either the test hanging or sometimes (rarely) triggering a negative refcount check assert.

What line specifically causes this? (as in, if you comment things out, commenting out which line(s) prevents the segfault/infinite loop?)

The gc hangs while executing that function:
https://gitlab.arm.com/tooling/lisa/-/blob/main/lisa/tests/base.py?ref_type=heads#L1128
Sometimes it hangs inside predicate(obj) that is defined here as can be seen on this Python backtrace: #122695 (comment)

But the exact location is kind of variable and probably depends on when the gc decides to run. Always inside update_ref() though.

Does this happen on other CPython versions (main branch, 3.13, 3.11, etc)

So far I've tested 3.12.3 and 3.12.4 and it fails on both. I don't think I can easily test on 3.13 as some of our dependencies have extension modules that may or may not be compatible with 3.13, but I may be able to hack through the code to still have the offending code run with no dep.

[ZeroIntensity]

Apologies, my connection is slow at the moment so I've been trying to install it for the past hour. I'll see if I can reproduce it locally whenever it installs. Does lisa contain any C extensions? (If so, this might be user-error.)