Issue41594
This issue tracker has been migrated to GitHub,
and is currently read-only.
For more information,
see the GitHub FAQs in the Python's Developer Guide.
Created on 2020-08-20 00:24 by kyleam, last changed 2022-04-11 14:59 by admin.
Files | ||||
---|---|---|---|---|
File name | Uploaded | Description | Edit | |
reproducer.py | kyleam, 2020-08-20 00:24 | script to trigger issue |
Messages (3) | |||
---|---|---|---|
msg375680 - (view) | Author: Kyle Meyer (kyleam) * | Date: 2020-08-20 00:24 | |
I've been debugging an intermittent test failure in code that calls `loop.subprocess_exec` with an `asyncio.SubprocessProtocol` subclass. Here's a minimal example that I hope captures the issue. It's based closely off of the `DateProtocol` [example][1] in the asyncio protocol documentation. import asyncio class Protocol(asyncio.SubprocessProtocol): def __init__(self, exit_future): self.exit_future = exit_future self.output = bytearray() def pipe_data_received(self, fd, data): self.output.extend(data) def process_exited(self): self.exit_future.set_result(True) async def get_stdout(): loop = asyncio.get_running_loop() exit_future = asyncio.Future(loop=loop) transport, protocol = await loop.subprocess_exec( lambda: Protocol(exit_future), "printf", "ok", stdin=None, stderr=None) await exit_future transport.close() return bytes(protocol.output) The attached script adds some debugging statements to what's above and then repeats the specified number of calls to `asyncio.run(get_stdout())`, aborting if `asyncio.run(get_stdout())` returns an empty byte string rather then the expected `b'ok'`. With Python 3.7.3 on a Debian system, I see occasional aborts. For example, after two runs of the script with no unexpectedly empty output, I saw $ python3 reproducer.py 500 Iteration: 32 of 500 Failed on iteration 32 logfile: /tmp/asyncio-debug-bqehu8f3.log $ tail /tmp/asyncio-debug-bqehu8f3.log DEBUG: process_exited() called DEBUG: Starting iteration 31 DEBUG: Using selector: EpollSelector DEBUG: pipe_data_received(): fd=1, data=b'ok' DEBUG: process_exited() called DEBUG: Starting iteration 32 DEBUG: Using selector: EpollSelector DEBUG: process_exited() called DEBUG: pipe_data_received(): fd=1, data=b'ok' DEBUG: Failed on iteration 32 Based on the debug statements, it looks like `pipe_data_received` does get called with the output for the run that comes up empty, but only after `process_exited` is called. On my first try with a python built from a recent commit (0be7c216e1), I triggered the failure: $ python -V Python 3.10.0a0 $ python reproducer.py 500 Iteration: 8 of 500 Failed on iteration 8 logfile: /tmp/asyncio-debug-m5fba4ga.log $ tail /tmp/asyncio-debug-m5fba4ga.log DEBUG: process_exited() called DEBUG: Starting iteration 7 DEBUG: Using selector: EpollSelector DEBUG: pipe_data_received(): fd=1, data=b'ok' DEBUG: process_exited() called DEBUG: Starting iteration 8 DEBUG: Using selector: EpollSelector DEBUG: process_exited() called DEBUG: pipe_data_received(): fd=1, data=b'ok' DEBUG: Failed on iteration 8 As I'm following the example from the documentation closely, I hope I'm not committing a silly error that leads to an expected race here. [1]: https://docs.python.org/3/library/asyncio-protocol.html#loop-subprocess-exec-and-subprocessprotocol |
|||
msg375890 - (view) | Author: Yaroslav Halchenko (Yaroslav.Halchenko) | Date: 2020-08-25 15:21 | |
Might (although unlikely) be related to https://bugs.python.org/issue40634 which is about BlockingIOError being raised (and ignored) if SelectorEventLoop is reused (not the case here) also in the case of short lived processes. |
|||
msg375985 - (view) | Author: Kyle Meyer (kyleam) * | Date: 2020-08-27 11:23 | |
I should have thought to provide the output of when debug=True is passed to asyncio.run(). Here it is, with the python on my Debian system: $ python3 -V Python 3.7.3 $ python3 reproducer.py Iteration: 1 of 100 Failed on iteration 1 logfile: /tmp/asyncio-debug-rqfsxyth.log $ cat /tmp/asyncio-debug-rqfsxyth.log DEBUG: Starting iteration 1 DEBUG: Using selector: EpollSelector DEBUG: execute program 'printf' stdout=<pipe> DEBUG: process 'printf' created: pid 20488 DEBUG: process 20488 exited with returncode 0 INFO: <_UnixSubprocessTransport pid=20488 running> exited with return code 0 DEBUG: Read pipe 8 connected: (<_UnixReadPipeTransport fd=8 polling>, <ReadSubprocessPipeProto fd=1 pipe=<_UnixReadPipeTransport fd=8 polling>>) DEBUG: process_exited() called INFO: execute program 'printf': <_UnixSubprocessTransport pid=20488 returncode=0 stdout=<_UnixReadPipeTransport fd=8 polling>> DEBUG: pipe_data_received(): fd=1, data=b'ok' DEBUG: Close <_UnixSelectorEventLoop running=False closed=False debug=True> DEBUG: Failed on iteration 1 And with a python built from a recent commit (8e19c8be8701): $ python -V Python 3.10.0a0 $ python reproducer.py Iteration: 1 of 100 Failed on iteration 1 logfile: /tmp/asyncio-debug-9eyhuas4.log $ cat /tmp/asyncio-debug-9eyhuas4.log DEBUG: Starting iteration 1 DEBUG: Using selector: EpollSelector DEBUG: execute program 'printf' stdout=<pipe> DEBUG: process 'printf' created: pid 20524 DEBUG: process 20524 exited with returncode 0 INFO: <_UnixSubprocessTransport pid=20524 running> exited with return code 0 DEBUG: Read pipe 8 connected: (<_UnixReadPipeTransport fd=8 polling>, <ReadSubprocessPipeProto fd=1 pipe=<_UnixReadPipeTransport fd=8 polling>>) DEBUG: process_exited() called INFO: execute program 'printf': <_UnixSubprocessTransport pid=20524 returncode=0 stdout=<_UnixReadPipeTransport fd=8 polling>> DEBUG: pipe_data_received(): fd=1, data=b'ok' DEBUG: Close <_UnixSelectorEventLoop running=False closed=False debug=True> DEBUG: Failed on iteration 1 --- It looks like I can work around the issue (i.e. I don't observe any lost output) by adding this line to the attached script: diff --git a/reproducer.py b/reproducer.py index 5e04c36..a462898 100644 --- a/reproducer.py +++ b/reproducer.py @@ -25,6 +25,7 @@ async def get_stdout(): transport, protocol = await loop.subprocess_exec( lambda: Protocol(exit_future), "printf", "ok", stdin=None, stderr=None) + await asyncio.ensure_future(transport._wait()) await exit_future transport.close() return bytes(protocol.output) |
History | |||
---|---|---|---|
Date | User | Action | Args |
2022-04-11 14:59:34 | admin | set | github: 85760 |
2020-08-27 11:23:44 | kyleam | set | messages:
+ msg375985 versions: + Python 3.10 |
2020-08-25 15:21:41 | Yaroslav.Halchenko | set | nosy:
+ Yaroslav.Halchenko messages: + msg375890 |
2020-08-20 00:24:11 | kyleam | create |