Asyncio Race Condition Leading to Infinite Loop

[TheTechromancer]

This is a pyzmq bug

• This is a pyzmq-specific bug, not an issue of zmq socket behavior. Don't worry if you're not sure! We'll figure it out together.

What pyzmq version?

26.0.3

What libzmq version?

4.3.5

Python version (and how it was installed)

Python 3.9 via apt

OS

Debian

What happened?

Recently I've run into a bug in cpython that directly affects ZMQ. It triggers whenever asyncio debugging is enabled, and the ZMQ future blocks for more than .1 second:

https://github.com/python/cpython/blob/7c2921844f9fa713f93152bf3a569812cee347a0/Lib/asyncio/base_events.py#L2021-L2023

The bug is due to an unintended recursion that happens when repr() is called on an asyncio task. The recursion is caused by ZMQ's future storing references to other futures including itself, which creates a circular reference. However, because each new layer of recursion must iterate over multiple futures, a RecursionError is never reached, and instead it results in a deadlock where the CPU is stuck at 100%:

This is mainly a bug in cpython, and was fixed in 3.11. However, 3.10 and earlier are still vulnerable to this bug, and based on the feedback from the cpython issue, the fix will not be back ported to those older versions.

python/cpython#122296

I'm creating this issue so you're aware of it, and so anyone else googling for the issue can find it. This one was a beast to track down, since it only happens when PYTHONASYNCIODEBUG=1 and when the ZMQ future blocks for more than .1 second. Hopefully it's helpful to someone.

Full traceback:
python_traceback.txt

Code to reproduce bug

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)

Traceback, if applicable

No response

More info

No response

[minrk]

Thanks for the report! I'm not sure there's an easy fix, but if one turns up I'll give it a try. Hopefully this will help others find out what's going on, at least.

[StefanD986]

This is actually not only an issue with PYTHONASYNCIODEBUG=1, but also happens if the task is logged for any other reason. So the impact is a bit bigger.

Here is an more minimal example:

import asyncio

import zmq.asyncio


async def start_zmq_task():
    context: zmq.Context = zmq.asyncio.Context()
    pull_socket: zmq.Socket = context.socket(zmq.PULL)
    t = asyncio.create_task(pull_socket.recv())
    print(t)


def main():
    asyncio.run(start_zmq_task())


if __name__ == "__main__":
    main()