Stall when connector hits limit from several connections to same bad hostname

[yrro]

Long story short

When a session's connector has a connection limit, multiple requests for a URL with a bad hostname never complete.

Expected behaviour

Script should run to completion

Actual behaviour

The second connection neither completes nor throws an error, and the script hangs.

Steps to reproduce

import aiohttp
import asyncio
import sys
import traceback

@asyncio.coroutine                                                                                  
def stall(session):
    for c in asyncio.as_completed([session.get('http://badhost.example/') for i in range(2)]):
        print(c)
        try:
            resp = yield from c
        except:
            for line in traceback.format_exception_only(*sys.exc_info()[0:2]):
                print(line, end='', file=sys.stderr)
        else:
            yield from resp.release()

loop = asyncio.get_event_loop()
with aiohttp.ClientSession(connector=aiohttp.TCPConnector(limit=1)) as session:
    loop.run_until_complete(stall(session))
loop.close()

Your environment

python 3.4.2 on Debian jessie
aiohttp 0.21.4

[unixsurfer]

I don't think it is only bad hostname which leads to this situation. With the following code:

import asyncio
import logging
import aiohttp

LOG_FORMAT = ('%(asctime)s %(message)s')
logging.basicConfig(format=LOG_FORMAT)
log = logging.getLogger('root')  # pylint: disable=I0011,C0103
log.setLevel('DEBUG')


async def fetch(session, url):
    "single fetch"
    log.info('trying %s', url)
    try:
        with aiohttp.Timeout(5):
            async with session.get(url, compress=True) as response:
                if response.status == 200:
                    rs =  await response.text()
                    log.info('status 200  %s response size %s', url, len(rs))
                else:
                    log.error('received %s for %s', response.status, url)
    except aiohttp.errors.ClientError as exc:
        log.error(exc)
    except asyncio.TimeoutError as exc:
        log.error('fetching data timeout for %s', url)

async def fetch_all(session, urls, loop):
    """This a delegating routine."""
    futures = [loop.create_task(fetch(session, url)) for url in urls]
    for future in asyncio.as_completed(futures):
        result = await future
        if result is not None:
            pass


def main():
    """main code"""
    ssl_conn = aiohttp.TCPConnector(conn_timeout=2, limit=1, verify_ssl=False)
    sites = ['google.com', 'yahoo.com', 'facebook.com', 'cnn.com']
    urls = ['https://{}:443/'.format(site) for site in sites]

    loop = asyncio.get_event_loop()
    with aiohttp.ClientSession(loop=loop, connector=ssl_conn) as session:
        loop.run_until_complete(fetch_all(session, urls, loop))

# This is the standard boilerplate that calls the main() function.
if __name__ == '__main__':
    main()

I see that request to yahoo receives timeout exception (catched by try block) but in the tcpdump trace I see actual response from yahoo (it responses with 301).

2016-03-27 12:08:58,578 trying https://google.com:443/
2016-03-27 12:08:58,582 trying https://yahoo.com:443/
2016-03-27 12:08:58,583 trying https://facebook.com:443/
2016-03-27 12:08:58,584 trying https://cnn.com:443/
2016-03-27 12:08:58,771 received 400 for https://google.com:443/
2016-03-27 12:08:58,859 [Errno None] Cannot connect to host cnn.com:443 ssl:True [Can not connect to cnn.com:443 [None]]
2016-03-27 12:08:59,856 status 200  https://facebook.com:443/ response size 69800
2016-03-27 12:09:03,587 fetching data timeout for https://yahoo.com:443/

When I remove cnn from the url list and remove also 443 then I see:

2016-03-27 12:21:41,845 trying https://google.com/
2016-03-27 12:21:41,853 trying https://yahoo.com/
2016-03-27 12:21:41,856 trying https://facebook.com/
2016-03-27 12:21:42,032 received 400 for https://google.com/
2016-03-27 12:21:43,038 status 200  https://facebook.com/ response size 69651
2016-03-27 12:21:46,857 fetching data timeout for https://yahoo.com/

running curl -vv https://yahoo.com:443/ or curl -vv https://yahoo.com returns 301 to www.yahoo.com.

[unixsurfer]

I don't think #861 solved the problem. If I run the code I mentioned above I see the same behavior.
@yrro , can you confirm if #861 fixes your problem ?

[danielnelson]

@unixsurfer Try removing compress=True from the request since you are not sending a body.

[unixsurfer]

@danielnelson, compress=False did the trick:
python ./aiosyncissue835.py
2016-05-23 22:08:20,190 trying https://google.com:443/
2016-05-23 22:08:20,193 trying https://yahoo.com:443/
2016-05-23 22:08:20,194 trying https://facebook.com:443/
2016-05-23 22:08:20,194 trying https://cnn.com:443/
2016-05-23 22:08:20,403 status 200 https://google.com:443/ response size 11424
2016-05-23 22:08:20,441 [Errno None] Cannot connect to host cnn.com:443 ssl:True [Can not connect to cnn.com:443 [None]]
2016-05-23 22:08:21,162 status 200 https://facebook.com:443/ response size 57148
2016-05-23 22:08:21,466 status 200 https://yahoo.com:443/ response size 434217

with compress=True

python ./aiosyncissue835.py
2016-05-23 22:08:57,912 trying https://google.com:443/
2016-05-23 22:08:57,916 trying https://yahoo.com:443/
2016-05-23 22:08:57,917 trying https://facebook.com:443/
2016-05-23 22:08:57,917 trying https://cnn.com:443/
2016-05-23 22:08:58,062 received 400 for https://google.com:443/
2016-05-23 22:08:58,145 [Errno None] Cannot connect to host cnn.com:443 ssl:True [Can not connect to cnn.com:443 [None]]
2016-05-23 22:08:59,081 status 200 https://facebook.com:443/ response size 57182
2016-05-23 22:09:02,920 fetching data timeout for https://yahoo.com:443/

Do you have any explanation about this behavior ?

[danielnelson]

Setting compress=True adds the Content-Encoding and Transfer-Encoding headers, and yahoo is taking a long time to respond when these are set, when it does respond it seems to close the connection. The equivalent curl command would be curl -vv -L -H Content-Encoding:deflate -H Transfer-Encoding:chunked https://yahoo.com:443/.

[unixsurfer]

Without -H Transfer-Encoding:chunked curl returns instantly

[unixsurfer]

yahoo doesn't like chunked Transfer-Encoding
curl -vv -L -H Transfer-Encoding:chunked https://yahoo.com:443/ 2>&1|grep 'HTTP/1.1'

GET / HTTP/1.1
< HTTP/1.1 301 Redirect
GET / HTTP/1.1
< HTTP/1.1 502 Server Hangup

Do we know why aiohttp uses chunked Transfer-Encoding when compression is enabled? A far as I know when both these headers are set then web server has to compress all payload before it sends out the compressed response in chunks.

[fafhrd91]

reason for chunking exactly this, we can start compressing and send compressed chunks immediately, we do not need to compress whole blob.

[danielnelson]

I think this issue should be closed since the original report is addressed. If we want to turn off chunked transfer with compression that should be a separate issue.