Race condition leading to infinite loop in asyncio/base_events.py

[TheTechromancer]

Bug report

Bug description:

Thanks for taking the time to look at this issue.

Recently I've been running into a rare and insidious race condition that can result in a deadlock. The condition triggers when asyncio debugging is enabled (PYTHONASYNCIODEBUG=1), and a slow callback is encountered:

cpython/Lib/asyncio/base_events.py

Lines 1899 to 1901 in 9e9c71d

	if dt >= self.slow_callback_duration:
	logger.warning('Executing %s took %.3f seconds',
	_format_handle(handle), dt)

We first encountered the issue during our test runs, where it would occur probably approximately 1 out of 4000 times the above message was printed.

The deadlock is actually some form of "livelock", where the interpreter appears to be frozen, but CPU usage is stuck at 100%. The stack trace looks similar to a recursion bug; however it doesn't seem to descend far enough to trigger a RecursionError, so it survives as an infinite loop.

It took me weeks to track it down, and in the end I was only able to get the stack trace by attaching to the frozen python process with gdb:

  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 634, in run_until_complete
    self.run_forever()
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 601, in run_forever
    self._run_once()
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1901, in _run_once
    _format_handle(handle), dt)
  File "/usr/local/lib/python3.9/asyncio/base_events.py", line 78, in _format_handle
    return repr(cb.__self__)
  File "/usr/local/lib/python3.9/asyncio/base_tasks.py", line 21, in _task_repr_info
    info.insert(3, f'wait_for={task._fut_waiter!r}')
  File "/usr/local/lib/python3.9/asyncio/base_futures.py", line 76, in _future_repr_info
    info.append(_format_callbacks(future._callbacks))
  File "/usr/local/lib/python3.9/asyncio/base_futures.py", line 37, in _format_callbacks
    cb = '{}, {}'.format(format_cb(cb[0][0]), format_cb(cb[1][0]))
  File "/usr/local/lib/python3.9/asyncio/base_futures.py", line 32, in format_cb
    return format_helpers._format_callback_source(callback, ())
  File "/usr/local/lib/python3.9/asyncio/format_helpers.py", line 23, in _format_callback_source
    func_repr = _format_callback(func, args, None)
  File "/usr/local/lib/python3.9/asyncio/format_helpers.py", line 47, in _format_callback
    return _format_callback(func.func, func.args, func.keywords, suffix)
  File "/usr/local/lib/python3.9/asyncio/format_helpers.py", line 56, in _format_callback
    func_repr += _format_args_and_kwargs(args, kwargs)
  File "/usr/local/lib/python3.9/asyncio/format_helpers.py", line 40, in _format_args_and_kwargs
    items.extend(f'{k}={reprlib.repr(v)}' for k, v in kwargs.items())
  File "/usr/local/lib/python3.9/asyncio/format_helpers.py", line 40, in <genexpr>
    items.extend(f'{k}={reprlib.repr(v)}' for k, v in kwargs.items())
  File "/usr/local/lib/python3.9/reprlib.py", line 52, in repr
    return self.repr1(x, self.maxlevel)
  File "/usr/local/lib/python3.9/reprlib.py", line 60, in repr1
    return getattr(self, 'repr_' + typename)(x, level)
  File "/usr/local/lib/python3.9/reprlib.py", line 103, in repr_deque
    return self._repr_iterable(x, level, 'deque([', '])', self.maxdeque)
  File "/usr/local/lib/python3.9/reprlib.py", line 71, in _repr_iterable
    pieces = [repr1(elem, newlevel) for elem in islice(x, maxiter)]
  File "/usr/local/lib/python3.9/reprlib.py", line 71, in <listcomp>
    pieces = [repr1(elem, newlevel) for elem in islice(x, maxiter)]
  File "/usr/local/lib/python3.9/reprlib.py", line 62, in repr1
    return self.repr_instance(x, level)
  File "/usr/local/lib/python3.9/reprlib.py", line 139, in repr_instance
    s = builtins.repr(x)
  File "/usr/local/lib/python3.9/collections/__init__.py", line 458, in __repr__
    return self.__class__.__name__ + repr_fmt % self

    ...repeats ~40 times
    
    return self.__class__.__name__ + repr_fmt % self
  File "/usr/local/lib/python3.9/asyncio/base_futures.py", line 76, in _future_repr_info
    info.append(_format_callbacks(future._callbacks))
  File "/usr/local/lib/python3.9/asyncio/base_futures.py", line 37, in _format_callbacks
    cb = '{}, {}'.format(format_cb(cb[0][0]), format_cb(cb[1][0]))
  File "/usr/local/lib/python3.9/asyncio/base_futures.py", line 32, in format_cb
    return format_helpers._format_callback_source(callback, ())
  File "/usr/local/lib/python3.9/asyncio/format_helpers.py", line 23, in _format_callback_source
    func_repr = _format_callback(func, args, None)
  File "/usr/local/lib/python3.9/asyncio/format_helpers.py", line 47, in _format_callback
    return _format_callback(func.func, func.args, func.keywords, suffix)
  File "/usr/local/lib/python3.9/asyncio/format_helpers.py", line 56, in _format_callback
    func_repr += _format_args_and_kwargs(args, kwargs)
  File "/usr/local/lib/python3.9/asyncio/format_helpers.py", line 40, in _format_args_and_kwargs
    items.extend(f'{k}={reprlib.repr(v)}' for k, v in kwargs.items())
  File "/usr/local/lib/python3.9/asyncio/format_helpers.py", line 40, in <genexpr>
    items.extend(f'{k}={reprlib.repr(v)}' for k, v in kwargs.items())
  File "/usr/local/lib/python3.9/reprlib.py", line 52, in repr
    return self.repr1(x, self.maxlevel)
  File "/usr/local/lib/python3.9/reprlib.py", line 62, in repr1
    return self.repr_instance(x, level)
  File "/usr/local/lib/python3.9/reprlib.py", line 139, in repr_instance
    s = builtins.repr(x)
  File "/usr/local/lib/python3.9/collections/__init__.py", line 458, in __repr__
    return self.__class__.__name__ + repr_fmt % self
  File "<string>", line 1, in <module>

Full traceback:
python_traceback.txt

CPython versions tested on:

3.9

Operating systems tested on:

Linux

[ZeroIntensity]

At first glance, this looks like a recursive __repr__, but as you said not deep enough to trigger a RecursionError. FWIW, this was also reproduced only on 3.9 -- we can't fix anything (other than security fixes) on that version. Does this occur on 3.12+?

[TheTechromancer]

Thanks for the quick response. Yes we are encountering the bug in 3.12 as well. I haven't confirmed with the traceback that it's the same one, but I suspect it is.

[ZeroIntensity]

Got it, do you have a reproducer?

[TheTechromancer]

I'm working on one; should hopefully have it shortly.

[ZeroIntensity]

Can someone add the topic-asyncio label, and possibly type-crash (I'm not sure if deadlocks qualify for that)?

[Eclips4]

Thanks for the report!
I'm putting the "pending" label here until we get a reproducer.

[TheTechromancer]

Still working on reproducing this one. It's tricky because introspecting the offending variables results in a RecursionError. I made a small script to print the variables in GDB:

import sys

def get_stack_info():
    stack_info = []
    frame = sys._getframe(1)  # Start from the caller's frame
    while frame:
        filename = frame.f_code.co_filename
        lineno = frame.f_lineno
        function = frame.f_code.co_name
        locals_dict = dict(frame.f_locals)  # Create a copy of the locals dict
        stack_info.append((filename, lineno, function, locals_dict))
        frame = frame.f_back
    return stack_info

output_file = '/tmp/debug_output.txt'

with open(output_file, 'w') as f:
    f.write('Call stack with local variables:\n')
    for filename, lineno, function, locals_dict in reversed(get_stack_info()):
        f.write(f'\n{filename}:{lineno} in {function}\n')
        for key, value in list(locals_dict.items()):
            try:
                f.write(f'  {key} = {str(value)[:200]}\n')
            except Exception as e:
                f.write(f'  {key} = ERROR on type:{type(value)}: {e}\n')

print(f'Debug information written to {output_file}')

This outputs the full stack trace, including function arguments and their values:
debug_output.txt

From the snippet below, this is the offending chain of objects:

• _asyncio.Task
• _asyncio.Future
• collections.deque
• zmq._future._FutureEvent
• _asyncio.Future

This makes it seem like there is a circular reference to _asyncio.Future. _asyncio.Future somewhere contains a reference to zmq._future._FutureEvent, and zmq._future._FutureEvent somewhere contains a reference to _asyncio.Future:

/usr/local/lib/python3.9/asyncio/base_events.py:78 in _format_handle
  handle = <Handle <TaskStepMethWrapper object at 0x7ba09ae6e220>() created at /usr/local/lib/python3.9/asyncio/base_events.py:438>
  cb = <TaskStepMethWrapper object at 0x7ba09ae6e220>

/usr/local/lib/python3.9/asyncio/base_tasks.py:21 in _task_repr_info
  task = ERROR on type:<class '_asyncio.Task'>: maximum recursion depth exceeded
  info = ['pending', "name='Task-6454'", 'coro=<EngineServer.worker() running at /d_bbot/bbot/core/engine.py:451>', 'cb=[_chain_future.<locals>._call_set_state() at /usr/local/lib/python3.9/asyncio/futures.py:
  coro = EngineServer.worker() running at /d_bbot/bbot/core/engine.py:451

/usr/local/lib/python3.9/asyncio/base_futures.py:76 in _future_repr_info
  future = ERROR on type:<class '_asyncio.Future'>: maximum recursion depth exceeded while calling a Python object
  info = ['pending']

/usr/local/lib/python3.9/asyncio/base_futures.py:37 in _format_callbacks
  cb = ERROR on type:<class 'list'>: maximum recursion depth exceeded
  size = 2
  format_cb = <function _format_callbacks.<locals>.format_cb at 0x7ba08f4774c0>

/usr/local/lib/python3.9/asyncio/base_futures.py:32 in format_cb
  callback = ERROR on type:<class 'functools.partial'>: maximum recursion depth exceeded while calling a Python object

/usr/local/lib/python3.9/asyncio/format_helpers.py:23 in _format_callback_source
  func = ERROR on type:<class 'functools.partial'>: maximum recursion depth exceeded while calling a Python object
  args = ()

/usr/local/lib/python3.9/asyncio/format_helpers.py:47 in _format_callback
  func = ERROR on type:<class 'functools.partial'>: maximum recursion depth exceeded while calling a Python object
  args = ()
  kwargs = None
  suffix = ()

/usr/local/lib/python3.9/asyncio/format_helpers.py:56 in _format_callback
  func = <function _AsyncSocket._remove_finished_future at 0x7ba0b36a7d30>
  args = ()
  kwargs = ERROR on type:<class 'dict'>: maximum recursion depth exceeded while calling a Python object
  suffix = ()
  func_repr = _AsyncSocket._remove_finished_future

/usr/local/lib/python3.9/asyncio/format_helpers.py:40 in _format_args_and_kwargs
  args = ()
  kwargs = ERROR on type:<class 'dict'>: maximum recursion depth exceeded while calling a Python object
  items = []

/usr/local/lib/python3.9/asyncio/format_helpers.py:40 in <genexpr>
  .0 = <dict_itemiterator object at 0x7ba083e7e6d0>
  k = event_list
  v = ERROR on type:<class 'collections.deque'>: maximum recursion depth exceeded while calling a Python object

/usr/local/lib/python3.9/reprlib.py:52 in repr
  self = <reprlib.Repr object at 0x7ba0bc85ec10>
  x = ERROR on type:<class 'collections.deque'>: maximum recursion depth exceeded while calling a Python object

/usr/local/lib/python3.9/reprlib.py:60 in repr1
  self = <reprlib.Repr object at 0x7ba0bc85ec10>
  x = ERROR on type:<class 'collections.deque'>: maximum recursion depth exceeded while calling a Python object
  level = 6
  typename = deque

/usr/local/lib/python3.9/reprlib.py:103 in repr_deque
  self = <reprlib.Repr object at 0x7ba0bc85ec10>
  x = ERROR on type:<class 'collections.deque'>: maximum recursion depth exceeded while calling a Python object
  level = 6

/usr/local/lib/python3.9/reprlib.py:71 in _repr_iterable
  self = <reprlib.Repr object at 0x7ba0bc85ec10>
  x = ERROR on type:<class 'collections.deque'>: maximum recursion depth exceeded while calling a Python object
  level = 6
  left = deque([
  right = ])
  maxiter = 6
  trail = 
  n = 1
  newlevel = 5
  repr1 = <bound method Repr.repr1 of <reprlib.Repr object at 0x7ba0bc85ec10>>

/usr/local/lib/python3.9/reprlib.py:71 in <listcomp>
  .0 = <itertools.islice object at 0x7ba083e7e220>
  elem = ERROR on type:<class 'zmq._future._FutureEvent'>: maximum recursion depth exceeded
  newlevel = 5
  repr1 = <bound method Repr.repr1 of <reprlib.Repr object at 0x7ba0bc85ec10>>

/usr/local/lib/python3.9/reprlib.py:62 in repr1
  self = <reprlib.Repr object at 0x7ba0bc85ec10>
  x = ERROR on type:<class 'zmq._future._FutureEvent'>: maximum recursion depth exceeded
  level = 5
  typename = _FutureEvent

/usr/local/lib/python3.9/reprlib.py:139 in repr_instance
  self = <reprlib.Repr object at 0x7ba0bc85ec10>
  x = ERROR on type:<class 'zmq._future._FutureEvent'>: maximum recursion depth exceeded
  level = 5

/usr/local/lib/python3.9/collections/__init__.py:458 in __repr__
  self = ERROR on type:<class 'zmq._future._FutureEvent'>: maximum recursion depth exceeded
  repr_fmt = (future=%r, kind=%r, kwargs=%r, msg=%r, timer=%r)

/usr/local/lib/python3.9/asyncio/base_futures.py:76 in _future_repr_info
  future = ERROR on type:<class '_asyncio.Future'>: maximum recursion depth exceeded while calling a Python object
  info = ['pending']

[ZeroIntensity]

It's hard to find the problem without a reproducer, but zmq does indeed keep a reference to the future: see here.

[TheTechromancer]

Here is the reproducer:

import asyncio
import time
import functools

async def slow_callback():
    await asyncio.sleep(.1)
    time.sleep(.2)  # Blocking sleep to trigger the warning
    await asyncio.sleep(.1)

async def main():
    task = asyncio.create_task(slow_callback())
    task.add_done_callback(
        functools.partial(print, [task, task])
    )
    await task

if __name__ == "__main__":
    asyncio.run(main(), debug=True)

This hangs on 3.9 and 3.10, but 3.11 and 3.12 seem unaffected. It appears the freezes we're encountering on those later versions is a different bug. (yay for me 🫠)