Skip to content

Repository navigation

ReadTimeout - SSL shutdown timed out #1008

Closed
Closed
ReadTimeout - SSL shutdown timed out#1008

Description

@ScottSturdivant
ScottSturdivant
opened on May 29, 2020

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!

Activity

  1. yeraydiazdiaz commented on May 30, 2020

    @yeraydiazdiaz
    yeraydiazdiaz
    on May 30, 2020
    Contributor

    Hi @ScottSturdivant,

    about 40% of the time

    Can you clarify what you mean by that?

    In the meantime it'd be useful if you could set and environment variable HTTPX_LOG_LEVEL to TRACE to get some further logging as described in the docs.

    Moving to httpx until we know for a fact that it's an issue in httpcore.

  2. yeraydiazdiaz
    transferred this issue fromencode/httpcoreon May 30, 2020

  3. ScottSturdivant commented on May 30, 2020

    @ScottSturdivant
    ScottSturdivant
    on May 30, 2020
    Author

    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

  4. yeraydiazdiaz commented on Jun 2, 2020

    @yeraydiazdiaz
    yeraydiazdiaz
    on Jun 2, 2020
    Contributor

    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.

  5. ScottSturdivant commented on Jun 2, 2020

    @ScottSturdivant
    ScottSturdivant
    on Jun 2, 2020
    Author

    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!

  6. ScottSturdivant
    closed this as completedon Jun 2, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions