asyncio.create_subprocess_exec() only works with main event loop

[sth]

BPO	35621
Nosy	@stefanseefeld, @asvetlov, @sth, @1st1, @koobs, @pablogsal, @miss-islington, @tirkarthi, @adefossez, @aeros, @rojer
PRs	bpo-35621: Support running subprocesses in asyncio when loop is executed in non-main thread #13630 bpo-35621: Fix tests when SafeChildWatcher is expected instead of ThreadedChildWatcher #13754 Revert "bpo-35621: Support running subprocesses in asyncio when loop is executed in non-main thread (#13630)" #13793 bpo-35621: Support running subprocesses in asyncio when loop is executed in non-main thread  #14344 [3.8] bpo-35621: Support running subprocesses in asyncio when loop is executed in non-main thread (GH-14344) #14484
Files	koobs-freebsd-10-non-debug-3x-build-1170.txt

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2019-06-30.09:56:09.887>
created_at = <Date 2018-12-30.22:59:38.171>
labels = ['type-bug', '3.8', '3.9', 'expert-asyncio']
title = 'asyncio.create_subprocess_exec() only works with main event loop'
updated_at = <Date 2020-05-30.02:49:41.494>
user = 'https://github.com/sth'

bugs.python.org fields:

activity = <Date 2020-05-30.02:49:41.494>
actor = 'aeros'
assignee = 'none'
closed = True
closed_date = <Date 2019-06-30.09:56:09.887>
closer = 'asvetlov'
components = ['asyncio']
creation = <Date 2018-12-30.22:59:38.171>
creator = 'sth'
dependencies = []
files = ['48384']
hgrepos = []
issue_num = 35621
keywords = ['patch']
message_count = 17.0
messages = ['332771', '334298', '344270', '344284', '344305', '344307', '344313', '344314', '344321', '344322', '344331', '344500', '346924', '346925', '348122', '370297', '370355']
nosy_count = 12.0
nosy_names = ['stefan', 'asvetlov', 'sth', 'yselivanov', 'koobs', 'pablogsal', 'miss-islington', 'xtreak', 'adefossez', 'aeros', 'Tim Froehlich', 'rojer']
pr_nums = ['13630', '13754', '13793', '14344', '14484']
priority = 'normal'
resolution = 'fixed'
stage = 'resolved'
status = 'closed'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue35621'
versions = ['Python 3.8', 'Python 3.9']

[sth]

asyncio.create_subprocess_exec() accepts a loop parameter, but doesn't use it to watch the child process. Instead uses get_event_loop_policy().get_child_watcher(), which doesn't doesn't know about loop but tries to use the current default event loop.

This fails if there is no current event loop or if that loop isn't running:

import asyncio

async def action(loop):
    proc = await asyncio.create_subprocess_exec('echo', loop=loop)
    await proc.wait()

loop = asyncio.new_event_loop()
loop.run_until_complete(action(loop))
loop.close()

This crashes because the main event loop never was created:

Traceback (most recent call last):
  File "sample.py", line 8, in <module>
    loop.run_until_complete(action(loop))
  File "/home/sth/devel/cpython.vanilla/Lib/asyncio/base_events.py", line 589, in run_until_complete
    return future.result()
  File "sample.py", line 4, in action
    proc = await asyncio.create_subprocess_exec('echo', loop=loop)
  File "/home/sth/devel/cpython.vanilla/Lib/asyncio/subprocess.py", line 213, in create_subprocess_exec
    transport, protocol = await loop.subprocess_exec(
  File "/home/sth/devel/cpython.vanilla/Lib/asyncio/base_events.py", line 1542, in subprocess_exec
    transport = await self._make_subprocess_transport(
  File "/home/sth/devel/cpython.vanilla/Lib/asyncio/unix_events.py", line 193, in _make_subprocess_transport
    watcher.add_child_handler(transp.get_pid(),
  File "/home/sth/devel/cpython.vanilla/Lib/asyncio/unix_events.py", line 924, in add_child_handler
    raise RuntimeError(
RuntimeError: Cannot add child handler, the child watcher does not have a loop attached

If we do have a current event loop, for example by calling asyncio.get_event_loop() before creating out own loop, then we don't get an error, but the program hangs indefinitely since that loop isn't running.

Expected behavior would be that the loop given to create_subprocess_exec() is used to watch the child process.

[adefossez]

Also impacted.

A fix I found is to add `watcher.attach_loop(self)` just after `with events.get_child_watcher() as watcher:` in `_make_subprocess_transport` in `asyncio/unix_events.py`.

[asvetlov]

New changeset 13ed079 by Andrew Svetlov in branch 'master':
bpo-35621: Support running subprocesses in asyncio when loop is executed in non-main thread (bpo-13630)
13ed079

[koobs]

New buildbot failure on koobs-freebsd10 that appears related to (includes) this changeset

Full log attached

[tirkarthi]

Also seems to occur on Ubuntu : https://buildbot.python.org/all/#/builders/141/builds/1912/steps/5/logs/stdio

karthi@ubuntu-s-1vcpu-1gb-blr1-01:~/cpython$ ./python -m unittest test.test_asyncio.test_unix_events
...................Exception in thread Thread-1:
Traceback (most recent call last):
  File "/home/karthi/cpython/Lib/threading.py", line 923, in _bootstrap_inner
    self.run()
  File "/home/karthi/cpython/Lib/threading.py", line 865, in run
    self._target(*self._args, **self._kwargs)
  File "/home/karthi/cpython/Lib/test/test_asyncio/test_unix_events.py", line 1833, in f
    self.assertIsInstance(watcher, asyncio.SafeChildWatcher)
  File "/home/karthi/cpython/Lib/unittest/case.py", line 1330, in assertIsInstance
    self.fail(self._formatMessage(msg, standardMsg))
  File "/home/karthi/cpython/Lib/unittest/case.py", line 748, in fail
    raise self.failureException(msg)
AssertionError: <asyncio.unix_events.ThreadedChildWatcher object at 0x7f00b357d640> is not an instance of <class 'asyncio.unix_events.SafeChildWatcher'>
../home/karthi/cpython/Lib/asyncio/base_events.py:646: ResourceWarning: unclosed event loop <_UnixSelectorEventLoop running=False closed=False debug=False>
  _warn(f"unclosed event loop {self!r}", ResourceWarning, source=self)
ResourceWarning: Enable tracemalloc to get the object allocation traceback
...............................................................................................

---

Ran 116 tests in 1.391s

OK

[tirkarthi]

It seems the assertion has to use ThreadedChildWatcher instead of SafeChildWatcher as the default seems to be changed at [0] . If changing assertion fixes the test I am curious why it didn't fail in the primary CI.

[0] 13ed079#diff-8441007d39090aec5e09dbfcfa9973b7R1299

[pablogsal]

I cannot reproduce this issue locally :(

[pablogsal]

When I ran the tests, the watcher I get is a SafeChildWatcher

[asvetlov]

Thanks for the report!

The failure depends on tests order execution (maybe you use -jN flag?).
Before default child watcher was SafeChildWatcher, not it is ThreaderChildWather.
The watcher is a global variable (a property of global event loop policy).

The failed test doesn't make sense for default ThreadChildWatcher but still valuable for old default SafeChildWatcher.
I've changed the test to use SafeChildWatcher explicitly.

See #13754 for the fix