[New-bugs-announce] [issue41594] Intermittent failures of loop.subprocess_exec() to capture output
Kyle Meyer
report at bugs.python.org
Wed Aug 19 20:24:11 EDT 2020
New submission from Kyle Meyer <kyle at 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 <report at bugs.python.org>
<https://bugs.python.org/issue41594>
_______________________________________
More information about the New-bugs-announce
mailing list