Client.close() can hang. (asyncio only).

I've been doing some async requests with HTTPX for a while now without any issue.

Summary

However, I've stumbled upon today a case I cannot explain. While doing a request to Microsoft Graph OAuth2 access token endpoint, I correctly receive a response but HTTPX client seems to hang and never return. I didn't find any other API with the same behaviour.

Reproduction

import asyncio

import httpx


async def main():
    async with httpx.Client() as client:
        response = await client.post(
            "https://login.microsoftonline.com/common/oauth2/v2.0/token",
            # You can keep those parameters, the issue happens also for 4XX responses
            data={
                "grant_type": "authorization_code",
                "code": "code",
                "redirect_uri": "http://localhost:8000/redirect",
                "client_id": "CLIENT_ID",
                "client_secret": "CLIENT_SECRET",
            },
        )

        print(response.http_version)  # HTTP/1.1
        print(len(response.content))  # 485 (same as in Content-Length header)
        print(response.headers)
    # Never happens
    print("Done")
    return response


asyncio.run(main())

Response headers

Headers([('cache-control', 'no-cache, no-store'), ('pragma', 'no-cache'), ('content-type', 'application/json; charset=utf-8'), ('expires', '-1'), ('strict-transport-security', 'max-age=31536000; includeSubDomains'), ('x-content-type-options', 'nosniff'), ('x-ms-request-id', 'dd57f328-14dd-4a99-8ed4-c81566f10800'), ('x-ms-ests-server', '2.1.9707.19 - AMS2 ProdSlices'), ('p3p', 'CP="DSP CUR OTPi IND OTRi ONL FIN"'), ('set-cookie', 'fpc=AhPq7wxRjzlCr42-XJpjplo; expires=Sun, 12-Jan-2020 06:43:04 GMT; path=/; secure; HttpOnly; SameSite=None'), ('set-cookie', 'x-ms-gateway-slice=prod; path=/; SameSite=None; secure; HttpOnly'), ('set-cookie', 'stsservicecookie=ests; path=/; SameSite=None; secure; HttpOnly'), ('date', 'Fri, 13 Dec 2019 06:43:04 GMT'), ('content-length', '485')])

After waiting a while, a `ConnectionResetError` is raised. Here is the stacktrace

  File "/Users/fvoron/.local/share/virtualenvs/httpx-oauth-5xgbpDkq/src/httpx/httpx/client.py", line 884, in __aexit__
    await self.close()
  File "/Users/fvoron/.local/share/virtualenvs/httpx-oauth-5xgbpDkq/src/httpx/httpx/client.py", line 873, in close
    await self.dispatch.close()
  File "/Users/fvoron/.local/share/virtualenvs/httpx-oauth-5xgbpDkq/src/httpx/httpx/dispatch/connection_pool.py", line 212, in close
    await connection.close()
  File "/Users/fvoron/.local/share/virtualenvs/httpx-oauth-5xgbpDkq/src/httpx/httpx/dispatch/connection.py", line 171, in close
    await self.open_connection.close()
  File "/Users/fvoron/.local/share/virtualenvs/httpx-oauth-5xgbpDkq/src/httpx/httpx/dispatch/http11.py", line 72, in close
    await self.socket.close()
  File "/Users/fvoron/.local/share/virtualenvs/httpx-oauth-5xgbpDkq/src/httpx/httpx/concurrency/asyncio.py", line 167, in close
    await self.stream_writer.wait_closed()
  File "/Users/fvoron/.pyenv/versions/3.7.5/lib/python3.7/asyncio/streams.py", line 323, in wait_closed
    await self._protocol._closed
  File "/Users/fvoron/.pyenv/versions/3.7.5/lib/python3.7/asyncio/selector_events.py", line 804, in _read_ready__data_received
    data = self._sock.recv(self.max_size)
ConnectionResetError: [Errno 54] Connection reset by peer

Versions

Python 3.7
HTTPX 0.9.3

From the code sample and stack traces, the issue seems to be that we fail to close the socket with the same server - the ConnectionResetError traceback shows that very explicitly: stream.wait_closed() hangs.

To me this could seem like an asyncio bug (although very unlikely) - perhaps one way to start the investigation would be to connect to the endpoint via a raw asyncio stream (without HTTPX), then close it immediately and see if wait_closed() hangs as well?

@florimondmanca

Thank you for your feedback @florimondmanca :) I've tried what you suggest (although I have to admit my knowledge on the subject is quite limited):

import asyncio

async def main():
    reader, writer = await asyncio.open_connection("login.microsoftonline.com", port=443)
    print("Opened")
    writer.close()
    await writer.wait_closed()
    print("Closed")

asyncio.run(main())

The stream is closing properly in this case.

It seems fairly likely this might have been resolved by 0.9.4, just released.

Some things to test out here...

Does the issue replicate with 0.9.4?
Does the issue replicate when using Trio instead of asyncio?

@tomchristie

Thank you @tomchristie!

Yes, the issue does replicate with 0.9.4.
No, the issue doesn't replicate with Trio.

So, should we suspect a bug in asyncio? Clearly there must be something strange with the Microsoft server to trigger such an issue.

Okay, thanks, that's super helpful - what's the absolute simplest case you can reduce this to?

I'm assuming the you wouldn't see an issue if using client = httpx.Client(), since it appears that the point at which the issue occurs is the await client.close() that happens automatically on leaving the client context block.

Okay, thanks, that's super helpful - what's the absolute simplest case you can reduce this to?

This:

import asyncio
import httpx

async def main():
    async with httpx.Client() as client:
        response = await client.get("https://login.microsoftonline.com")

asyncio.run(main())

I'm assuming the you wouldn't see an issue if using client = httpx.Client(), since it appears that the point at which the issue occurs is the await client.close() that happens automatically on leaving the client context block.

You're right. In this case , the issue happens when i call await client.close():

import asyncio
import httpx

async def main():
    client = httpx.Client()
    response = await client.get("https://login.microsoftonline.com")
    # await client.close()

asyncio.run(main())

@frankie567

@frankie567 Can you share the debug output from running your sample program?

$ HTTPX_LOG_LEVEL=debug python example.py

Also, is this specific to 3.7, ie can you reproduce (if able to) on 3.6 or 3.8?

Also, is this specific to 3.7, ie can you reproduce (if able to) on 3.6 or 3.8?

I can reproduce this on 3.8 but not on 3.6

@florimondmanca

@florimondmanca Here is the debug output ; unfortunately, nothing really interesting 🙁

DEBUG [2019-12-14 13:08:37] httpx.client - HTTP Request: GET https://login.microsoftonline.com "HTTP/1.1 302 Found"
DEBUG [2019-12-14 13:08:37] httpx.client - HTTP Request: GET https://www.office.com/login "HTTP/1.1 302 Found"
DEBUG [2019-12-14 13:08:37] httpx.client - HTTP Request: GET https://login.microsoftonline.com/common/oauth2/authorize?client_id=4345a7b9-9a63-4910-a426-35363201d503&response_mode=form_post&response_type=code+id_token&scope=openid+profile&state=OpenIdConnect.AuthenticationProperties%3DUr15hZ2a7vKvlcS7jtdRSPJgJjpQYriifWkZM-ljQJNUF7QjpSPiIO0dhkcNmZQOOfge0-qii4VyBoALBAOaYg0_2yXsVfdnpVInUv33rQi0HJ6McyFAEodbnNkbBW1y&nonce=637119221172335056.NGRiNDZkNTYtZTI2Ni00MTBjLWFjMGEtNGQ3ZjY3ODg1MmE2M2RmMjQ2MTAtZTkzMS00ZDg4LWEyNWMtYTBlY2IyNzY0ZTFk&redirect_uri=https%3A%2F%2Fwww.office.com%2F&ui_locales=en-US&mkt=en-US "HTTP/1.1 200 OK"
// And then the ConnectionResetError stacktrace

I've also tested on other Python versions and indeed, as @Shivelight stated, the problem does not occur on 3.6 but occurs on 3.8.

If of any use, I've created a test script with Tox to help debug on different versions: https://github.com/frankie567/httpx-issue-634

@frankie567

@frankie567 Ah sorry, meant to point you at the TRACE output, which gives a lot more details about what's going on in the internals: HTTPX_LOG_LEVEL=trace ...

@frankie567

Thanks a lot for the reproduction repo @frankie567, super helpful!

Here's what HTTPX_LOG_LEVEL=trace pytest -s outputs for me there. After reaching the last trace log line, the program hangs for a while then the ConnectionResetError traceback shows up. Nothing strange to me in there.

=================================================== test session starts ===================================================
platform darwin -- Python 3.8.0, pytest-5.3.2, py-1.8.0, pluggy-0.13.1
rootdir: /Users/florimond/Desktop/httpx-issue-634
plugins: asyncio-0.10.0, trio-0.5.2
collected 2 items                                                                                                         

test_issue_634.py TRACE [2019-12-14 14:56:43] httpx.dispatch.connection_pool - acquire_connection origin=Origin(scheme='https' host='login.microsoftonline.com' port=443)
TRACE [2019-12-14 14:56:43] httpx.dispatch.connection_pool - new_connection connection=HTTPConnection(origin=Origin(scheme='https' host='login.microsoftonline.com' port=443))
TRACE [2019-12-14 14:56:43] httpx.config - load_ssl_context verify=True cert=None trust_env=True http2=False
TRACE [2019-12-14 14:56:43] httpx.config - load_verify_locations cafile=/Users/florimond/.pyenv/versions/3.8.0/lib/python3.8/site-packages/certifi/cacert.pem
TRACE [2019-12-14 14:56:43] httpx.dispatch.connection - start_connect tcp host='login.microsoftonline.com' port=443 timeout=Timeout(timeout=5.0)
TRACE [2019-12-14 14:56:43] httpx.dispatch.connection - connected http_version='HTTP/1.1'
TRACE [2019-12-14 14:56:43] httpx.dispatch.http11 - send_headers method='GET' target='/' headers=Headers({'host': 'login.microsoftonline.com', 'user-agent': 'python-httpx/0.9.4', 'accept': '*/*', 'accept-encoding': 'gzip, deflate', 'connection': 'keep-alive'})
TRACE [2019-12-14 14:56:43] httpx.dispatch.http11 - receive_event event=NEED_DATA
TRACE [2019-12-14 14:56:43] httpx.dispatch.http11 - receive_event event=Response(status_code=302, headers=[(b'cache-control', b'no-cache, no-store'), (b'pragma', b'no-cache'), (b'content-type', b'text/html; charset=utf-8'), (b'content-encoding', b'gzip'), (b'expires', b'-1'), (b'location', b'https://www.office.com/login'), (b'vary', b'Accept-Encoding'), (b'strict-transport-security', b'max-age=31536000; includeSubDomains'), (b'x-content-type-options', b'nosniff'), (b'x-ms-request-id', b'a44d764f-09f0-4efd-b68e-5442ee2b3700'), (b'x-ms-ests-server', b'2.1.9707.19 - AMS2 ProdSlices'), (b'p3p', b'CP="DSP CUR OTPi IND OTRi ONL FIN"'), (b'set-cookie', b'fpc=AuVrkvxDhodPiZNhYbh_Hss; expires=Mon, 13-Jan-2020 13:56:43 GMT; path=/; secure; HttpOnly; SameSite=None'), (b'set-cookie', b'esctx=AQABAAAAAACQN9QBRU3jT6bcBQLZNUj7x9gFWLmezWn77DSx4w_OagIgqe6BsGFeYNyjJ8UmOUHgP4GYHhjqpLvFW-kuWo3pnXY6domlwXnpwvYC6JumrXcpyaIq_dE0RdgTtFaWVlr0z0lfSsGfcsnxsX4uB8KgsBR76wfh-jVixPtGetE8cx8T2bZ78gbCk2sm7fTbV_AgAA; domain=.login.microsoftonline.com; path=/; secure; HttpOnly; SameSite=None'), (b'set-cookie', b'x-ms-gateway-slice=prod; path=/; SameSite=None; secure; HttpOnly'), (b'set-cookie', b'stsservicecookie=ests; path=/; SameSite=None; secure; HttpOnly'), (b'date', b'Sat, 14 Dec 2019 13:56:43 GMT'), (b'content-length', b'132')], http_version=b'1.1', reason=b'Found')
DEBUG [2019-12-14 14:56:43] httpx.client - HTTP Request: GET https://login.microsoftonline.com "HTTP/1.1 302 Found"
TRACE [2019-12-14 14:56:43] httpx.dispatch.http11 - receive_event event=Data(<132 bytes>)
TRACE [2019-12-14 14:56:43] httpx.dispatch.http11 - receive_event event=EndOfMessage(headers=[])
TRACE [2019-12-14 14:56:43] httpx.dispatch.http11 - response_closed our_state=DONE their_state=DONE
TRACE [2019-12-14 14:56:43] httpx.dispatch.connection_pool - release_connection connection=HTTPConnection(origin=Origin(scheme='https' host='login.microsoftonline.com' port=443))
TRACE [2019-12-14 14:56:43] httpx.dispatch.connection_pool - acquire_connection origin=Origin(scheme='https' host='www.office.com' port=443)
TRACE [2019-12-14 14:56:43] httpx.dispatch.connection_pool - new_connection connection=HTTPConnection(origin=Origin(scheme='https' host='www.office.com' port=443))
TRACE [2019-12-14 14:56:43] httpx.config - load_ssl_context verify=True cert=None trust_env=True http2=False
TRACE [2019-12-14 14:56:43] httpx.config - load_verify_locations cafile=/Users/florimond/.pyenv/versions/3.8.0/lib/python3.8/site-packages/certifi/cacert.pem
TRACE [2019-12-14 14:56:43] httpx.dispatch.connection - start_connect tcp host='www.office.com' port=443 timeout=Timeout(timeout=5.0)
TRACE [2019-12-14 14:56:44] httpx.dispatch.connection - connected http_version='HTTP/1.1'
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - send_headers method='GET' target='/login' headers=Headers({'host': 'www.office.com', 'user-agent': 'python-httpx/0.9.4', 'accept': '*/*', 'accept-encoding': 'gzip, deflate', 'connection': 'keep-alive'})
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=NEED_DATA
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=Response(status_code=302, headers=[(b'content-type', b'text/html; charset=utf-8'), (b'location', b'https://login.microsoftonline.com/common/oauth2/authorize?client_id=4345a7b9-9a63-4910-a426-35363201d503&response_mode=form_post&response_type=code+id_token&scope=openid+profile&state=OpenIdConnect.AuthenticationProperties%3dOA6h_WUdlR7KHclJgoabO6I1EvFomAxPIy-apxBQEWmLujF3w7UjW3atLt6sKiOJvTcJx5H9LaqVpNYm3RuN12M0KxiN8ft1jhu5rGrAvBI_R7S6MHXqL7hMi78Em-Rk&nonce=637119286040410558.OWRjZjA0MjAtMmYyZC00YjcyLWFjMTMtMDg1ZGY3NTBlY2Y0OTM5MGU3ODQtNjE0NC00NGU5LWE2MDAtMjI5OGJjOWRlMTFl&redirect_uri=https%3a%2f%2fwww.office.com%2f&ui_locales=en-US&mkt=en-US'), (b'set-cookie', b'OH.DCAffinity=OH-suk; path=/; secure; HttpOnly'), (b'set-cookie', b'OpenIdConnect.nonce.JFkijwvenD220XD3VLS4fCVRtP%2BsEQFk5iynd01YQeo%3D=dmdpaFZSd1g4VU8zUkw1WGVZRmZ3eERZMEJnRl9ZNUQtX09nU19pTmU4VzZHMFYtMS1BclI5YzdjWlphN2x4Mlo0RldycU9wdjVTNUpsa2IzUkpOLWd2R2tFMnVrTXExZ09DdjNCdmYxN09qbklZdGJlR0dKbkQ2MmFKM1hjS2hLUEZuNHE5aUJuejdVSm5GSldkM3FqMnBNUDYwVENDV2lDcmM5VzFSRlEzQ0VGMnNIQjF1c21yLTBYbjdsZF9tNVM4ZldSZUZqbWk2UlE4Y1Z3Q0VKWFlxSk9GM3dKdV91NmtWLWpwQW1BUWppdkxfQ1FZcWZZWmRqOW9SUDJlaw%3D%3D; path=/; secure; HttpOnly'), (b'set-cookie', b'OH.SID=0f38058b-5f9d-4ab4-ac4e-cd2adc56b4c2; path=/; secure; HttpOnly'), (b'set-cookie', b'OH.DCAffinity=OH-suk; path=/; secure; HttpOnly'), (b'set-cookie', b'OpenIdConnect.nonce.JFkijwvenD220XD3VLS4fCVRtP%2BsEQFk5iynd01YQeo%3D=dmdpaFZSd1g4VU8zUkw1WGVZRmZ3eERZMEJnRl9ZNUQtX09nU19pTmU4VzZHMFYtMS1BclI5YzdjWlphN2x4Mlo0RldycU9wdjVTNUpsa2IzUkpOLWd2R2tFMnVrTXExZ09DdjNCdmYxN09qbklZdGJlR0dKbkQ2MmFKM1hjS2hLUEZuNHE5aUJuejdVSm5GSldkM3FqMnBNUDYwVENDV2lDcmM5VzFSRlEzQ0VGMnNIQjF1c21yLTBYbjdsZF9tNVM4ZldSZUZqbWk2UlE4Y1Z3Q0VKWFlxSk9GM3dKdV91NmtWLWpwQW1BUWppdkxfQ1FZcWZZWmRqOW9SUDJlaw%3D%3D; path=/; secure; HttpOnly'), (b'strict-transport-security', b'max-age=31536000; includeSubDomains'), (b'x-frame-options', b'SAMEORIGIN'), (b'x-ua-compatible', b'IE=edge,chrome=1'), (b'x-content-type-options', b'nosniff'), (b'x-xss-protection', b'1; mode=block'), (b'referrer-policy', b'strict-origin-when-cross-origin'), (b'x-msedge-ref', b'Ref A: C9899F3742DC4DE48571771FC98457ED Ref B: LON21EDGE1016 Ref C: 2019-12-14T13:56:44Z'), (b'set-cookie', b'MUID=2E09B7BDDC1B616D3169B98FDD106051; path=/; secure; expires=Thu, 07-Jan-2021 13:56:44 GMT; domain=office.com'), (b'date', b'Sat, 14 Dec 2019 13:56:43 GMT'), (b'content-length', b'0')], http_version=b'1.1', reason=b'Found')
DEBUG [2019-12-14 14:56:44] httpx.client - HTTP Request: GET https://www.office.com/login "HTTP/1.1 302 Found"
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=EndOfMessage(headers=[])
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - response_closed our_state=DONE their_state=DONE
TRACE [2019-12-14 14:56:44] httpx.dispatch.connection_pool - release_connection connection=HTTPConnection(origin=Origin(scheme='https' host='www.office.com' port=443))
TRACE [2019-12-14 14:56:44] httpx.dispatch.connection_pool - acquire_connection origin=Origin(scheme='https' host='login.microsoftonline.com' port=443)
TRACE [2019-12-14 14:56:44] httpx.dispatch.connection_pool - reuse_connection connection=HTTPConnection(origin=Origin(scheme='https' host='login.microsoftonline.com' port=443))
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - send_headers method='GET' target='/common/oauth2/authorize?client_id=4345a7b9-9a63-4910-a426-35363201d503&response_mode=form_post&response_type=code+id_token&scope=openid+profile&state=OpenIdConnect.AuthenticationProperties%3DOA6h_WUdlR7KHclJgoabO6I1EvFomAxPIy-apxBQEWmLujF3w7UjW3atLt6sKiOJvTcJx5H9LaqVpNYm3RuN12M0KxiN8ft1jhu5rGrAvBI_R7S6MHXqL7hMi78Em-Rk&nonce=637119286040410558.OWRjZjA0MjAtMmYyZC00YjcyLWFjMTMtMDg1ZGY3NTBlY2Y0OTM5MGU3ODQtNjE0NC00NGU5LWE2MDAtMjI5OGJjOWRlMTFl&redirect_uri=https%3A%2F%2Fwww.office.com%2F&ui_locales=en-US&mkt=en-US' headers=Headers({'host': 'login.microsoftonline.com', 'user-agent': 'python-httpx/0.9.4', 'accept': '*/*', 'accept-encoding': 'gzip, deflate', 'connection': 'keep-alive', 'cookie': 'esctx=AQABAAAAAACQN9QBRU3jT6bcBQLZNUj7x9gFWLmezWn77DSx4w_OagIgqe6BsGFeYNyjJ8UmOUHgP4GYHhjqpLvFW-kuWo3pnXY6domlwXnpwvYC6JumrXcpyaIq_dE0RdgTtFaWVlr0z0lfSsGfcsnxsX4uB8KgsBR76wfh-jVixPtGetE8cx8T2bZ78gbCk2sm7fTbV_AgAA; fpc=AuVrkvxDhodPiZNhYbh_Hss; stsservicecookie=ests; x-ms-gateway-slice=prod'})
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=NEED_DATA
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=Response(status_code=200, headers=[(b'cache-control', b'no-cache, no-store'), (b'pragma', b'no-cache'), (b'content-type', b'text/html; charset=utf-8'), (b'content-encoding', b'gzip'), (b'expires', b'-1'), (b'vary', b'Accept-Encoding'), (b'strict-transport-security', b'max-age=31536000; includeSubDomains'), (b'x-content-type-options', b'nosniff'), (b'x-frame-options', b'DENY'), (b'link', b'<https://aadcdn.msauth.net>; rel=preconnect; crossorigin'), (b'link', b'<https://aadcdn.msauth.net>; rel=dns-prefetch'), (b'link', b'<https://aadcdn.msftauth.net>; rel=dns-prefetch'), (b'x-dns-prefetch-control', b'on'), (b'x-ms-request-id', b'9f17abde-144f-4254-8ccd-b1c0d6e43300'), (b'x-ms-ests-server', b'2.1.9707.19 - AMS2 ProdSlices'), (b'p3p', b'CP="DSP CUR OTPi IND OTRi ONL FIN"'), (b'set-cookie', b'buid=AQABAAEAAACQN9QBRU3jT6bcBQLZNUj75it6P3ynAsfQsGU6T4nGCH8tp9BbRVb_Vq8Ghg9Y_gAT77Q7GbZJ8xv1G_-h-UBs3NwoH_Pctt-XxEo6-6jluFMp-G3SZiuHulLGBNpL638gAA; expires=Mon, 13-Jan-2020 13:56:44 GMT; path=/; secure; HttpOnly; SameSite=None'), (b'set-cookie', b'fpc=AuVrkvxDhodPiZNhYbh_Hst9Hyj2AQAAABvhhtUOAAAA; expires=Mon, 13-Jan-2020 13:56:44 GMT; path=/; secure; HttpOnly; SameSite=None'), (b'set-cookie', b'x-ms-gateway-slice=prod; path=/; SameSite=None; secure; HttpOnly'), (b'set-cookie', b'stsservicecookie=ests; path=/; secure; HttpOnly'), (b'date', b'Sat, 14 Dec 2019 13:56:43 GMT'), (b'content-length', b'45049')], http_version=b'1.1', reason=b'OK')
DEBUG [2019-12-14 14:56:44] httpx.client - HTTP Request: GET https://login.microsoftonline.com/common/oauth2/authorize?client_id=4345a7b9-9a63-4910-a426-35363201d503&response_mode=form_post&response_type=code+id_token&scope=openid+profile&state=OpenIdConnect.AuthenticationProperties%3DOA6h_WUdlR7KHclJgoabO6I1EvFomAxPIy-apxBQEWmLujF3w7UjW3atLt6sKiOJvTcJx5H9LaqVpNYm3RuN12M0KxiN8ft1jhu5rGrAvBI_R7S6MHXqL7hMi78Em-Rk&nonce=637119286040410558.OWRjZjA0MjAtMmYyZC00YjcyLWFjMTMtMDg1ZGY3NTBlY2Y0OTM5MGU3ODQtNjE0NC00NGU5LWE2MDAtMjI5OGJjOWRlMTFl&redirect_uri=https%3A%2F%2Fwww.office.com%2F&ui_locales=en-US&mkt=en-US "HTTP/1.1 200 OK"
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=Data(<2877 bytes>)
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=NEED_DATA
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=Data(<4096 bytes>)
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=NEED_DATA
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=Data(<4096 bytes>)
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=NEED_DATA
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=Data(<4096 bytes>)
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=NEED_DATA
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=Data(<4096 bytes>)
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=NEED_DATA
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=Data(<4096 bytes>)
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=NEED_DATA
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=Data(<4096 bytes>)
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=NEED_DATA
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=Data(<4096 bytes>)
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=NEED_DATA
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=Data(<4096 bytes>)
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=NEED_DATA
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=Data(<4096 bytes>)
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=NEED_DATA
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=Data(<4096 bytes>)
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=NEED_DATA
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=Data(<1212 bytes>)
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - receive_event event=EndOfMessage(headers=[])
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - response_closed our_state=DONE their_state=DONE
TRACE [2019-12-14 14:56:44] httpx.dispatch.connection_pool - release_connection connection=HTTPConnection(origin=Origin(scheme='https' host='login.microsoftonline.com' port=443))
TRACE [2019-12-14 14:56:44] httpx.dispatch.connection - close_connection
TRACE [2019-12-14 14:56:44] httpx.dispatch.http11 - send_event event=ConnectionClosed()

@frankie567

So, turns out that if we remove the .wait_closed() call added by #494, then the request doesn't hang anymore…

I pushed the change in #640. @frankie567 Can you verify this solves the issue on your side?

pip install "git+https://github.com/encode/httpx@asyncio-client-close"

@florimondmanca

@florimondmanca yes, I was debugging exactly that, it gets stuck on wait_closed() since inside the run_forever method doesn't break because in case we hit MS, as self._stopping never gets set to True.
In case of hitting other websites however, self._stopping gets set to True after about 3-4 iterations of loop inside def run_forever which internally calls _run
Also, would we be okay with removing wait_closed() since the docs suggest calling it?
https://docs.python.org/3/library/asyncio-stream.html#asyncio.StreamWriter.close

debug trace post for reference ->

-> await self.stream_writer.wait_closed()
(Pdb) ll
164  	    async def close(self) -> None:
165  	        self.stream_writer.close()
166  	        if sys.version_info >= (3, 7):
167  ->	            await self.stream_writer.wait_closed()


(Pdb) ll
517  	    def run_forever(self):
518  	        """Run until stop() is called."""
519  	        self._check_closed()
520  	        if self.is_running():
521  	            raise RuntimeError('This event loop is already running')
522  	        if events._get_running_loop() is not None:
523  	            raise RuntimeError(
524  	                'Cannot run the event loop while another loop is running')
525  	        self._set_coroutine_origin_tracking(self._debug)
526  	        self._thread_id = threading.get_ident()
527  	
528  	        old_agen_hooks = sys.get_asyncgen_hooks()
529  	        sys.set_asyncgen_hooks(firstiter=self._asyncgen_firstiter_hook,
530  	                               finalizer=self._asyncgen_finalizer_hook)
531  	        try:
532  	            events._set_running_loop(self)
533  	            while True:
534  ->	                self._run_once()
535  	                if self._stopping:
536  	                    break

@florimondmanca

@florimondmanca Yes, it solves the issue 😃

I would be curious though to understand what's so particular in the MS endpoint that prevents the stream to close properly 🤔

Closed via #640.

Even so, it would be really useful if anyone's able to dig into this further.

(Perhaps try simplifying things right down, eg. just open the connection using asyncio, then issue a close and wait_closed and determine if the issue still presents.)

@tomchristie

@tomchristie I'll try things and keep you updated ; I'm really curious about this issue.

So, I tried things but unfortunately I wasn't able to go much further in our understanding of the issue. I made a replication script using the asyncio.open_connection API: https://github.com/frankie567/httpx-issue-634/blob/master/debug.py

I found that the issue happens only with SSL. By reading the debug logs, it looks like MS never send an EOF after the client has initiated a shutdown. Hence, we get stuck at self._sock.recv(self.max_size).

Debug log with login.microsoftonline.com ❌

DEBUG:asyncio:Using selector: KqueueSelector
DEBUG:asyncio:Get address info login.microsoftonline.com:443, type=<SocketKind.SOCK_STREAM: 1>
DEBUG:asyncio:Getting address info login.microsoftonline.com:443, type=<SocketKind.SOCK_STREAM: 1> took 12.295ms: [(<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('40.126.9.66', 443)), (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('20.190.137.96', 443)), (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('20.190.137.98', 443)), (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('40.126.9.6', 443)), (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('40.126.9.8', 443))]
DEBUG:asyncio:poll took 11.673 ms: 1 events
DEBUG:asyncio:connect <socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('0.0.0.0', 0)> to ('40.126.9.66', 443)
DEBUG:asyncio:poll took 22.213 ms: 1 events
DEBUG:asyncio:<asyncio.sslproto.SSLProtocol object at 0x10485a6a0> starts SSL handshake
DEBUG:asyncio:poll 59999.590 ms took 26.570 ms: 1 events
DEBUG:asyncio:poll 59971.424 ms took 22.643 ms: 1 events
DEBUG:asyncio:<asyncio.sslproto.SSLProtocol object at 0x10485a6a0>: SSL handshake took 52.0 ms
DEBUG:asyncio:<socket.socket fd=9, family=AddressFamily.AF_INET, type=SocketKind.SOCK_STREAM, proto=6, laddr=('192.168.1.38', 54329), raddr=('40.126.9.66', 443)> connected to login.microsoftonline.com:443: (<asyncio.sslproto._SSLProtocolTransport object at 0x1047c6f98>, <asyncio.streams.StreamReaderProtocol object at 0x10485a668>)
DEBUG:httpx-issue-634:Connection to login.microsoftonline.com opened
DEBUG:httpx-issue-634:Close stream writer...
INFO:asyncio:poll took 123454.226 ms: 1 events
DEBUG:asyncio:<_SelectorSocketTransport fd=9 read=polling write=<idle, bufsize=0>>: Fatal read error on socket transport
Traceback (most recent call last):
  File "/Users/fvoron/.pyenv/versions/3.7.2/lib/python3.7/asyncio/selector_events.py", line 801, in _read_ready__data_received
    data = self._sock.recv(self.max_size)
ConnectionResetError: [Errno 54] Connection reset by peer
DEBUG:asyncio:Close <_UnixSelectorEventLoop running=False closed=False debug=True>
Traceback (most recent call last):
  File "debug.py", line 23, in <module>
    asyncio.run(main("login.microsoftonline.com"), debug=True)
  File "/Users/fvoron/.pyenv/versions/3.7.2/lib/python3.7/asyncio/runners.py", line 43, in run
    return loop.run_until_complete(main)
  File "/Users/fvoron/.pyenv/versions/3.7.2/lib/python3.7/asyncio/base_events.py", line 584, in run_until_complete
    return future.result()
  File "debug.py", line 20, in main
    await writer.wait_closed()
  File "/Users/fvoron/.pyenv/versions/3.7.2/lib/python3.7/asyncio/streams.py", line 323, in wait_closed
    await self._protocol._closed
  File "/Users/fvoron/.pyenv/versions/3.7.2/lib/python3.7/asyncio/selector_events.py", line 801, in _read_ready__data_received
    data = self._sock.recv(self.max_size)
ConnectionResetError: [Errno 54] Connection reset by peer

Debug log with www.google.fr ✅

DEBUG:asyncio:Using selector: KqueueSelector
DEBUG:asyncio:Get address info www.google.fr:443, type=<SocketKind.SOCK_STREAM: 1>
DEBUG:asyncio:Getting address info www.google.fr:443, type=<SocketKind.SOCK_STREAM: 1> took 6.560ms: [(<AddressFamily.AF_INET6: 30>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('2a00:1450:4007:80a::2003', 443, 0, 0)), (<AddressFamily.AF_INET: 2>, <SocketKind.SOCK_STREAM: 1>, 6, '', ('216.58.204.131', 443))]
DEBUG:asyncio:poll took 5.679 ms: 1 events
DEBUG:asyncio:connect <socket.socket fd=8, family=AddressFamily.AF_INET6, type=SocketKind.SOCK_STREAM, proto=6, laddr=('::', 0, 0, 0)> to ('2a00:1450:4007:80a::2003', 443, 0, 0)
DEBUG:asyncio:poll took 10.062 ms: 1 events
DEBUG:asyncio:<asyncio.sslproto.SSLProtocol object at 0x107ca8630> starts SSL handshake
DEBUG:asyncio:poll 59999.540 ms took 14.717 ms: 1 events
DEBUG:asyncio:poll 59982.631 ms took 9.567 ms: 1 events
DEBUG:asyncio:<asyncio.sslproto.SSLProtocol object at 0x107ca8630>: SSL handshake took 28.3 ms
DEBUG:asyncio:<socket.socket fd=8, family=AddressFamily.AF_INET6, type=SocketKind.SOCK_STREAM, proto=6, laddr=('2a01:e0a:7:f560:9452:ba32:bc63:f461', 54621, 0, 0), raddr=('2a00:1450:4007:80a::2003', 443, 0, 0)> connected to www.google.fr:443: (<asyncio.sslproto._SSLProtocolTransport object at 0x107c16f60>, <asyncio.streams.StreamReaderProtocol object at 0x107ca85f8>)
DEBUG:httpx-issue-634:Connection to www.google.fr opened
DEBUG:httpx-issue-634:Close stream writer...
DEBUG:asyncio:poll took 9.050 ms: 1 events
DEBUG:asyncio:<_SelectorSocketTransport fd=8 read=polling write=<idle, bufsize=0>> received EOF
DEBUG:asyncio:<asyncio.sslproto.SSLProtocol object at 0x107ca8630> received EOF
DEBUG:asyncio:Close <_UnixSelectorEventLoop running=False closed=False debug=True>

I've also made another attempt by using the low-level socket/ssl API (which is synchronous): https://github.com/frankie567/httpx-issue-634/blob/master/debug_ssl.py

Basically, it just opens the socket, unwrap and close. With login.microsoftonline.com, it gets stuck and raises ConnectionResetError:

Traceback (most recent call last):
  File "debug_ssl.py", line 9, in <module>
    ssock.unwrap()
  File "/Users/fvoron/.pyenv/versions/3.7.2/lib/python3.7/ssl.py", line 1094, in unwrap
    s = self._sslobj.shutdown()
ConnectionResetError: [Errno 54] Connection reset by peer

Other servers either immediately return or raise OSError: [Errno 0] Error (?).

@frankie567

Thanks for going further in the investigation @frankie567!

Not sure if this was asked before — does this behavior replicate with Requests or urllib3? Surely a server not sending an EOF on connection close is an issue these libraries have encountered before, might be worth looking at whether/how they’re handling it.

Ok, so now things are becoming interesting 😅 I've dug a bit into urllib3 and found out that ultimately, the close method is handled by the standard library HTTPConnection.close method. In it, close method is called on the socket and we're done.

On the other hand, in the asyncio code, great efforts are made to first unwrap the socket.

And here is where the problem arises for MS server. Doing this with urllib3 reproduces the exact same problem:

import logging
import urllib3

logging.basicConfig(level=logging.DEBUG)
logging.getLogger('urllib3').setLevel(logging.DEBUG)

http = urllib3.PoolManager()

pool = http.connection_from_host('login.microsoftonline.com', port=443, scheme='https')
conn = pool._new_conn() # urllib3.connection.HTTPSConnection -> urllib3.connection.HTTPConnection -> http.client.HTTPConnection
conn.connect()
conn.sock.unwrap()

So... I don't know. My (bold) theory would be that asyncio devs wanted to do things right by doing the unwrap process ; which unexpectedly raise this kind of issues. But actually, it was never implemented like this in the http lib.

Okay, that's some good investigation, thanks.

My short on this would be that on asyncio we're now doing the right thing just calling .close() and not following up with wait_closed(), because it gives us more robust behaviour.

It's interesting that trio also does not present this issue. I've no idea about what differences they have wrt. scoket unwrapping. (I don't have a much experience with low level SSL implementation in any case.)

It's possible? that there's a "technically correct, but real-world problematic" bug that's worth filing against asyncio here, but I don't have enough background to take a call on that.

Following your comment, I had a look at trio. I should have done it way earlier: it seems that they encountered the very same problem, and even added a very long comment about it in the code: https://github.com/python-trio/trio/blob/master/trio/_ssl.py#L779-L829

They purposely have an ignore_want_read flag, so that they don't block on read after unwrapping.

Maybe it's worth to file a case at asyncio, telling how trio tackle this and see what they think about it?

To me this could seem like an asyncio bug (although very unlikely)

I think we can reassess that "very unlikely". 😃

Raised https://bugs.python.org/issue39758

Navigation Menu

Repository navigation

Client.close() can hang. (asyncio only). #634

Summary

Reproduction

Versions

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Client.close() can hang. (asyncio only). #634

Description

Summary

Reproduction

Versions

Activity

florimondmanca commented on Dec 13, 2019

frankie567 commented on Dec 13, 2019

lovelydinosaur commented on Dec 13, 2019

frankie567 commented on Dec 13, 2019

lovelydinosaur commented on Dec 13, 2019

lovelydinosaur commented on Dec 13, 2019

frankie567 commented on Dec 13, 2019

florimondmanca commented on Dec 14, 2019

Shivelight commented on Dec 14, 2019

frankie567 commented on Dec 14, 2019

frankie567 commented on Dec 14, 2019

florimondmanca commented on Dec 14, 2019

florimondmanca commented on Dec 14, 2019

florimondmanca commented on Dec 14, 2019

gdhameeja commented on Dec 14, 2019

frankie567 commented on Dec 15, 2019

lovelydinosaur commented on Dec 16, 2019

frankie567 commented on Dec 16, 2019

frankie567 commented on Dec 18, 2019

florimondmanca commented on Dec 18, 2019

frankie567 commented on Dec 19, 2019

lovelydinosaur commented on Dec 19, 2019

frankie567 commented on Dec 19, 2019

lovelydinosaur commented on Jan 15, 2020

lovelydinosaur commented on Feb 26, 2020

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions