ReadTimeout - SSL shutdown timed out

[Kludex]

Originally opened by @ScottSturdivant on 2020-05-30 08:49:00 in encode/httpx

Hi,

Just curious if someone might have some insight as to what might be happening here. I have some code that is subscribing to messages via an SSE server. The code is very similar to this:

import asyncio
import httpx

client = httpx.AsyncClient()

async def sse():
 async with client:
 async with client.stream('GET', 'https://server.blargh.home:5000/stream', timeout=None) as response:
 async for chunk in response.aiter_raw():
 yield chunk


async def subscribe():
 async for event in sse():
 print(repr(event))


asyncio.run(subscribe())

On one device in particular, about 40% of the time, I'm seeing that httpcore._exceptions.ReadTimeout is raised from the aiter_raw(). Here is the traceback:

 async for chunk in response.aiter_raw():
 async for chunk in self.aiterator:
 async for chunk in self.stream:
 async for part in self._raw_stream:
 File "/usr/local/packages/python3_7_acap/python3.7/lib/python3.7/site-packages/httpcore/_async/base.py", line 57, in __aiter__
 File "/usr/local/packages/python3_7_acap/python3.7/lib/python3.7/site-packages/httpcore/_async/connection_pool.py", line 49, in __aiter__
 File "/usr/local/packages/python3_7_acap/python3.7/lib/python3.7/site-packages/httpx/_models.py", line 1009, in aiter_raw
 File "/usr/local/packages/python3_7_acap/python3.7/lib/python3.7/site-packages/pygw/core/client.py", line 175, in sse
 ERROR: Other SSE failure.
 Traceback (most recent call last):
 data = await self.socket.read(self.READ_NUM_BYTES, timeout)
 event = await self._receive_event(timeout)
 raise to_exc(exc) from None
 self.stream_reader.read(n), timeout.get("read")
 File "/usr/local/packages/python3_7_acap/python3.7/lib/python3.7/site-packages/httpcore/_async/http11.py", line 128, in _receive_response_data
 File "/usr/local/packages/python3_7_acap/python3.7/lib/python3.7/site-packages/httpcore/_async/http11.py", line 145, in _receive_event
 File "/usr/local/packages/python3_7_acap/python3.7/lib/python3.7/site-packages/httpcore/_backends/asyncio.py", line 135, in read
 File "/usr/local/packages/python3_7_acap/python3.7/lib/python3.7/site-packages/httpcore/_exceptions.py", line 12, in map_exceptions
 File "<pyrun>/contextlib.py", line 130, in __exit__
 httpcore._exceptions.ReadTimeout: SSL shutdown timed out

The stream is pretty dead. Every ~ 5 minutes a heartbeat is sent but otherwise it is generally quiet. This problem is only happening on one device and it happens to be running PyRun as its interpreter. Perhaps that's making some difference.

As it is, I have a try/except around the async with client so the stream is able to be re-established and works. Just trying to figure out what might be generating this and if there's some system configuration that needs to be done, or...

Thank you for any help!

[Kludex]

Originally posted by @ScottSturdivant on 2020-05-30T17:06:43Z

Hi @yeraydiazdiaz,

Thanks a lot for taking the time to look at this! Re: 40%, what I mean is that it's not 100% reproducible. Majority (60%) of the time when I run the program, I never receive the ReadTimeout exception.

During the SSE event handling, I will use the same AsyncClient instance that I'm using for the SSE stream itself. Is that perhaps an issue?

Here are the logs. It may be a bit tricky to see, but I receive 2 events. (Look for Yielding event). The first one I do nothing with. The second one, I wind up first submitting a PUT request and then a POST request, using the same client obj. After that point, the ReadTimeout error is raised.

INFO: SSE: Listening for events.
INFO: Starting SSE subscription to stream/device/bc37948f-2e69-46c8-854a-e65601f9cd1b/
TRACE [2020-05-30 10:48:32] httpcore._async.connection_pool - get_connection_from_pool=(b'https', b'qa-debian8.example.com', 443)
TRACE: get_connection_from_pool=(b'https', b'qa-debian8.example.com', 443)
TRACE [2020-05-30 10:48:32] httpcore._async.connection_pool - created connection=<httpcore._async.connection.AsyncHTTPConnection object at 0x70e57fb0>
TRACE: created connection=<httpcore._async.connection.AsyncHTTPConnection object at 0x70e57fb0>
TRACE [2020-05-30 10:48:32] httpcore._async.connection - open_socket origin=(b'https', b'qa-debian8.example.com', 443) timeout={'connect': None, 'read': None, 'write': None, 'pool': None}
TRACE: open_socket origin=(b'https', b'qa-debian8.example.com', 443) timeout={'connect': None, 'read': None, 'write': None, 'pool': None}
TRACE [2020-05-30 10:48:32] httpcore._async.connection - create_connection socket=<httpcore._backends.asyncio.SocketStream object at 0x70e57150> http_version='HTTP/1.1'
TRACE: create_connection socket=<httpcore._backends.asyncio.SocketStream object at 0x70e57150> http_version='HTTP/1.1'
TRACE [2020-05-30 10:48:32] httpcore._async.connection - connection.request method=b'GET' url=(b'https', b'qa-debian8.example.com', 443, b'/v1.0/stream/device/bc37948f-2e69-46c8-854a-e65601f9cd1b/') headers=[(b'host', b'qa-debian8.example.com'), (b'user-agent', b
'python-httpx/0.13.3'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate'), (b'connection', b'keep-alive'), (b'x-request-id', b'068696ba-043c-4fdf-a059-6d41b8dc3392'), (b'authorization', b'Basic ZXlKaGJHY2lPaUpJVXpJMU5pSXNJbWxoZENJNk1UVTVNRGcxTnpNd09Td2laWGh3SWpveE5Ua3dPVFF6TnpBNUxqQjkuZXlKcFpDSTZJbUpqTXpjN
U5EaG1MVEpsTmprdE5EWmpPQzA0TlRSaExXVTJOVFl3TVdZNVkyUXhZaUo5Ljk3WDJza0FyeF9fNVdOc2lmblNzcjlZRmNDOHgwRDdYckpoR19kMWxRMDgsTWpBeU1DMHdOUzB6TUZReE5qbzBPRG96TWk0Mk9UQTNPREFyTURBNk1EQT06TUdRQ01FWlRva1RuK3lWT2ZHd3E5SlNKSEVTWG9Dc1JnUFcvenhqMDliL1d4TDI0RG5oLzRzZTJUMlBwRExEVzM4VFZvQUl3ZVQxcUxpNXVvVEtBdU9ubmVzT00wRjVqRFV4K3dMZX
REWUtJMXlZSUFkZzZsdmtpNXJVbVBPZHNxTzJwWWtJcA==')]
TRACE: connection.request method=b'GET' url=(b'https', b'qa-debian8.example.com', 443, b'/v1.0/stream/device/bc37948f-2e69-46c8-854a-e65601f9cd1b/') headers=[(b'host', b'qa-debian8.example.com'), (b'user-agent', b'python-httpx/0.13.3'), (b'accept', b'*/*'), (b
'accept-encoding', b'gzip, deflate'), (b'connection', b'keep-alive'), (b'x-request-id', b'068696ba-043c-4fdf-a059-6d41b8dc3392'), (b'authorization', b'Basic ZXlKaGJHY2lPaUpJVXpJMU5pSXNJbWxoZENJNk1UVTVNRGcxTnpNd09Td2laWGh3SWpveE5Ua3dPVFF6TnpBNUxqQjkuZXlKcFpDSTZJbUpqTXpjNU5EaG1MVEpsTmprdE5EWmpPQzA0TlRSaExXVTJOVFl3TVdZ
NVkyUXhZaUo5Ljk3WDJza0FyeF9fNVdOc2lmblNzcjlZRmNDOHgwRDdYckpoR19kMWxRMDgsTWpBeU1DMHdOUzB6TUZReE5qbzBPRG96TWk0Mk9UQTNPREFyTURBNk1EQT06TUdRQ01FWlRva1RuK3lWT2ZHd3E5SlNKSEVTWG9Dc1JnUFcvenhqMDliL1d4TDI0RG5oLzRzZTJUMlBwRExEVzM4VFZvQUl3ZVQxcUxpNXVvVEtBdU9ubmVzT00wRjVqRFV4K3dMZXREWUtJMXlZSUFkZzZsdmtpNXJVbVBPZHNxTzJwWWtJcA=='
)]
TRACE [2020-05-30 10:48:32] httpcore._async.http11 - send_request method=b'GET' url=(b'https', b'qa-debian8.example.com', 443, b'/v1.0/stream/device/bc37948f-2e69-46c8-854a-e65601f9cd1b/') headers=[(b'host', b'qa-debian8.example.com'), (b'user-agent', b'python-ht
tpx/0.13.3'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate'), (b'connection', b'keep-alive'), (b'x-request-id', b'068696ba-043c-4fdf-a059-6d41b8dc3392'), (b'authorization', b'Basic ZXlKaGJHY2lPaUpJVXpJMU5pSXNJbWxoZENJNk1UVTVNRGcxTnpNd09Td2laWGh3SWpveE5Ua3dPVFF6TnpBNUxqQjkuZXlKcFpDSTZJbUpqTXpjNU5EaG1MVEp
sTmprdE5EWmpPQzA0TlRSaExXVTJOVFl3TVdZNVkyUXhZaUo5Ljk3WDJza0FyeF9fNVdOc2lmblNzcjlZRmNDOHgwRDdYckpoR19kMWxRMDgsTWpBeU1DMHdOUzB6TUZReE5qbzBPRG96TWk0Mk9UQTNPREFyTURBNk1EQT06TUdRQ01FWlRva1RuK3lWT2ZHd3E5SlNKSEVTWG9Dc1JnUFcvenhqMDliL1d4TDI0RG5oLzRzZTJUMlBwRExEVzM4VFZvQUl3ZVQxcUxpNXVvVEtBdU9ubmVzT00wRjVqRFV4K3dMZXREWUtJMXlZ
SUFkZzZsdmtpNXJVbVBPZHNxTzJwWWtJcA==')]
TRACE: send_request method=b'GET' url=(b'https', b'qa-debian8.example.com', 443, b'/v1.0/stream/device/bc37948f-2e69-46c8-854a-e65601f9cd1b/') headers=[(b'host', b'qa-debian8.example.com'), (b'user-agent', b'python-httpx/0.13.3'), (b'accept', b'*/*'), (b'accep
t-encoding', b'gzip, deflate'), (b'connection', b'keep-alive'), (b'x-request-id', b'068696ba-043c-4fdf-a059-6d41b8dc3392'), (b'authorization', b'Basic ZXlKaGJHY2lPaUpJVXpJMU5pSXNJbWxoZENJNk1UVTVNRGcxTnpNd09Td2laWGh3SWpveE5Ua3dPVFF6TnpBNUxqQjkuZXlKcFpDSTZJbUpqTXpjNU5EaG1MVEpsTmprdE5EWmpPQzA0TlRSaExXVTJOVFl3TVdZNVkyUX
hZaUo5Ljk3WDJza0FyeF9fNVdOc2lmblNzcjlZRmNDOHgwRDdYckpoR19kMWxRMDgsTWpBeU1DMHdOUzB6TUZReE5qbzBPRG96TWk0Mk9UQTNPREFyTURBNk1EQT06TUdRQ01FWlRva1RuK3lWT2ZHd3E5SlNKSEVTWG9Dc1JnUFcvenhqMDliL1d4TDI0RG5oLzRzZTJUMlBwRExEVzM4VFZvQUl3ZVQxcUxpNXVvVEtBdU9ubmVzT00wRjVqRFV4K3dMZXREWUtJMXlZSUFkZzZsdmtpNXJVbVBPZHNxTzJwWWtJcA==')]
TRACE [2020-05-30 10:48:32] httpcore._async.http11 - send_data=Data(<0 bytes>)
TRACE: send_data=Data(<0 bytes>)
DEBUG [2020-05-30 10:48:38] httpx._client - HTTP Request: GET https://qa-debian8.example.com/v1.0/stream/device/bc37948f-2e69-46c8-854a-e65601f9cd1b/ "HTTP/1.1 200 OK"
DEBUG: HTTP Request: GET https://qa-debian8.example.com/v1.0/stream/device/bc37948f-2e69-46c8-854a-e65601f9cd1b/ "HTTP/1.1 200 OK"
TRACE [2020-05-30 10:48:38] httpcore._async.http11 - receive_event=Data(<4090 bytes>)
TRACE: receive_event=Data(<4090 bytes>)
TRACE [2020-05-30 10:48:38] httpcore._async.http11 - receive_event=Data(<1472 bytes>)
TRACE: receive_event=Data(<1472 bytes>)
INFO: SSE: making event obj
INFO: SSE: Yielding event.
INFO: blockchain_record event #17838, 5522 bytes
INFO: Handling new BCI record.
INFO: Record mismatch but ours is newer, discarding.
INFO: SSE: Record handled.
INFO: SSE: Resetting data.
TRACE [2020-05-30 10:48:48] httpcore._async.http11 - receive_event=Data(<4090 bytes>)
TRACE: receive_event=Data(<4090 bytes>)
TRACE [2020-05-30 10:48:48] httpcore._async.http11 - receive_event=Data(<1473 bytes>)
TRACE: receive_event=Data(<1473 bytes>)
INFO: SSE: making event obj
INFO: SSE: Yielding event.
INFO: blockchain_record event #17839, 5523 bytes
INFO: Handling new BCI record.
INFO: PUT with Auth: https://qa-debian8.example.com/v1.0/blockchain_record/
TRACE [2020-05-30 10:48:48] httpcore._async.connection_pool - get_connection_from_pool=(b'https', b'qa-debian8.example.com', 443)
TRACE: get_connection_from_pool=(b'https', b'qa-debian8.example.com', 443)
TRACE [2020-05-30 10:48:48] httpcore._async.connection_pool - created connection=<httpcore._async.connection.AsyncHTTPConnection object at 0x70e57df0>
TRACE: created connection=<httpcore._async.connection.AsyncHTTPConnection object at 0x70e57df0>
TRACE [2020-05-30 10:48:48] httpcore._async.connection - open_socket origin=(b'https', b'qa-debian8.example.com', 443) timeout={'connect': 5.0, 'read': 5.0, 'write': 5.0, 'pool': 5.0}
TRACE: open_socket origin=(b'https', b'qa-debian8.example.com', 443) timeout={'connect': 5.0, 'read': 5.0, 'write': 5.0, 'pool': 5.0}
TRACE [2020-05-30 10:48:48] httpcore._async.connection - create_connection socket=<httpcore._backends.asyncio.SocketStream object at 0x70e8a590> http_version='HTTP/1.1'
TRACE: create_connection socket=<httpcore._backends.asyncio.SocketStream object at 0x70e8a590> http_version='HTTP/1.1'
TRACE [2020-05-30 10:48:48] httpcore._async.connection - connection.request method=b'PUT' url=(b'https', b'qa-debian8.example.com', 443, b'/v1.0/blockchain_record/') headers=[(b'host', b'qa-debian8.example.com'), (b'user-agent', b'python-httpx/0.13.3'), (b'accept
', b'*/*'), (b'accept-encoding', b'gzip, deflate'), (b'connection', b'keep-alive'), (b'x-software-type', b'Embedded Gateway'), (b'content-length', b'5535'), (b'content-type', b'application/json'), (b'x-request-id', b'fd1fb01b-af2b-4e05-86cd-b12b8a14307d'), (b'authorization', b'Basic ZXlKaGJHY2lPaUpJVXpJMU5pS
XNJbWxoZENJNk1UVTVNRGcxTnpNd09Td2laWGh3SWpveE5Ua3dPVFF6TnpBNUxqQjkuZXlKcFpDSTZJbUpqTXpjNU5EaG1MVEpsTmprdE5EWmpPQzA0TlRSaExXVTJOVFl3TVdZNVkyUXhZaUo5Ljk3WDJza0FyeF9fNVdOc2lmblNzcjlZRmNDOHgwRDdYckpoR19kMWxRMDgsTWpBeU1DMHdOUzB6TUZReE5qbzBPRG8wT0M0eU5qTTNOeklyTURBNk1EQT06TUdVQ01CL3V5OGFTSkM1bkc2UHZrcEhnWHY2TkZRKzNHcUdSQj
FDWmtQS3pJMU1sS1dYcldYT2s1Ykh2eDJLTmlhUW8rd0l4QUxmRStrQStYSVNDOGpPd2JORnlMdkcwWmt5OFN4YnA3RUZUTCtSb0tUQXFxd25UL1I5Q3JKYUc5dWZaK1dZMm9nPT0=')]
TRACE: connection.request method=b'PUT' url=(b'https', b'qa-debian8.example.com', 443, b'/v1.0/blockchain_record/') headers=[(b'host', b'qa-debian8.example.com'), (b'user-agent', b'python-httpx/0.13.3'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflat
e'), (b'connection', b'keep-alive'), (b'x-software-type', b'Embedded Gateway'), (b'content-length', b'5535'), (b'content-type', b'application/json'), (b'x-request-id', b'fd1fb01b-af2b-4e05-86cd-b12b8a14307d'), (b'authorization', b'Basic ZXlKaGJHY2lPaUpJVXpJMU5pSXNJbWxoZENJNk1UVTVNRGcxTnpNd09Td2laWGh3SWpveE5U
a3dPVFF6TnpBNUxqQjkuZXlKcFpDSTZJbUpqTXpjNU5EaG1MVEpsTmprdE5EWmpPQzA0TlRSaExXVTJOVFl3TVdZNVkyUXhZaUo5Ljk3WDJza0FyeF9fNVdOc2lmblNzcjlZRmNDOHgwRDdYckpoR19kMWxRMDgsTWpBeU1DMHdOUzB6TUZReE5qbzBPRG8wT0M0eU5qTTNOeklyTURBNk1EQT06TUdVQ01CL3V5OGFTSkM1bkc2UHZrcEhnWHY2TkZRKzNHcUdSQjFDWmtQS3pJMU1sS1dYcldYT2s1Ykh2eDJLTmlhUW8rd0l4Q
UxmRStrQStYSVNDOGpPd2JORnlMdkcwWmt5OFN4YnA3RUZUTCtSb0tUQXFxd25UL1I5Q3JKYUc5dWZaK1dZMm9nPT0=')]
TRACE [2020-05-30 10:48:48] httpcore._async.http11 - send_request method=b'PUT' url=(b'https', b'qa-debian8.example.com', 443, b'/v1.0/blockchain_record/') headers=[(b'host', b'qa-debian8.example.com'), (b'user-agent', b'python-httpx/0.13.3'), (b'accept', b'*/*')
, (b'accept-encoding', b'gzip, deflate'), (b'connection', b'keep-alive'), (b'x-software-type', b'Embedded Gateway'), (b'content-length', b'5535'), (b'content-type', b'application/json'), (b'x-request-id', b'fd1fb01b-af2b-4e05-86cd-b12b8a14307d'), (b'authorization', b'Basic ZXlKaGJHY2lPaUpJVXpJMU5pSXNJbWxoZEN
JNk1UVTVNRGcxTnpNd09Td2laWGh3SWpveE5Ua3dPVFF6TnpBNUxqQjkuZXlKcFpDSTZJbUpqTXpjNU5EaG1MVEpsTmprdE5EWmpPQzA0TlRSaExXVTJOVFl3TVdZNVkyUXhZaUo5Ljk3WDJza0FyeF9fNVdOc2lmblNzcjlZRmNDOHgwRDdYckpoR19kMWxRMDgsTWpBeU1DMHdOUzB6TUZReE5qbzBPRG8wT0M0eU5qTTNOeklyTURBNk1EQT06TUdVQ01CL3V5OGFTSkM1bkc2UHZrcEhnWHY2TkZRKzNHcUdSQjFDWmtQS3pJ
MU1sS1dYcldYT2s1Ykh2eDJLTmlhUW8rd0l4QUxmRStrQStYSVNDOGpPd2JORnlMdkcwWmt5OFN4YnA3RUZUTCtSb0tUQXFxd25UL1I5Q3JKYUc5dWZaK1dZMm9nPT0=')]
TRACE: send_request method=b'PUT' url=(b'https', b'qa-debian8.example.com', 443, b'/v1.0/blockchain_record/') headers=[(b'host', b'qa-debian8.example.com'), (b'user-agent', b'python-httpx/0.13.3'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate'), (
b'connection', b'keep-alive'), (b'x-software-type', b'Embedded Gateway'), (b'content-length', b'5535'), (b'content-type', b'application/json'), (b'x-request-id', b'fd1fb01b-af2b-4e05-86cd-b12b8a14307d'), (b'authorization', b'Basic ZXlKaGJHY2lPaUpJVXpJMU5pSXNJbWxoZENJNk1UVTVNRGcxTnpNd09Td2laWGh3SWpveE5Ua3dPVF
F6TnpBNUxqQjkuZXlKcFpDSTZJbUpqTXpjNU5EaG1MVEpsTmprdE5EWmpPQzA0TlRSaExXVTJOVFl3TVdZNVkyUXhZaUo5Ljk3WDJza0FyeF9fNVdOc2lmblNzcjlZRmNDOHgwRDdYckpoR19kMWxRMDgsTWpBeU1DMHdOUzB6TUZReE5qbzBPRG8wT0M0eU5qTTNOeklyTURBNk1EQT06TUdVQ01CL3V5OGFTSkM1bkc2UHZrcEhnWHY2TkZRKzNHcUdSQjFDWmtQS3pJMU1sS1dYcldYT2s1Ykh2eDJLTmlhUW8rd0l4QUxmRSt
rQStYSVNDOGpPd2JORnlMdkcwWmt5OFN4YnA3RUZUTCtSb0tUQXFxd25UL1I5Q3JKYUc5dWZaK1dZMm9nPT0=')]
TRACE [2020-05-30 10:48:48] httpcore._async.http11 - send_data=Data(<5535 bytes>)
TRACE: send_data=Data(<5535 bytes>)
DEBUG [2020-05-30 10:48:48] httpx._client - HTTP Request: PUT https://qa-debian8.example.com/v1.0/blockchain_record/ "HTTP/1.1 200 OK"
DEBUG: HTTP Request: PUT https://qa-debian8.example.com/v1.0/blockchain_record/ "HTTP/1.1 200 OK"
TRACE [2020-05-30 10:48:48] httpcore._async.http11 - receive_event=Data(<4096 bytes>)
TRACE: receive_event=Data(<4096 bytes>)
TRACE [2020-05-30 10:48:48] httpcore._async.http11 - receive_event=Data(<4096 bytes>)
TRACE: receive_event=Data(<4096 bytes>)
TRACE [2020-05-30 10:48:48] httpcore._async.http11 - receive_event=Data(<2744 bytes>)
TRACE: receive_event=Data(<2744 bytes>)
TRACE [2020-05-30 10:48:48] httpcore._async.http11 - receive_event=EndOfMessage(headers=[])
TRACE: receive_event=EndOfMessage(headers=[])
TRACE [2020-05-30 10:48:48] httpcore._async.http11 - response_closed our_state=DONE their_state=DONE
TRACE: response_closed our_state=DONE their_state=DONE
INFO: Update of BCI record was successful, preparing to sign the transaction
INFO: POST: https://qa-debian8.example.com/v1.0/blockchain/
TRACE [2020-05-30 10:48:48] httpcore._async.connection_pool - get_connection_from_pool=(b'https', b'qa-debian8.example.com', 443)
TRACE: get_connection_from_pool=(b'https', b'qa-debian8.example.com', 443)
TRACE [2020-05-30 10:48:48] httpcore._async.connection_pool - created connection=<httpcore._async.connection.AsyncHTTPConnection object at 0x70e57550>
TRACE: created connection=<httpcore._async.connection.AsyncHTTPConnection object at 0x70e57550>
TRACE [2020-05-30 10:48:48] httpcore._async.connection - open_socket origin=(b'https', b'qa-debian8.example.com', 443) timeout={'connect': 5.0, 'read': 5.0, 'write': 5.0, 'pool': 5.0}
TRACE: open_socket origin=(b'https', b'qa-debian8.example.com', 443) timeout={'connect': 5.0, 'read': 5.0, 'write': 5.0, 'pool': 5.0}
TRACE [2020-05-30 10:48:48] httpcore._async.connection - create_connection socket=<httpcore._backends.asyncio.SocketStream object at 0x70e8ad90> http_version='HTTP/1.1'
TRACE: create_connection socket=<httpcore._backends.asyncio.SocketStream object at 0x70e8ad90> http_version='HTTP/1.1'
TRACE [2020-05-30 10:48:48] httpcore._async.connection - connection.request method=b'POST' url=(b'https', b'qa-debian8.example.com', 443, b'/v1.0/blockchain/') headers=[(b'host', b'qa-debian8.example.com'), (b'user-agent', b'python-httpx/0.13.3'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate'), (b'connection', b'keep-alive'), (b'x-software-type', b'Embedded Gateway'), (b'content-length', b'10996'), (b'content-type', b'application/json')]
TRACE: connection.request method=b'POST' url=(b'https', b'qa-debian8.example.com', 443, b'/v1.0/blockchain/') headers=[(b'host', b'qa-debian8.example.com'), (b'user-agent', b'python-httpx/0.13.3'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate'), (b'connection', b'keep-alive'), (b'x-software-type', b'Embedded Gateway'), (b'content-length', b'10996'), (b'content-type', b'application/json')]
TRACE [2020-05-30 10:48:48] httpcore._async.http11 - send_request method=b'POST' url=(b'https', b'qa-debian8.example.com', 443, b'/v1.0/blockchain/') headers=[(b'host', b'qa-debian8.example.com'), (b'user-agent', b'python-httpx/0.13.3'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate'), (b'connection', b'keep-alive'), (b'x-software-type', b'Embedded Gateway'), (b'content-length', b'10996'), (b'content-type', b'application/json')]
TRACE: send_request method=b'POST' url=(b'https', b'qa-debian8.example.com', 443, b'/v1.0/blockchain/') headers=[(b'host', b'qa-debian8.example.com'), (b'user-agent', b'python-httpx/0.13.3'), (b'accept', b'*/*'), (b'accept-encoding', b'gzip, deflate'), (b'connection', b'keep-alive'), (b'x-software-type', b'Embedded Gateway'), (b'content-length', b'10996'), (b'content-type', b'application/json')]
TRACE [2020-05-30 10:48:48] httpcore._async.http11 - send_data=Data(<10996 bytes>)
TRACE: send_data=Data(<10996 bytes>)
DEBUG [2020-05-30 10:48:49] httpx._client - HTTP Request: POST https://qa-debian8.example.com/v1.0/blockchain/ "HTTP/1.1 200 OK"
DEBUG: HTTP Request: POST https://qa-debian8.example.com/v1.0/blockchain/ "HTTP/1.1 200 OK"
TRACE [2020-05-30 10:48:49] httpcore._async.http11 - receive_event=Data(<3 bytes>)
TRACE: receive_event=Data(<3 bytes>)
TRACE [2020-05-30 10:48:49] httpcore._async.http11 - receive_event=EndOfMessage(headers=[])
TRACE: receive_event=EndOfMessage(headers=[])
TRACE [2020-05-30 10:48:49] httpcore._async.http11 - response_closed our_state=DONE their_state=DONE
TRACE: response_closed our_state=DONE their_state=DONE
INFO: handle_new_record: update complete, all done.
INFO: SSE: Record handled.
INFO: SSE: Resetting data.
TRACE [2020-05-30 10:49:18] httpcore._async.http11 - response_closed our_state=DONE their_state=SEND_BODY
TRACE: response_closed our_state=DONE their_state=SEND_BODY
ERROR: Other SSE failure.
Traceback (most recent call last):
 File "/usr/local/packages/python3_7_acap/python3.7/lib/python3.7/site-packages/pygw/core/client.py", line 175, in sse
 async for chunk in response.aiter_raw():
 File "/usr/local/packages/python3_7_acap/python3.7/lib/python3.7/site-packages/httpx/_models.py", line 1009, in aiter_raw
 async for part in self._raw_stream:
 File "/usr/local/packages/python3_7_acap/python3.7/lib/python3.7/site-packages/httpcore/_async/connection_pool.py", line 49, in __aiter__
 async for chunk in self.stream:
 File "/usr/local/packages/python3_7_acap/python3.7/lib/python3.7/site-packages/httpcore/_async/base.py", line 57, in __aiter__
 async for chunk in self.aiterator:
 File "/usr/local/packages/python3_7_acap/python3.7/lib/python3.7/site-packages/httpcore/_async/http11.py", line 128, in _receive_response_data
 event = await self._receive_event(timeout)
 File "/usr/local/packages/python3_7_acap/python3.7/lib/python3.7/site-packages/httpcore/_async/http11.py", line 145, in _receive_event
 data = await self.socket.read(self.READ_NUM_BYTES, timeout)
 File "/usr/local/packages/python3_7_acap/python3.7/lib/python3.7/site-packages/httpcore/_backends/asyncio.py", line 135, in read
 self.stream_reader.read(n), timeout.get("read")
 File "<pyrun>/contextlib.py", line 130, in __exit__
 File "/usr/local/packages/python3_7_acap/python3.7/lib/python3.7/site-packages/httpcore/_exceptions.py", line 12, in map_exceptions
 raise to_exc(exc) from None
httpcore._exceptions.ReadTimeout: SSL shutdown timed out

[Kludex]

Originally posted by @yeraydiazdiaz on 2020-06-02T11:09:04Z

Hey, thanks for the trace logs.

So just before the end there's this very odd line:

TRACE: response_closed our_state=DONE their_state=SEND_BODY

Which suggests a connection is closed on the client side before sending the body.

In above lines we can see data being sent and received, although it's hard for me to see if there's anything missing from just the size of the payloads. In any case seems the PUT and POST connections both complete with lines like:

response_closed our_state=DONE their_state=DONE

So I'm not really sure which connection it is that's being closed while waiting for the request body.

I've tried reproducing it by several requests with binary payloads ~simultaneously to a local HTTPS server but HTTPX behaved as expected for me.

My only suggestion is to wait for encode/httpcore#101 and encode/httpcore#102 to be merged which add more logging to the connection pool, run it again and check the more detailed output.

[Kludex]

Originally posted by @ScottSturdivant on 2020-06-02T22:07:44Z

Hi @yeraydiazdiaz:

For what it's worth, I've switched to instantiating separate clients for the SSE listener and for the handler and since having done that, have not seen this error.

So my code now looks more like this:

import asyncio
import httpx


async def sse():
 async with httpx.AsyncClient() as client:
 async with client.stream('GET', 'https://server.blargh.home:5000/stream', timeout=None) as response:
 async for chunk in response.aiter_raw():
 yield chunk


async def subscribe():
 async with httpx.AsyncClient() as client:
 async for event in sse():
 await client.put(...)
 await client.post(...)

asyncio.run(subscribe())

The client for subscribe is shared with the rest of the app to hopefully take advantage of connection pooling, etc. Just now the sse function gets its own and the code runs without complaint.

I'll keep an eye out on those two issues, but in the meantime closing this one. Thank you again!