asyncio.create_subprocess_shell().communicate() hangs

[tannewt]

I'm trying viztracer with an asyncio program that spawns many processes via asyncio.create_subprocess_shell(). It works when run with python but hangs at the first .communicate() call under viztracer.

Any tips on where to look when debugging this? Thanks!

[gaogaotiantian]

Can you provide a minimum reproducing example so I can take a look at it?

[tannewt]

Ok here you go. Looks like it has to do with subprocessing out to python as well. (Using an echo command doesn't have the same issue.) Viztracer version is 0.16.3. Python is 3.12.3 on Arch Linux.

In subpython.py:

print("hello viztracer")

In viztracer_asyncio_subprocess.py:

import asyncio

async def run_echo():
    process = await asyncio.create_subprocess_shell(
        "python subpython.py",
        stdout=asyncio.subprocess.PIPE,
        stderr=asyncio.subprocess.PIPE)
    stdout, stderr = await process.communicate()
    print(stdout)

asyncio.run(run_echo())

Run python viztracer_asyncio_subprocess.py and get:

b'hello viztracer\n'

Run viztracer viztracer_asyncio_subprocess.py and it hangs. ctrl-c gives:

Total Entries: 1145                                                             
Use the following command to open the report:
vizviewer /home/tannewt/repos/circuitpython/ports/raspberrypi/result.json
Traceback (most recent call last):
  File "/usr/lib/python3.12/asyncio/runners.py", line 118, in run
    return self._loop.run_until_complete(task)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/asyncio/base_events.py", line 687, in run_until_complete
    return future.result()
           ^^^^^^^^^^^^^^^
  File "/home/tannewt/repos/circuitpython/ports/raspberrypi/viztracer_asyncio_subprocess.py", line 8, in run_echo
    stdout, stderr = await process.communicate()
                     ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/asyncio/subprocess.py", line 201, in communicate
    stdin, stdout, stderr = await tasks.gather(stdin, stdout, stderr)
                            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/asyncio/subprocess.py", line 181, in _read_stream
    output = await stream.read()
             ^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/asyncio/streams.py", line 706, in read
    block = await self.read(self._limit)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/asyncio/streams.py", line 713, in read
    await self._wait_for_data('read')
  File "/usr/lib/python3.12/asyncio/streams.py", line 545, in _wait_for_data
    await self._waiter
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/tannewt/repos/venv/bin/viztracer", line 8, in <module>
    sys.exit(main())
             ^^^^^^
  File "/home/tannewt/repos/venv/lib/python3.12/site-packages/viztracer/main.py", line 671, in main
    success, err_msg = ui.run()
                       ^^^^^^^^
  File "/home/tannewt/repos/venv/lib/python3.12/site-packages/viztracer/main.py", line 317, in run
    return self.run_command()
           ^^^^^^^^^^^^^^^^^^
  File "/home/tannewt/repos/venv/lib/python3.12/site-packages/viztracer/main.py", line 449, in run_command
    return self.run_code(code, main_mod.__dict__)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/tannewt/repos/venv/lib/python3.12/site-packages/viztracer/main.py", line 361, in run_code
    exec(code, global_dict)
  File "/home/tannewt/repos/circuitpython/ports/raspberrypi/viztracer_asyncio_subprocess.py", line 11, in <module>
    asyncio.run(run_echo())
  File "/usr/lib/python3.12/asyncio/runners.py", line 194, in run
    return runner.run(main)
           ^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.12/asyncio/runners.py", line 123, in run
    raise KeyboardInterrupt()
KeyboardInterrupt
Exception ignored in: <function BaseSubprocessTransport.__del__ at 0x796022fe3ba0>
Traceback (most recent call last):
  File "/usr/lib/python3.12/asyncio/base_subprocess.py", line 126, in __del__
  File "/usr/lib/python3.12/asyncio/base_subprocess.py", line 104, in close
  File "/usr/lib/python3.12/asyncio/unix_events.py", line 568, in close
  File "/usr/lib/python3.12/asyncio/unix_events.py", line 592, in _close
  File "/usr/lib/python3.12/asyncio/base_events.py", line 795, in call_soon
  File "/usr/lib/python3.12/asyncio/base_events.py", line 541, in _check_closed
RuntimeError: Event loop is closed

[gaogaotiantian]

The root cause is my monkey patch to subprocess.Popen when shell=True. I fixed it in #434 and it will be out in the next release. In the mean time, if you need the feature immediately, feel free to install from the github source directly.

[tannewt]

Thank you so much!

[tannewt]

I installed from source and it works. Thanks again!

[gaogaotiantian]

No problem :)