New submission from Kyle Meyer <k...@kyleam.com>:
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 ---------- components: asyncio files: reproducer.py messages: 375680 nosy: asvetlov, kyleam, yselivanov priority: normal severity: normal status: open title: Intermittent failures of loop.subprocess_exec() to capture output type: behavior versions: Python 3.7 Added file: https://bugs.python.org/file49406/reproducer.py _______________________________________ Python tracker <rep...@bugs.python.org> <https://bugs.python.org/issue41594> _______________________________________ _______________________________________________ Python-bugs-list mailing list Unsubscribe: https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com