Skip to content
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.

Sign up for GitHub

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

Jump to bottom

Switch from requests to httpx #10

Open
nmlorg opened this issue Aug 23, 2024 · 4 comments
Open

Switch from requests to httpx #10

nmlorg opened this issue Aug 23, 2024 · 4 comments
Assignees
@nmlorg
Labels
enhancement New feature or request

Comments

@nmlorg
Copy link
Owner

nmlorg commented Aug 23, 2024

Splitting this out from #9.

I haven't done a lot of testing, but 0045680 seems to have intermittently but significantly reduced response time, presumably by eliminating both the TCP handshake (to the Netherlands) and TLS negotiation for some requests.

Right now, each thread gets its own requests.Session, so each bot's long-poll Session stays active pretty much constantly but the main thread's Session (and any connections it maintains) can go idle potentially for hours at a time (and hence time out and need to be reestablished before a response can be delivered).

encode/httpx#1633 (comment)

Yes. HTTPX is intended to be thread-safe, and yes, a single client-instance across all threads will do better in terms of connection pooling, than using an instance-per-thread.

However, changing requests.py to:

_SESSION = httpx.Client(http2=True)
⋮
def post(*args, **kwargs):
    return _SESSION.post(*args, **kwargs)

consistently gives:

2024-08-23 14:59:28,013 INFO Thread-1 (_poll_bot) _client.py:1026] HTTP Request: POST https://api.telegram.org/bot44…/getupdates "HTTP/2 200 OK"
2024-08-23 15:00:01,741 INFO MainThread reminders.py:42] Running periodic.
2024-08-23 15:00:08,887 INFO MainThread reminders.py:192] Editing reminder -40…/8197.
2024-08-23 15:00:18,220 INFO Thread-1 (_poll_bot) _client.py:1026] HTTP Request: POST https://api.telegram.org/bot44…/getupdates "HTTP/2 200 OK"
2024-08-23 15:00:18,221 INFO MainThread _client.py:1026] HTTP Request: POST https://api.telegram.org/bot44…/editmessagecaption "HTTP/2 200 OK"

which suggests that requests to the same host are serialized (the editMessageCaption didn't complete until 1 ms after a previous getUpdates completed). A quick test seems to confirm this is an actual effect, not just a discrepancy in the logging:

>>> import ntelebot
>>> import threading
>>> import time
>>> bot = ntelebot.bot.Bot('18…')
>>> print(time.time(), bot.getme(), time.time())
1724451017.3645363 {'id': 18…, 'is_bot': True, 'first_name': 'ntelebot', 'username': 'ntelebot', 'can_join_groups': False, 'can_read_all_group_messages': False, 'supports_inline_queries': False, 'can_connect_to_business': False, 'has_main_web_app': False} 1724451017.9219635
>>> t = threading.Thread(target=lambda: print(time.time(), bot.getupdates(timeout=20), time.time())); t.daemon = True; t.start()
>>> print(time.time(), bot.getme(), time.time())
1724451058.9599593 [] 1724451079.5572999
1724451061.5596561 {'id': 18…, 'is_bot': True, 'first_name': 'ntelebot', 'username': 'ntelebot', 'can_join_groups': False, 'can_read_all_group_messages': False, 'supports_inline_queries': False, 'can_connect_to_business': False, 'has_main_web_app': False} 1724451079.5575902

The exact timing (getUpdates returning at 1724451079.5572999 and getMe returning at 1724451079.5575902, 290 µs — not ms — later) suggests the requests did actually go out as requested, but something caused the responses to stack up. I haven't dug deeply enough to figure out if this is actually happening in the HTTP/2 stream or if this is happening somewhere inside httpx.

Even more worryingly:

>>> t = threading.Thread(target=lambda: print(bot.getupdates())); t.daemon = True; t.start(); print(bot.getme())
Exception in thread Thread-1 (<lambda>):
Traceback (most recent call last):
  File "lib/python3.10/site-packages/httpx/_transports/default.py", line 69, in map_httpcore_exceptions
    yield
  File "lib/python3.10/site-packages/httpx/_transports/default.py", line 233, in handle_request
    resp = self._pool.handle_request(req)
  File "lib/python3.10/site-packages/httpcore/_sync/connection_pool.py", line 216, in handle_request
    raise exc from None
  File "lib/python3.10/site-packages/httpcore/_sync/connection_pool.py", line 196, in handle_request
    response = connection.handle_request(
  File "lib/python3.10/site-packages/httpcore/_sync/connection.py", line 101, in handle_request
    return self._connection.handle_request(request)
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 185, in handle_request
    raise exc
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 148, in handle_request
    status, headers = self._receive_response(
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 292, in _receive_response
    event = self._receive_stream_event(request, stream_id)
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 333, in _receive_stream_event
    self._receive_events(request, stream_id)
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 361, in _receive_events
    events = self._read_incoming_data(request)
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 452, in _read_incoming_data
    raise exc
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 440, in _read_incoming_data
    raise RemoteProtocolError("Server disconnected")
httpcore.RemoteProtocolError: Server disconnected

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/usr/lib/python3.10/threading.py", line 1016, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.10/threading.py", line 953, in run
    self._target(*self._args, **self._kwargs)
  File "<stdin>", line 1, in <lambda>
Traceback (most recent call last):
  File "lib/python3.10/site-packages/httpx/_transports/default.py", line 69, in map_httpcore_exceptions
    yield
  File "lib/python3.10/site-packages/httpx/_transports/default.py", line 233, in handle_request
    resp = self._pool.handle_request(req)
  File "lib/python3.10/site-packages/httpcore/_sync/connection_pool.py", line 216, in handle_request
    raise exc from None
  File "lib/python3.10/site-packages/httpcore/_sync/connection_pool.py", line 196, in handle_request
    response = connection.handle_request(
  File "lib/python3.10/site-packages/httpcore/_sync/connection.py", line 101, in handle_request
    return self._connection.handle_request(request)
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 185, in handle_request
    raise exc
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 148, in handle_request
    status, headers = self._receive_response(
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 292, in _receive_response
    event = self._receive_stream_event(request, stream_id)
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 333, in _receive_stream_event
    self._receive_events(request, stream_id)
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 361, in _receive_events
    events = self._read_incoming_data(request)
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 435, in _read_incoming_data
    raise self._read_exception  # pragma: nocover
  File "lib/python3.10/site-packages/httpx/_transports/default.py", line 69, in map_httpcore_exceptions
    yield
  File "lib/python3.10/site-packages/httpx/_transports/default.py", line 233, in handle_request
    resp = self._pool.handle_request(req)
  File "lib/python3.10/site-packages/httpcore/_sync/connection_pool.py", line 216, in handle_request
    raise exc from None
  File "lib/python3.10/site-packages/httpcore/_sync/connection_pool.py", line 196, in handle_request
    response = connection.handle_request(
  File "lib/python3.10/site-packages/httpcore/_sync/connection.py", line 101, in handle_request
    return self._connection.handle_request(request)
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 185, in handle_request
    raise exc
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 148, in handle_request
    status, headers = self._receive_response(
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 292, in _receive_response
    event = self._receive_stream_event(request, stream_id)
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 333, in _receive_stream_event
    self._receive_events(request, stream_id)
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 361, in _receive_events
    events = self._read_incoming_data(request)
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 452, in _read_incoming_data
    raise exc
  File "lib/python3.10/site-packages/httpcore/_sync/http2.py", line 440, in _read_incoming_data
    raise RemoteProtocolError("Server disconnected")
httpcore.RemoteProtocolError: Server disconnected

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "ntelebot/ntelebot/bot.py", line 57, in __call__
    data = ntelebot.requests.post(self.url, timeout=self.timeout, **_prepare(params)).json()
  File "ntelebot/ntelebot/requests.py", line 29, in post
    return _SESSION.post(*args, **kwargs)
  File "lib/python3.10/site-packages/httpx/_client.py", line 1145, in post
    return self.request(
  File "lib/python3.10/site-packages/httpx/_client.py", line 827, in request
    return self.send(request, auth=auth, follow_redirects=follow_redirects)
  File "lib/python3.10/site-packages/httpx/_client.py", line 914, in send
    response = self._send_handling_auth(
  File "lib/python3.10/site-packages/httpx/_client.py", line 942, in _send_handling_auth
    response = self._send_handling_redirects(
  File "lib/python3.10/site-packages/httpx/_client.py", line 979, in _send_handling_redirects
    response = self._send_single_request(request)
  File "lib/python3.10/site-packages/httpx/_client.py", line 1015, in _send_single_request
    response = transport.handle_request(request)
  File "lib/python3.10/site-packages/httpx/_transports/default.py", line 232, in handle_request
    with map_httpcore_exceptions():
  File "/usr/lib/python3.10/contextlib.py", line 153, in __exit__
    self.gen.throw(typ, value, traceback)
  File "lib/python3.10/site-packages/httpx/_transports/default.py", line 86, in map_httpcore_exceptions
    raise mapped_exc(message) from exc
httpx.RemoteProtocolError: Server disconnected
  File "ntelebot/ntelebot/bot.py", line 57, in __call__
    data = ntelebot.requests.post(self.url, timeout=self.timeout, **_prepare(params)).json()
>>>   File "ntelebot/ntelebot/requests.py", line 29, in post
    return _SESSION.post(*args, **kwargs)
  File "lib/python3.10/site-packages/httpx/_client.py", line 1145, in post
    return self.request(
  File "lib/python3.10/site-packages/httpx/_client.py", line 827, in request
    return self.send(request, auth=auth, follow_redirects=follow_redirects)
  File "lib/python3.10/site-packages/httpx/_client.py", line 914, in send
    response = self._send_handling_auth(
  File "lib/python3.10/site-packages/httpx/_client.py", line 942, in _send_handling_auth
    response = self._send_handling_redirects(
  File "lib/python3.10/site-packages/httpx/_client.py", line 979, in _send_handling_redirects
    response = self._send_single_request(request)
  File "lib/python3.10/site-packages/httpx/_client.py", line 1015, in _send_single_request
    response = transport.handle_request(request)
  File "lib/python3.10/site-packages/httpx/_transports/default.py", line 232, in handle_request
    with map_httpcore_exceptions():
  File "/usr/lib/python3.10/contextlib.py", line 153, in __exit__
    self.gen.throw(typ, value, traceback)
  File "lib/python3.10/site-packages/httpx/_transports/default.py", line 86, in map_httpcore_exceptions
    raise mapped_exc(message) from exc
httpx.RemoteProtocolError: Server disconnected

but I have not been able to reliably reproduce this, so I don't know if this is something like a really tight race in httpx or if TBA just decided to dump a connection at the perfect wrong time. Either way, though, I think this is showing that both requests were canceled, i.e. if TBA dumped the connection during getUpdates it caused the subsequent getMe to fail too, rather than trigger a reconnect 🙁.
@nmlorg nmlorg added the enhancement New feature or request label Aug 23, 2024
@nmlorg nmlorg self-assigned this Aug 23, 2024
@nmlorg
Copy link
Owner Author

nmlorg commented Aug 24, 2024 

import logging
import threading
import time

import httpx


logging.basicConfig(format='%(asctime)s %(threadName)s %(filename)s:%(lineno)s] %(message)s',
                    level=logging.DEBUG)

client = httpx.Client(http2=True, timeout=15)

t = threading.Thread(target=lambda: logging.info('%s', client.get('https://httpbin.org/delay/10')))
t.start()

time.sleep(5)
logging.info('%s', client.get('https://httpbin.org/get'))
2024-08-23 19:06:14,216 MainThread _config.py:80] load_ssl_context verify=True cert=None trust_env=True http2=False
2024-08-23 19:06:14,217 MainThread _config.py:146] load_verify_locations cafile='lib/python3.10/site-packages/certifi/cacert.pem'
2024-08-23 19:06:14,237 Thread-1 (<lambda>) _trace.py:45] connect_tcp.started host='httpbin.org' port=443 local_address=None timeout=15 socket_options=None
2024-08-23 19:06:14,472 Thread-1 (<lambda>) _trace.py:45] connect_tcp.complete return_value=<httpcore._backends.sync.SyncStream object at 0x7caab1f3a950>
2024-08-23 19:06:14,472 Thread-1 (<lambda>) _trace.py:45] start_tls.started ssl_context=<ssl.SSLContext object at 0x7caab30df140> server_hostname='httpbin.org' timeout=15
2024-08-23 19:06:14,769 Thread-1 (<lambda>) _trace.py:45] start_tls.complete return_value=<httpcore._backends.sync.SyncStream object at 0x7caab1f3a920>
2024-08-23 19:06:14,770 Thread-1 (<lambda>) _trace.py:45] send_connection_init.started request=<Request [b'GET']>
2024-08-23 19:06:14,770 Thread-1 (<lambda>) _trace.py:45] send_connection_init.complete
2024-08-23 19:06:14,770 Thread-1 (<lambda>) _trace.py:45] send_request_headers.started request=<Request [b'GET']> stream_id=1
2024-08-23 19:06:14,770 Thread-1 (<lambda>) hpack.py:267] Adding (b':method', b'GET') to the header table, sensitive:False, huffman:True
2024-08-23 19:06:14,770 Thread-1 (<lambda>) hpack.py:61] Encoding 2 with 7 bits
2024-08-23 19:06:14,770 Thread-1 (<lambda>) hpack.py:267] Adding (b':authority', b'httpbin.org') to the header table, sensitive:False, huffman:True
2024-08-23 19:06:14,770 Thread-1 (<lambda>) hpack.py:61] Encoding 1 with 6 bits
2024-08-23 19:06:14,770 Thread-1 (<lambda>) hpack.py:61] Encoding 8 with 7 bits
2024-08-23 19:06:14,770 Thread-1 (<lambda>) hpack.py:267] Adding (b':scheme', b'https') to the header table, sensitive:False, huffman:True
2024-08-23 19:06:14,770 Thread-1 (<lambda>) hpack.py:61] Encoding 7 with 7 bits
2024-08-23 19:06:14,771 Thread-1 (<lambda>) hpack.py:267] Adding (b':path', b'/delay/10') to the header table, sensitive:False, huffman:True
2024-08-23 19:06:14,771 Thread-1 (<lambda>) hpack.py:61] Encoding 4 with 6 bits
2024-08-23 19:06:14,771 Thread-1 (<lambda>) hpack.py:61] Encoding 7 with 7 bits
2024-08-23 19:06:14,771 Thread-1 (<lambda>) hpack.py:267] Adding (b'accept', b'*/*') to the header table, sensitive:False, huffman:True
2024-08-23 19:06:14,771 Thread-1 (<lambda>) hpack.py:61] Encoding 19 with 6 bits
2024-08-23 19:06:14,771 Thread-1 (<lambda>) hpack.py:61] Encoding 3 with 7 bits
2024-08-23 19:06:14,771 Thread-1 (<lambda>) hpack.py:267] Adding (b'accept-encoding', b'gzip, deflate, br') to the header table, sensitive:False, huffman:True
2024-08-23 19:06:14,771 Thread-1 (<lambda>) hpack.py:61] Encoding 16 with 6 bits
2024-08-23 19:06:14,771 Thread-1 (<lambda>) hpack.py:61] Encoding 13 with 7 bits
2024-08-23 19:06:14,771 Thread-1 (<lambda>) hpack.py:267] Adding (b'user-agent', b'python-httpx/0.27.0') to the header table, sensitive:False, huffman:True
2024-08-23 19:06:14,771 Thread-1 (<lambda>) hpack.py:61] Encoding 58 with 6 bits
2024-08-23 19:06:14,771 Thread-1 (<lambda>) hpack.py:61] Encoding 14 with 7 bits
2024-08-23 19:06:14,771 Thread-1 (<lambda>) hpack.py:259] Encoded header block to b"\x82A\x88\x9d)\xae3T\xb9\xec\x9b\x87D\x87bB\xd0?L\x04\x1fS\x83\xf9c\xe7P\x8d\x9b\xd9\xab\xfaRB\xcb@\xd2_\xa5#\xb3z\x8e\xaf\xd2g=KN\x94\xd7\xe5\x80.'W\x07"
2024-08-23 19:06:14,771 Thread-1 (<lambda>) _trace.py:45] send_request_headers.complete
2024-08-23 19:06:14,771 Thread-1 (<lambda>) _trace.py:45] send_request_body.started request=<Request [b'GET']> stream_id=1
2024-08-23 19:06:14,771 Thread-1 (<lambda>) _trace.py:45] send_request_body.complete
2024-08-23 19:06:14,771 Thread-1 (<lambda>) _trace.py:45] receive_response_headers.started request=<Request [b'GET']> stream_id=1
2024-08-23 19:06:14,771 Thread-1 (<lambda>) _trace.py:45] receive_remote_settings.started
2024-08-23 19:06:14,771 Thread-1 (<lambda>) _trace.py:45] receive_remote_settings.complete return_value=<RemoteSettingsChanged changed_settings:{ChangedSetting(setting=SettingCodes.MAX_CONCURRENT_STREAMS, original_value=None, new_value=128), ChangedSetting(setting=SettingCodes.INITIAL_WINDOW_SIZE, original_value=65535, new_value=65536), ChangedSetting(setting=SettingCodes.MAX_FRAME_SIZE, original_value=16384, new_value=16777215)}>



2024-08-23 19:06:19,244 MainThread _trace.py:45] send_request_headers.started request=<Request [b'GET']> stream_id=3
2024-08-23 19:06:19,244 MainThread hpack.py:267] Adding (b':method', b'GET') to the header table, sensitive:False, huffman:True
2024-08-23 19:06:19,244 MainThread hpack.py:61] Encoding 2 with 7 bits
2024-08-23 19:06:19,244 MainThread hpack.py:267] Adding (b':authority', b'httpbin.org') to the header table, sensitive:False, huffman:True
2024-08-23 19:06:19,244 MainThread hpack.py:61] Encoding 66 with 7 bits
2024-08-23 19:06:19,244 MainThread hpack.py:267] Adding (b':scheme', b'https') to the header table, sensitive:False, huffman:True
2024-08-23 19:06:19,244 MainThread hpack.py:61] Encoding 7 with 7 bits
2024-08-23 19:06:19,244 MainThread hpack.py:267] Adding (b':path', b'/get') to the header table, sensitive:False, huffman:True
2024-08-23 19:06:19,244 MainThread hpack.py:61] Encoding 4 with 6 bits
2024-08-23 19:06:19,244 MainThread hpack.py:61] Encoding 3 with 7 bits
2024-08-23 19:06:19,244 MainThread hpack.py:267] Adding (b'accept', b'*/*') to the header table, sensitive:False, huffman:True
2024-08-23 19:06:19,244 MainThread hpack.py:61] Encoding 65 with 7 bits
2024-08-23 19:06:19,244 MainThread hpack.py:267] Adding (b'accept-encoding', b'gzip, deflate, br') to the header table, sensitive:False, huffman:True
2024-08-23 19:06:19,244 MainThread hpack.py:61] Encoding 64 with 7 bits
2024-08-23 19:06:19,244 MainThread hpack.py:267] Adding (b'user-agent', b'python-httpx/0.27.0') to the header table, sensitive:False, huffman:True
2024-08-23 19:06:19,244 MainThread hpack.py:61] Encoding 63 with 7 bits
2024-08-23 19:06:19,244 MainThread hpack.py:259] Encoded header block to b'\x82\xc2\x87D\x83bb\xa7\xc1\xc0\xbf'
2024-08-23 19:06:19,245 MainThread _trace.py:45] send_request_headers.complete
2024-08-23 19:06:19,245 MainThread _trace.py:45] send_request_body.started request=<Request [b'GET']> stream_id=3
2024-08-23 19:06:19,245 MainThread _trace.py:45] send_request_body.complete
2024-08-23 19:06:19,245 MainThread _trace.py:45] receive_response_headers.started request=<Request [b'GET']> stream_id=3
2024-08-23 19:06:19,435 Thread-1 (<lambda>) hpack.py:452] Decoding b' \x88a\x96\xdc4\xfd(&\x94\x86\xd9\x94\x10\x04\xd2\x80\x15\xc09p/\xa9\x8bF\xff_\x8b\x1du\xd0b\r&=LtA\xea\\\x03309\x00\x85Al\xee[?\x8b\x9a\xda\x8cC\xd9S\x01}w\xd7\x07\x00\x93\x19\x08T!b\x1e\xa4\xd8z\x16\x1d\x14\x1f\xc2\xc7\xb0\xd3\x1a\xaf\x01*\x00\x96\x19\x08T!b\x1e\xa4\xd8z\x16\x1d\x14\x1f\xc2\xc4\xb0\xb2\x16\xa4\x98t#\x83M\x96\x97'
2024-08-23 19:06:19,435 Thread-1 (<lambda>) hpack.py:126] Decoded 0, consumed 1 bytes
2024-08-23 19:06:19,435 Thread-1 (<lambda>) table.py:199] Resizing header table to 0 from 4096
2024-08-23 19:06:19,435 Thread-1 (<lambda>) hpack.py:126] Decoded 8, consumed 1 bytes
2024-08-23 19:06:19,435 Thread-1 (<lambda>) hpack.py:551] Decoded (b':status', b'200'), consumed 1
2024-08-23 19:06:19,435 Thread-1 (<lambda>) hpack.py:126] Decoded 33, consumed 1 bytes
2024-08-23 19:06:19,435 Thread-1 (<lambda>) hpack.py:126] Decoded 22, consumed 1 bytes
2024-08-23 19:06:19,436 Thread-1 (<lambda>) hpack.py:626] Decoded (b'date', b'Sat, 24 Aug 2024 02:06:19 GMT'), total consumed 24 bytes, indexed True
2024-08-23 19:06:19,436 Thread-1 (<lambda>) hpack.py:126] Decoded 31, consumed 1 bytes
2024-08-23 19:06:19,436 Thread-1 (<lambda>) hpack.py:126] Decoded 11, consumed 1 bytes
2024-08-23 19:06:19,436 Thread-1 (<lambda>) hpack.py:626] Decoded (b'content-type', b'application/json'), total consumed 13 bytes, indexed True
2024-08-23 19:06:19,436 Thread-1 (<lambda>) hpack.py:126] Decoded 28, consumed 1 bytes
2024-08-23 19:06:19,436 Thread-1 (<lambda>) hpack.py:126] Decoded 3, consumed 1 bytes
2024-08-23 19:06:19,436 Thread-1 (<lambda>) hpack.py:626] Decoded (b'content-length', <memory at 0x7caab21d3640>), total consumed 5 bytes, indexed True
2024-08-23 19:06:19,436 Thread-1 (<lambda>) hpack.py:126] Decoded 5, consumed 1 bytes
2024-08-23 19:06:19,436 Thread-1 (<lambda>) hpack.py:126] Decoded 11, consumed 1 bytes
2024-08-23 19:06:19,436 Thread-1 (<lambda>) hpack.py:626] Decoded (b'server', b'gunicorn/19.9.0'), total consumed 19 bytes, indexed False
2024-08-23 19:06:19,436 Thread-1 (<lambda>) hpack.py:126] Decoded 19, consumed 1 bytes
2024-08-23 19:06:19,436 Thread-1 (<lambda>) hpack.py:126] Decoded 1, consumed 1 bytes
2024-08-23 19:06:19,436 Thread-1 (<lambda>) hpack.py:626] Decoded (b'access-control-allow-origin', <memory at 0x7caab21d3700>), total consumed 23 bytes, indexed False
2024-08-23 19:06:19,436 Thread-1 (<lambda>) hpack.py:126] Decoded 22, consumed 1 bytes
2024-08-23 19:06:19,436 Thread-1 (<lambda>) hpack.py:126] Decoded 3, consumed 1 bytes
2024-08-23 19:06:19,436 Thread-1 (<lambda>) hpack.py:626] Decoded (b'access-control-allow-credentials', b'true'), total consumed 28 bytes, indexed False



2024-08-23 19:06:24,944 Thread-1 (<lambda>) hpack.py:452] Decoding b'\x88a\x96\xdc4\xfd(&\x94\x86\xd9\x94\x10\x04\xd2\x80\x15\xc09pM)\x8bF\xff_\x8b\x1du\xd0b\r&=LtA\xea\\\x03360\x00\x85Al\xee[?\x8b\x9a\xda\x8cC\xd9S\x01}w\xd7\x07\x00\x93\x19\x08T!b\x1e\xa4\xd8z\x16\x1d\x14\x1f\xc2\xc7\xb0\xd3\x1a\xaf\x01*\x00\x96\x19\x08T!b\x1e\xa4\xd8z\x16\x1d\x14\x1f\xc2\xc4\xb0\xb2\x16\xa4\x98t#\x83M\x96\x97'
2024-08-23 19:06:24,944 Thread-1 (<lambda>) hpack.py:126] Decoded 8, consumed 1 bytes
2024-08-23 19:06:24,944 Thread-1 (<lambda>) hpack.py:551] Decoded (b':status', b'200'), consumed 1
2024-08-23 19:06:24,945 Thread-1 (<lambda>) hpack.py:126] Decoded 33, consumed 1 bytes
2024-08-23 19:06:24,945 Thread-1 (<lambda>) hpack.py:126] Decoded 22, consumed 1 bytes
2024-08-23 19:06:24,945 Thread-1 (<lambda>) hpack.py:626] Decoded (b'date', b'Sat, 24 Aug 2024 02:06:24 GMT'), total consumed 24 bytes, indexed True
2024-08-23 19:06:24,945 Thread-1 (<lambda>) hpack.py:126] Decoded 31, consumed 1 bytes
2024-08-23 19:06:24,945 Thread-1 (<lambda>) hpack.py:126] Decoded 11, consumed 1 bytes
2024-08-23 19:06:24,945 Thread-1 (<lambda>) hpack.py:626] Decoded (b'content-type', b'application/json'), total consumed 13 bytes, indexed True
2024-08-23 19:06:24,945 Thread-1 (<lambda>) hpack.py:126] Decoded 28, consumed 1 bytes
2024-08-23 19:06:24,945 Thread-1 (<lambda>) hpack.py:126] Decoded 3, consumed 1 bytes
2024-08-23 19:06:24,945 Thread-1 (<lambda>) hpack.py:626] Decoded (b'content-length', <memory at 0x7caab21d3280>), total consumed 5 bytes, indexed True
2024-08-23 19:06:24,945 Thread-1 (<lambda>) hpack.py:126] Decoded 5, consumed 1 bytes
2024-08-23 19:06:24,945 Thread-1 (<lambda>) hpack.py:126] Decoded 11, consumed 1 bytes
2024-08-23 19:06:24,945 Thread-1 (<lambda>) hpack.py:626] Decoded (b'server', b'gunicorn/19.9.0'), total consumed 19 bytes, indexed False
2024-08-23 19:06:24,945 Thread-1 (<lambda>) hpack.py:126] Decoded 19, consumed 1 bytes
2024-08-23 19:06:24,945 Thread-1 (<lambda>) hpack.py:126] Decoded 1, consumed 1 bytes
2024-08-23 19:06:24,945 Thread-1 (<lambda>) hpack.py:626] Decoded (b'access-control-allow-origin', <memory at 0x7caab21d37c0>), total consumed 23 bytes, indexed False
2024-08-23 19:06:24,945 Thread-1 (<lambda>) hpack.py:126] Decoded 22, consumed 1 bytes
2024-08-23 19:06:24,945 Thread-1 (<lambda>) hpack.py:126] Decoded 3, consumed 1 bytes
2024-08-23 19:06:24,945 Thread-1 (<lambda>) hpack.py:626] Decoded (b'access-control-allow-credentials', b'true'), total consumed 28 bytes, indexed False
2024-08-23 19:06:24,945 Thread-1 (<lambda>) _trace.py:45] receive_response_headers.complete return_value=(200, [(b'date', b'Sat, 24 Aug 2024 02:06:24 GMT'), (b'content-type', b'application/json'), (b'content-length', b'360'), (b'server', b'gunicorn/19.9.0'), (b'access-control-allow-origin', b'*'), (b'access-control-allow-credentials', b'true')])
2024-08-23 19:06:24,946 Thread-1 (<lambda>) _client.py:1026] HTTP Request: GET https://httpbin.org/delay/10 "HTTP/2 200 OK"
2024-08-23 19:06:24,946 Thread-1 (<lambda>) _trace.py:45] receive_response_body.started request=<Request [b'GET']> stream_id=1
2024-08-23 19:06:24,946 MainThread _trace.py:45] receive_response_headers.complete return_value=(200, [(b'date', b'Sat, 24 Aug 2024 02:06:19 GMT'), (b'content-type', b'application/json'), (b'content-length', b'309'), (b'server', b'gunicorn/19.9.0'), (b'access-control-allow-origin', b'*'), (b'access-control-allow-credentials', b'true')])
2024-08-23 19:06:24,946 MainThread _client.py:1026] HTTP Request: GET https://httpbin.org/get "HTTP/2 200 OK"
2024-08-23 19:06:24,946 MainThread _trace.py:45] receive_response_body.started request=<Request [b'GET']> stream_id=3
2024-08-23 19:06:24,946 MainThread _trace.py:45] receive_response_body.complete
2024-08-23 19:06:24,946 MainThread _trace.py:45] response_closed.started stream_id=3
2024-08-23 19:06:24,946 MainThread _trace.py:45] response_closed.complete
2024-08-23 19:06:24,946 MainThread test.py:17] <Response [200 OK]>
2024-08-23 19:06:24,947 Thread-1 (<lambda>) _trace.py:45] receive_response_body.complete
2024-08-23 19:06:24,947 Thread-1 (<lambda>) _trace.py:45] response_closed.started stream_id=1
2024-08-23 19:06:24,947 Thread-1 (<lambda>) _trace.py:45] response_closed.complete
2024-08-23 19:06:24,947 Thread-1 (<lambda>) test.py:13] <Response [200 OK]>

 
Changing http2=True to http2=False gives:

2024-08-23 19:08:49,765 MainThread _config.py:80] load_ssl_context verify=True cert=None trust_env=True http2=False
2024-08-23 19:08:49,766 MainThread _config.py:146] load_verify_locations cafile='lib/python3.10/site-packages/certifi/cacert.pem'
2024-08-23 19:08:49,787 Thread-1 (<lambda>) _trace.py:45] connect_tcp.started host='httpbin.org' port=443 local_address=None timeout=15 socket_options=None
2024-08-23 19:08:49,959 Thread-1 (<lambda>) _trace.py:45] connect_tcp.complete return_value=<httpcore._backends.sync.SyncStream object at 0x77ee7ae36950>
2024-08-23 19:08:49,959 Thread-1 (<lambda>) _trace.py:45] start_tls.started ssl_context=<ssl.SSLContext object at 0x77ee7c0df140> server_hostname='httpbin.org' timeout=15
2024-08-23 19:08:50,470 Thread-1 (<lambda>) _trace.py:45] start_tls.complete return_value=<httpcore._backends.sync.SyncStream object at 0x77ee7ae36920>
2024-08-23 19:08:50,470 Thread-1 (<lambda>) _trace.py:45] send_request_headers.started request=<Request [b'GET']>
2024-08-23 19:08:50,470 Thread-1 (<lambda>) _trace.py:45] send_request_headers.complete
2024-08-23 19:08:50,470 Thread-1 (<lambda>) _trace.py:45] send_request_body.started request=<Request [b'GET']>
2024-08-23 19:08:50,470 Thread-1 (<lambda>) _trace.py:45] send_request_body.complete
2024-08-23 19:08:50,470 Thread-1 (<lambda>) _trace.py:45] receive_response_headers.started request=<Request [b'GET']>



2024-08-23 19:08:54,793 MainThread _trace.py:45] connect_tcp.started host='httpbin.org' port=443 local_address=None timeout=15 socket_options=None
2024-08-23 19:08:54,981 MainThread _trace.py:45] connect_tcp.complete return_value=<httpcore._backends.sync.SyncStream object at 0x77ee7ae37820>
2024-08-23 19:08:54,981 MainThread _trace.py:45] start_tls.started ssl_context=<ssl.SSLContext object at 0x77ee7c0df140> server_hostname='httpbin.org' timeout=15
2024-08-23 19:08:55,333 MainThread _trace.py:45] start_tls.complete return_value=<httpcore._backends.sync.SyncStream object at 0x77ee7ae377f0>
2024-08-23 19:08:55,333 MainThread _trace.py:45] send_request_headers.started request=<Request [b'GET']>
2024-08-23 19:08:55,334 MainThread _trace.py:45] send_request_headers.complete
2024-08-23 19:08:55,334 MainThread _trace.py:45] send_request_body.started request=<Request [b'GET']>
2024-08-23 19:08:55,334 MainThread _trace.py:45] send_request_body.complete
2024-08-23 19:08:55,334 MainThread _trace.py:45] receive_response_headers.started request=<Request [b'GET']>
2024-08-23 19:08:55,491 MainThread _trace.py:45] receive_response_headers.complete return_value=(b'HTTP/1.1', 200, b'OK', [(b'Date', b'Sat, 24 Aug 2024 02:08:55 GMT'), (b'Content-Type', b'application/json'), (b'Content-Length', b'309'), (b'Connection', b'keep-alive'), (b'Server', b'gunicorn/19.9.0'), (b'Access-Control-Allow-Origin', b'*'), (b'Access-Control-Allow-Credentials', b'true')])
2024-08-23 19:08:55,492 MainThread _client.py:1026] HTTP Request: GET https://httpbin.org/get "HTTP/1.1 200 OK"
2024-08-23 19:08:55,492 MainThread _trace.py:45] receive_response_body.started request=<Request [b'GET']>
2024-08-23 19:08:55,494 MainThread _trace.py:45] receive_response_body.complete
2024-08-23 19:08:55,494 MainThread _trace.py:45] response_closed.started
2024-08-23 19:08:55,494 MainThread _trace.py:45] response_closed.complete
2024-08-23 19:08:55,495 MainThread test.py:17] <Response [200 OK]>



2024-08-23 19:09:01,171 Thread-1 (<lambda>) _trace.py:45] receive_response_headers.complete return_value=(b'HTTP/1.1', 200, b'OK', [(b'Date', b'Sat, 24 Aug 2024 02:09:01 GMT'), (b'Content-Type', b'application/json'), (b'Content-Length', b'360'), (b'Connection', b'keep-alive'), (b'Server', b'gunicorn/19.9.0'), (b'Access-Control-Allow-Origin', b'*'), (b'Access-Control-Allow-Credentials', b'true')])
2024-08-23 19:09:01,171 Thread-1 (<lambda>) _client.py:1026] HTTP Request: GET https://httpbin.org/delay/10 "HTTP/1.1 200 OK"
2024-08-23 19:09:01,171 Thread-1 (<lambda>) _trace.py:45] receive_response_body.started request=<Request [b'GET']>
2024-08-23 19:09:01,176 Thread-1 (<lambda>) _trace.py:45] receive_response_body.complete
2024-08-23 19:09:01,176 Thread-1 (<lambda>) _trace.py:45] response_closed.started
2024-08-23 19:09:01,176 Thread-1 (<lambda>) _trace.py:45] response_closed.complete
2024-08-23 19:09:01,176 Thread-1 (<lambda>) _trace.py:45] close.started
2024-08-23 19:09:01,177 Thread-1 (<lambda>) _trace.py:45] close.complete
2024-08-23 19:09:01,177 Thread-1 (<lambda>) test.py:13] <Response [200 OK]>

@nmlorg
Copy link
Owner Author

nmlorg commented Aug 24, 2024

encode/httpx#3278

@nmlorg
Copy link
Owner Author

nmlorg commented Aug 29, 2024

encode/httpcore#948

@nmlorg
Copy link
Owner Author

nmlorg commented Aug 31, 2024

encode/httpcore#950

@nmlorg nmlorg mentioned this issue Sep 1, 2024
Open
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@nmlorg nmlorg

Labels
enhancement New feature or request
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@nmlorg