New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Intermittent asyncio.open_connection / futures.InvalidStateError #65646
Comments
Intermittently, when using asyncio.wait_for() with asyncio.open_connection() to cancel the open_connection() task after a timeout period, an asyncio.futures.InvalidStateError is raised. It seems to be a race condition, if the open_connection() call succeeds roughly at the same time as the timeout. In order to recreate this issue, I used a slightly-modified version of the example at https://docs.python.org/3.4/library/asyncio-stream.html?highlight=open_connection#example ==== example.py ==== import asyncio
import urllib.parse
import sys
@asyncio.coroutine
def print_http_headers(url, timeout):
url = urllib.parse.urlsplit(url)
try:
reader, writer = yield from asyncio.wait_for(asyncio.open_connection(url.hostname, 80), timeout)
except asyncio.TimeoutError:
print('Timed out with {}-second timeout'.format(timeout))
return
query = ('HEAD {url.path} HTTP/1.0\r\n'
'Host: {url.hostname}\r\n'
'\r\n').format(url=url)
writer.write(query.encode('latin-1'))
while True:
line = yield from reader.readline()
if not line:
break
line = line.decode('latin1').rstrip()
if line:
print('HTTP header> %s' % line)
print('Success with {}-second timeout'.format(timeout))
url = sys.argv[1]
loop = asyncio.get_event_loop()
for timeout in range(5, 0, -1):
task = asyncio.async(print_http_headers(url, timeout/100))
loop.run_until_complete(task)
loop.close() ==== Output of "./example.py http://www.yahoo.com/" after running multiple times ==== HTTP header> HTTP/1.0 301 Redirect
HTTP header> Date: Tue, 06 May 2014 18:07:43 GMT
HTTP header> Connection: close
HTTP header> Via: http/1.1 ir12.fp.ne1.yahoo.com (ApacheTrafficServer/4.0.2)
HTTP header> Server: ATS
HTTP header> Cache-Control: no-store
HTTP header> Content-Type: text/html; charset=utf-8
HTTP header> Content-Language: en
HTTP header> Location: https://www.yahoo.com/
HTTP header> Content-Length: 214
Success with 0.04-second timeout
Timed out with 0.03-second timeout
Timed out with 0.02-second timeout
Exception in callback <bound method Future.set_result of Future<CANCELLED>>(None,)
handle: Handle(<bound method Future.set_result of Future<CANCELLED>>, (None,))
Traceback (most recent call last):
File "/opt/python3/lib/python3.4/asyncio/events.py", line 39, in _run
self._callback(*self._args)
File "/opt/python3/lib/python3.4/asyncio/futures.py", line 298, in set_result
raise InvalidStateError('{}: {!r}'.format(self._state, self))
asyncio.futures.InvalidStateError: CANCELLED: Future<CANCELLED>
Timed out with 0.01-second timeout |
Another run raised a different exception, Timed out with 0.05-second timeout
HTTP header> HTTP/1.0 301 Redirect
HTTP header> Date: Tue, 06 May 2014 18:58:53 GMT
HTTP header> Connection: close
HTTP header> Via: http/1.1 ir38.fp.bf1.yahoo.com (ApacheTrafficServer/4.0.2)
HTTP header> Server: ATS
HTTP header> Cache-Control: no-store
HTTP header> Content-Type: text/html; charset=utf-8
HTTP header> Content-Language: en
HTTP header> Location: https://www.yahoo.com/
HTTP header> Content-Length: 214
Success with 0.04-second timeout
HTTP header> HTTP/1.0 301 Redirect
HTTP header> Date: Tue, 06 May 2014 18:58:53 GMT
HTTP header> Connection: close
HTTP header> Via: http/1.1 ir45.fp.bf1.yahoo.com (ApacheTrafficServer/4.0.2)
HTTP header> Server: ATS
HTTP header> Cache-Control: no-store
HTTP header> Content-Type: text/html; charset=utf-8
HTTP header> Content-Language: en
HTTP header> Location: https://www.yahoo.com/
HTTP header> Content-Length: 214
Success with 0.03-second timeout
Timed out with 0.02-second timeout
Timed out with 0.01-second timeout
exception calling callback for <Future at 0x7f24e43aa710 state=finished returned list>
Traceback (most recent call last):
File "/opt/python3/lib/python3.4/concurrent/futures/_base.py", line 297, in _invoke_callbacks
callback(self)
File "/opt/python3/lib/python3.4/asyncio/futures.py", line 370, in <lambda>
new_future._copy_state, fut))
File "/opt/python3/lib/python3.4/asyncio/base_events.py", line 285, in call_soon_threadsafe
self._write_to_self()
File "/opt/python3/lib/python3.4/asyncio/selector_events.py", line 91, in _write_to_self
self._csock.send(b'x')
AttributeError: 'NoneType' object has no attribute 'send' |
The second error is easy to explain and fix: it's a race condition between the OS thread used to call getaddrinfo() and the main thread. The method _write_to_self() in selector_events.py is hopelessly naive. It should probably become something like this: def _write_to_self(self):
csock = self._csock
if csock is not None:
try:
self._csock.send(b'x')
except OSError:
pass It is possible that the main thread closes csock at any time, and calling send() on a closed socket will raise OSError with errno=9 (EBADF). Fortunately this is because close() sets the fd to -1; so there is no worry about reuse of the fd. I will investigate the first traceback next. |
New changeset afe8c4bd3230 by Guido van Rossum in branch '3.4': New changeset c0538334f4df by Guido van Rossum in branch 'default': |
I'm a little closer to understanding the first (more common) traceback. I can repro it by running your demo program in a loop -- it may take a while but occasionally I do get the same InvalidStateError. This appears to be an example of the problem speculated about in message #5 of https://code.google.com/p/tulip/issues/detail?id=58. In order to find out which occurrence of call_later(future.set_result, None) is causing this, I replaced all of them (about half a dozen) with an equivalent lambda -- the lambda shows up in the traceback, unlike the location where call_soon() is called. In this particular example, it is the last line of _SelectorSocketTransport.__init__() in selector_events.py (line 446). I suspect there are other places where a similar problem can occur. I still have to think more about how to fix this (without changing set_result() to always ignore a cancelled Future -- such a change would mask certain errors that I find important to catch). |
I'm unable to reproduce the issue with Python 3.5 (development version). |
This issue contains two sub-issues:
@ryder: If you are able to reproduce the second issue (InvalidStateError), please use set the environment variable PYTHONASYNCIODEBUG=1 to see the traceback where the call to set_result() was scheduled. It requires the latest development version of Tulip, Python 3.4 or Python 3.5 to get the traceback. I close this issue because I prefer to discuss the InvalidStateError in the issue bpo-21886. Thanks for the report Ryder. Thanks for the fix for the race condition in _write_to_self() Guido. |
New changeset d7e4efd5e279 by Victor Stinner in branch '3.4': New changeset 50c995bdc00a by Victor Stinner in branch 'default': |
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:
bugs.python.org fields:
The text was updated successfully, but these errors were encountered: